hub 0.166.0 source: the clock-ahead tunnel alarm wg_tunnel_stale/ok (R-1204, operator-only, edge-triggered); D21 + D4 proof evidence

2026-10-22 17:02:37 +02:00
parent 0639cf0772
commit e267c5e2cd
12 changed files with 279 additions and 1 deletions
@@ -0,0 +1,15 @@
+db-dumps/:
+total 52464
+drwxr-xr-x 2 root root     4096 Oct 22 00:30 .
+drwxr-xr-x 5 root root     4096 Oct 22 10:32 ..
+-rw-r--r-- 1 root root 53711763 Oct 22 00:30 immich-postgres.sql
+
+volume-dumps/:
+total 1080892
+drwxr-xr-x 2 root root      4096 Oct 22 00:30 .
+drwxr-xr-x 5 root root      4096 Oct 22 10:32 ..
+-rw-r--r-- 1 root root 823764480 Oct 22 00:30 immich_immich_ml_cache.tar
+-rw-r--r-- 1 root root 283049472 Oct 22 00:30 immich_immich_postgres_data.tar
+1160553832	.
+204665903	/mnt/sizing-bench/appdata/immich
+823835298	/v
@@ -0,0 +1,11 @@
+2026/10/22 14:32:59 backup.go:1014: [INFO] [backup] Stopping immich for safe volume dump
+2026/10/22 14:33:00 volume_exclusion.go:31: [INFO] [backup] Volume immich/immich_immich_ml_cache is excluded by the template (a cache the app rebuilds) — not dumped (R-49)
+2026/10/22 14:33:11 backup.go:911: [INFO] [backup] Volume dump: immich/immich_immich_postgres_data → 269.9 MB
+2026/10/22 14:33:11 data_versions.go:131: [DEBUG] [backup] immich: stamped volume-dumps/immich_immich_postgres_data.tar (283049472 B) with pins [ghcr.io/immich-app/immich-server:v3.2.4@sha256:d317916b28090c33eb36b308464e
+2026/10/22 14:33:11 backup.go:936: [DEBUG] [backup] Removed stale volume dump: immich/immich_immich_ml_cache.tar
+2026/10/22 14:33:11 backup.go:1030: [INFO] [backup] Restarting immich after volume dump
+total 276428
+drwxr-xr-x 2 root root      4096 Oct 22 14:33 .
+drwxr-xr-x 5 root root      4096 Oct 22 14:33 ..
+-rw-r--r-- 1 root root 283049472 Oct 22 14:33 immich_immich_postgres_data.tar
+336788031	.
@@ -0,0 +1,9 @@
+# 9202, 2026-10-22 14:35–14:40 UTC — after the backup without the model cache
+- POST /api/stacks/immich/stop → 200; `docker volume rm immich_immich_ml_cache` (as on a rebuilt box: no cache).
+- The local unit restore (POST /backup/restore stack_name=immich snapshot_id=helyi) is REFUSED by design (R-538): Immich's
+  unit holds no photo files, so the database is not put back over files it does not hold — the route for Immich is the
+  second drive's or the off-site whole restore. 9202 has neither target, so the restore leg itself was NOT run here.
+  What changed is only the cache volume's absence from the unit, so the proof is the state ANY such restore leaves:
+- POST /api/stacks/immich/start → 200; all four containers healthy; the cache volume holds 4096 B (empty).
+- Smart search's call, inside immich-machine-learning: POST localhost:3003/predict {clip.textual ViT-B-32__openai}
+  → HTTP 200, embedding length 512, 9.2 s (the model fetched); again → 200, 512, 0.1 s. The cache now 610 978 474 B.
@@ -0,0 +1,12 @@
+== BEFORE: root password over SSH from the LAN: root
+DooPlex public key added
+content check (sshd -t -f the snippet): rc=0
+sshd -t (whole): ok
+reload ssh: ok
+permitrootlogin without-password
+passwordauthentication yes
+active
+== AFTER: root password over SSH from the LAN: Permission denied, please try again.
+== AFTER: root KEY over SSH from the LAN: root
+== AFTER: the web page's password login (PVE /api2/json/access/ticket): HTTP 200
+console (tty1) login as root with the password AFTER the drop-in: shell, `id` → uid=0(root) — 02-console-login-after.png
@@ -1,3 +1,18 @@
+## v0.166.0 (unreleased — built 2026-10-22 night, NOT deployed; the deploy is the operator's yes) — the clock-ahead tunnel alarm (R-1204)
+
+- **`wg_tunnel_stale` / `wg_tunnel_ok` (operator-only).** A box that ran once with its clock ahead stamps a WireGuard
+  handshake in the future; ep0 then refuses every newer handshake, so its whole-box copies to ep0 and the operator's
+  door stay dead until the real date passes the wrong one — and nothing said why (rehearsal 2026-10-20 B6 #8). The hub
+  now parses the agent's `wireguard` stanza (`hostWireguard`) and, for a registered and active tunnel, alarms when the
+  handshake lies in the FUTURE by the box's clock (`handshake_future_s`, agent ≥ the R-1204 commit — the plain cause:
+  „the clock ran ahead once") or when it is older than 6 h while the box reports (measured: healthy tunnels shake hands
+  every ≤ 2 min — 113–124 s at most over 24 h on three boxes). Edge-triggered from the host's newest tunnel event
+  (`store.LatestHostTunnelEvent`, the host_swap shape): one alarm, one recovery (info — not mailed). An older agent
+  sends no future field and its age is clamped at 0, so the clock case is seen only with the new agent; the 6-hour
+  case works with every agent. The repair (re-key the peer, or ep0 forgets the stored timestamp) is a decision —
+  felhom.eu STATUS. Tests `TestR1204_TheClockAheadTunnelAlarmsOnceAndClears`, `TestR1204_WhatIsJudged`,
+  `TestR1204_TunnelEventsAreOperatorOnly` — red-proved (the handler call removed; the future case ignored).
+
 ## v0.165.0 (2026-10-22) — DEPLOYED on the operator's yes (image sha256:c6180fb79a2ff7d5546a704c68b634b9207afb0a0ecd524c74b0310434532537) — the household's mail list is never overwritten (R-1199 reopened); `host_swap_short` only when swap is really short (R-1216, D28 = A)

 - **R-1199 reopened.** `customer_notifications.household_saved` (new column, `store/household_prefs.go`): set ONLY by a
@@ -772,7 +772,9 @@ type hostReportPayload struct {
 		HostSwapMB  *int64 `json:"host_swap_mb"`
 		GuestSwapMB *int64 `json:"guest_swap_mb"`
 	} `json:"host"`
-	Guests []struct {
+	// Wireguard (R-1204): the box's own view of its tunnel to ep0. nil = an agent with no tunnel stanza.
+	Wireguard *hostWireguard `json:"wireguard"`
+	Guests    []struct {
 		VMID              int    `json:"vmid"`
 		Name              string `json:"name"`
 		Status            string `json:"status"`
@@ -994,6 +996,7 @@ func (h *Handler) handleHostReport(w http.ResponseWriter, r *http.Request) {
 	}
 	h.checkTunnel(hostID, custID, rep.Cloudflared.Status, rep.Cloudflared.Detail)
 	h.checkHostSwap(hostID, custID, rep.Host.HostSwapMB, rep.Host.GuestSwapMB)
+	h.checkWGTunnel(hostID, custID, rep.Wireguard)
 	h.checkCrash(hostID, custID, body)
 	h.checkDeliberateOff(hostID, custID, &rep)

@@ -0,0 +1,97 @@
+package api
+
+import (
+	"encoding/json"
+	"fmt"
+)
+
+// R-1204 (rehearsal 2026-10-20 B6 #8). A box that runs once with its clock AHEAD stamps a WireGuard handshake in the
+// future; ep0 then refuses every newer handshake (WireGuard's replay protection: the TAI64N timestamp must be newer
+// than the last one accepted from that peer), so the box's tunnel to ep0 — its PBS whole-box copies and the
+// operator's door — stays dead until the real date passes the wrong one, while the box itself reports normally.
+// Nothing said why. The hub now tells the OPERATOR once per host, edge-triggered from the host's newest tunnel event
+// (the host_swap shape), and once when it is healthy again. Operator-only (notify.operatorOnlyEvents): the household
+// cannot fix it. The repair (re-key the peer, or ep0 forgets the stored timestamp) is a separate decision.
+const (
+	eventWGTunnelStale = "wg_tunnel_stale"
+	eventWGTunnelOK    = "wg_tunnel_ok"
+	// wgTunnelStaleAfterS: a healthy tunnel shakes hands at least every ~2 minutes (measured 2026-10-22 over 24 h of
+	// reports on three boxes: 113–124 s at most); six hours is far past any reboot or network blip.
+	wgTunnelStaleAfterS = 6 * 3600
+)
+
+// hostWireguard is the agent's `wireguard` stanza (felhom-agent hub.WireguardStatus).
+type hostWireguard struct {
+	Registered        bool   `json:"registered"`
+	Active            bool   `json:"active"`
+	LastHandshakeAgeS *int64 `json:"last_handshake_age_s"`
+	// HandshakeFutureS (agent ≥ the R-1204 commit): > 0 when the latest handshake lies in the future by the box's clock.
+	HandshakeFutureS *int64 `json:"handshake_future_s"`
+}
+
+// wgTunnelStale judges one report: (stale, the cause in plain words). A box without a registered, active tunnel, or
+// one that sent no age, is not judged.
+func wgTunnelStale(w *hostWireguard) (bool, string) {
+	if w == nil || !w.Registered || !w.Active {
+		return false, ""
+	}
+	if w.HandshakeFutureS != nil && *w.HandshakeFutureS > 0 {
+		return true, fmt.Sprintf("its last handshake is stamped %s in the FUTURE by the box's own clock — the clock ran ahead once, and ep0 refuses every newer handshake until that time passes", humanDuration(*w.HandshakeFutureS))
+	}
+	if w.LastHandshakeAgeS != nil && *w.LastHandshakeAgeS > wgTunnelStaleAfterS {
+		return true, fmt.Sprintf("it has not shaken hands for %s while the box reports — the box's clock may have run ahead (then ep0 refuses it), or ep0 dropped the peer", humanDuration(*w.LastHandshakeAgeS))
+	}
+	return false, ""
+}
+
+func humanDuration(s int64) string {
+	switch {
+	case s >= 2*86400:
+		return fmt.Sprintf("%d days", s/86400)
+	case s >= 2*3600:
+		return fmt.Sprintf("%d hours", s/3600)
+	default:
+		return fmt.Sprintf("%d minutes", s/60)
+	}
+}
+
+func (h *Handler) checkWGTunnel(hostID, custID string, w *hostWireguard) {
+	if w == nil || custID == "" || !w.Registered || !w.Active || (w.LastHandshakeAgeS == nil && w.HandshakeFutureS == nil) {
+		return // not judged: no tunnel, or an agent that sent nothing to judge by
+	}
+	stale, cause := wgTunnelStale(w)
+	prev, err := h.store.LatestHostTunnelEvent(custID, hostID)
+	if err != nil {
+		h.logger.Printf("[WARN] host %s tunnel check: reading the last tunnel event failed: %v", hostID, err)
+		return
+	}
+	wasStale := prev != nil && prev.EventType == eventWGTunnelStale
+	var typ, sev, msg string
+	switch {
+	case stale && !wasStale:
+		typ, sev = eventWGTunnelStale, "warning"
+		msg = fmt.Sprintf("Host %s: its WireGuard tunnel to the off-site server (ep0) is down — %s. Its whole-box copies to ep0 "+
+			"and the operator's door do not work until it is repaired (R-1204). The household cannot fix this.", hostID, cause)
+	case !stale && wasStale:
+		typ, sev = eventWGTunnelOK, "info"
+		msg = fmt.Sprintf("Host %s: its WireGuard tunnel to the off-site server (ep0) shakes hands again.", hostID)
+	default:
+		return
+	}
+	h.logger.Printf("[WARN] host %s: %s", hostID, typ)
+	det := map[string]any{"host_id": hostID}
+	if w.LastHandshakeAgeS != nil {
+		det["last_handshake_age_s"] = *w.LastHandshakeAgeS
+	}
+	if w.HandshakeFutureS != nil {
+		det["handshake_future_s"] = *w.HandshakeFutureS
+	}
+	details, _ := json.Marshal(det)
+	if _, eerr := h.store.SaveEvent(custID, typ, sev, msg, string(details), "hub"); eerr != nil {
+		h.logger.Printf("[WARN] %s event save FAILED for %s: %v", typ, hostID, eerr)
+		return // the audit row first: a mail without its event row lies
+	}
+	if h.dispatcher != nil {
+		go h.dispatcher.ProcessEvent(custID, typ, sev, msg, string(details), "hub")
+	}
+}
@@ -0,0 +1,78 @@
+package api
+
+import (
+	"net/http"
+	"strings"
+	"testing"
+	"time"
+
+	"gitea.dooplex.hu/admin/felhom-hub/internal/store"
+)
+
+// R-1204: the box's tunnel to ep0 — a future-stamped handshake (the clock ran ahead) or no handshake for 6 h raises
+// wg_tunnel_stale ONCE (edge-triggered from the host's newest tunnel event), and wg_tunnel_ok once when healthy; a
+// healthy tunnel, an inactive one and an older agent are not judged.
+// RED-PROOF: with checkWGTunnel not called from the host-report handler the first count fails (0 events); with
+// wgTunnelStale ignoring handshake_future_s the clock case fails — seen failing 2026-10-22.
+func tunnelReportBody(hostID, wg string) string {
+	b := validReportBody(hostID)
+	i := strings.LastIndex(b, "}")
+	return b[:i] + `,"wireguard":` + wg + b[i:]
+}
+
+func TestR1204_TheClockAheadTunnelAlarmsOnceAndClears(t *testing.T) {
+	h, st, _ := newTestHandler(t)
+	st.SaveCustomerConfig(&store.CustomerConfig{CustomerID: "c1", APIKey: "ckey", RetrievalPassword: "p"})
+	st.UpsertHost(&store.Host{HostID: "h1", CustomerID: "c1", APIKey: "HKEY"})
+	post := func(wg string) {
+		t.Helper()
+		if rr := do(h, http.MethodPost, "/host-report", "HKEY", tunnelReportBody("h1", wg)); rr.Code != http.StatusOK {
+			t.Fatalf("host-report = %d %s", rr.Code, rr.Body.String())
+		}
+	}
+	count := func(typ string) int {
+		evs, _ := st.GetEventsByType("c1", typ, time.Time{})
+		return len(evs)
+	}
+	post(`{"registered":true,"active":true,"last_handshake_age_s":60}`) // healthy
+	post(`{"registered":true,"active":false}`)                          // service down: not judged here
+	if count(eventWGTunnelStale) != 0 {
+		t.Fatal("a healthy or inactive tunnel must not alarm")
+	}
+	post(`{"registered":true,"active":true,"last_handshake_age_s":0,"handshake_future_s":63072000}`) // ran 2 years ahead
+	post(`{"registered":true,"active":true,"last_handshake_age_s":0,"handshake_future_s":63071100}`)
+	if n := count(eventWGTunnelStale); n != 1 {
+		t.Fatalf("wg_tunnel_stale = %d, want exactly 1 (edge-triggered)", n)
+	}
+	evs, _ := st.GetEventsByType("c1", eventWGTunnelStale, time.Time{})
+	if !strings.Contains(evs[0].Message, "Host h1:") || !strings.Contains(evs[0].Message, "FUTURE") {
+		t.Fatalf("the alarm must name the host and the clock cause: %q", evs[0].Message)
+	}
+	post(`{"registered":true,"active":true,"last_handshake_age_s":45}`)
+	post(`{"registered":true,"active":true,"last_handshake_age_s":50}`)
+	if count(eventWGTunnelOK) != 1 {
+		t.Fatalf("wg_tunnel_ok = %d, want 1", count(eventWGTunnelOK))
+	}
+	post(`{"registered":true,"active":true,"last_handshake_age_s":30000}`) // 8 h 20 min with no handshake
+	if count(eventWGTunnelStale) != 2 {
+		t.Fatal("six hours without a handshake while reporting must alarm again")
+	}
+}
+
+func TestR1204_WhatIsJudged(t *testing.T) {
+	i := func(v int64) *int64 { return &v }
+	for _, c := range []struct {
+		w    *hostWireguard
+		want bool
+	}{
+		{nil, false},
+		{&hostWireguard{Registered: true, Active: true, LastHandshakeAgeS: i(120)}, false},
+		{&hostWireguard{Registered: true, Active: true, LastHandshakeAgeS: i(6*3600 + 1)}, true},
+		{&hostWireguard{Registered: true, Active: true, LastHandshakeAgeS: i(0), HandshakeFutureS: i(3600)}, true},
+		{&hostWireguard{Registered: false, Active: true, LastHandshakeAgeS: i(99999)}, false},
+	} {
+		if got, _ := wgTunnelStale(c.w); got != c.want {
+			t.Errorf("%+v: stale=%t, want %t", c.w, got, c.want)
+		}
+	}
+}
@@ -858,6 +858,10 @@ var operatorOnlyEvents = map[string]bool{
 	// The household cannot add swap to its host; the operator can.
 	"host_swap_short": true,
 	"host_swap_ok":    true,
+	// R-1204: the box's WireGuard tunnel to ep0 has not shaken hands (clock ran ahead, or ep0 dropped the peer) —
+	// the household cannot fix it.
+	"wg_tunnel_stale": true,
+	"wg_tunnel_ok":    true,
 	// R-1203 (2026-10-21): a household asked for a new box link while its old host is still linked — the operator
 	// gets the host name to delete. Registered in the same commit that mints the type.
 	"bind_old_host_linked": true,
@@ -0,0 +1,12 @@
+package notify
+
+import "testing"
+
+// R-1204: the household cannot repair its box's tunnel to ep0 — the alarm and its recovery are the operator's only.
+func TestR1204_TunnelEventsAreOperatorOnly(t *testing.T) {
+	for _, e := range []string{"wg_tunnel_stale", "wg_tunnel_ok"} {
+		if !operatorOnlyEvents[e] {
+			t.Fatalf("%s must be operator-only", e)
+		}
+	}
+}
@@ -2778,6 +2778,28 @@ func (s *Store) LatestHostSwapEvent(customerID, hostID string) (*Event, error) {
 	return &e, nil
 }

+// LatestHostTunnelEvent returns the newest wg_tunnel_stale / wg_tunnel_ok event for hostID, or nil (R-1204) — the
+// LatestHostSwapEvent shape: the host is read from the event's details (host_id).
+func (s *Store) LatestHostTunnelEvent(customerID, hostID string) (*Event, error) {
+	var e Event
+	var createdAt string
+	err := s.db.QueryRow(`
+		SELECT id, customer_id, event_type, severity, message, details_json, source, created_at
+		FROM events
+		WHERE customer_id = ? AND event_type IN ('wg_tunnel_stale', 'wg_tunnel_ok') AND json_extract(details_json, '$.host_id') = ?
+		ORDER BY created_at DESC, id DESC
+		LIMIT 1`, customerID, hostID,
+	).Scan(&e.ID, &e.CustomerID, &e.EventType, &e.Severity, &e.Message, &e.DetailsJSON, &e.Source, &createdAt)
+	if err == sql.ErrNoRows {
+		return nil, nil
+	}
+	if err != nil {
+		return nil, err
+	}
+	e.CreatedAt = parseSQLiteTime(createdAt)
+	return &e, nil
+}
+
 // GetAllRecentEvents returns the most recent events across all customers.
 func (s *Store) GetAllRecentEvents(limit int) ([]Event, error) {
 	rows, err := s.db.Query(`