diff --git a/documentation/audits/night-2026-10-23/P1-straycopy/00-9202-as-found.txt b/documentation/audits/night-2026-10-23/P1-straycopy/00-9202-as-found.txt new file mode 100644 index 00000000..7270b520 --- /dev/null +++ b/documentation/audits/night-2026-10-23/P1-straycopy/00-9202-as-found.txt @@ -0,0 +1,14 @@ +9202 as found 2026-10-22T18:23:57Z +gitea.dooplex.hu/admin/felhom-controller:0.339.0 +felhom-controller gitea.dooplex.hu/admin/felhom-controller:0.339.0 Up 2 hours (healthy) +filebrowser gtstef/filebrowser:1.5.6-stable Up 29 hours (healthy) +immich-machine-learning ghcr.io/immich-app/immich-machine-learning:v3.2.4 Up 4 hours (healthy) +immich-postgres ghcr.io/immich-app/postgres:16-vectorchord0.4.3-pgvectors0.2.0 Up 4 hours (healthy) +immich-redis redis:7-alpine Up 4 hours (healthy) +immich-server ghcr.io/immich-app/immich-server:v3.2.4 Up 4 hours (healthy) +traefik traefik:v3.7.13 Up 40 hours +Filesystem Size Used Avail Use% Mounted on +/dev/nvme0n1 938G 198G 693G 23% /mnt/felhom-drives/scratch_hdd +/dev/loop0 32G 2.1G 28G 7% /mnt +immich +privatebin diff --git a/documentation/audits/night-2026-10-23/P1-straycopy/01-switch-rc5.txt b/documentation/audits/night-2026-10-23/P1-straycopy/01-switch-rc5.txt new file mode 100644 index 00000000..425847ae --- /dev/null +++ b/documentation/audits/night-2026-10-23/P1-straycopy/01-switch-rc5.txt @@ -0,0 +1,5 @@ +== switch 9202 to rc.5 (2026-10-22T18:25:52Z) +switched to gitea.dooplex.hu/admin/felhom-controller:0.340.0-rc.5 at 18:25:55 +healthy after ~10s: Up 7 seconds (healthy) +== start-up lines +2026/10/22 18:25:55 [INFO] [tier2] start-up: no leftover second-drive copy container diff --git a/documentation/audits/night-2026-10-23/P1-straycopy/02-restart-mid-copy.txt b/documentation/audits/night-2026-10-23/P1-straycopy/02-restart-mid-copy.txt new file mode 100644 index 00000000..a9acb211 --- /dev/null +++ b/documentation/audits/night-2026-10-23/P1-straycopy/02-restart-mid-copy.txt @@ -0,0 +1,30 @@ +== media-leg container name expected: felhom-tier2-copy-immich- +== 18:36:49 POST /api/backup/tier2 (background) +== 18:36:50 the media copy runs: +felhom-tier2-copy-immich-9b848efc | Created | immich +== 18:36:54 restore probe during the copy: +restore probe: HTTP 302 -> /backups/apps?flash_error=Éppen fut a második meghajtóra készülő mentési másolat, ezért most nem indítható visszaállítás. Néhány perc múlva próbáld újra. +== 18:36:55 copies just before the restart: +felhom-tier2-copy-immich-948f2280 | Up 4 seconds (health: starting) | immich +== 18:36:56 restart the controller (systemctl restart felhom-controller-bootstrap) +18:36:59 controller: Up 1 second (health: starting) | copies: +18:37:02 controller: Up 4 seconds (health: starting) | copies: +18:37:06 controller: Up 8 seconds (healthy) | copies: +18:37:09 controller: Up 11 seconds (healthy) | copies: +18:37:12 controller: Up 14 seconds (healthy) | copies: +18:37:16 controller: Up 18 seconds (healthy) | copies: +18:37:19 controller: Up 21 seconds (healthy) | copies: +18:37:23 controller: Up 24 seconds (healthy) | copies: +18:37:26 controller: Up 28 seconds (healthy) | copies: +18:37:29 controller: Up 31 seconds (healthy) | copies: +18:37:32 controller: Up 34 seconds (healthy) | copies: +18:37:36 controller: Up 38 seconds (healthy) | copies: +18:37:39 controller: Up 41 seconds (healthy) | copies: +18:37:42 controller: Up 44 seconds (healthy) | copies: +18:37:46 controller: Up 48 seconds (healthy) | copies: +18:37:49 controller: Up 51 seconds (healthy) | copies: +18:37:53 controller: Up 55 seconds (healthy) | copies: +18:37:56 controller: Up 58 seconds (healthy) | copies: +18:37:59 controller: Up About a minute (healthy) | copies: +18:38:03 controller: Up About a minute (healthy) | copies: +18:38:06 controller: Up About a minute (healthy) | copies: diff --git a/documentation/audits/night-2026-10-23/P1-straycopy/02a-VOID-test-files-outside-a-leg.txt b/documentation/audits/night-2026-10-23/P1-straycopy/02a-VOID-test-files-outside-a-leg.txt new file mode 100644 index 00000000..f821744d --- /dev/null +++ b/documentation/audits/night-2026-10-23/P1-straycopy/02a-VOID-test-files-outside-a-leg.txt @@ -0,0 +1,47 @@ +== media-leg container name expected: felhom-tier2-copy-immich-c7776af6 +== 18:28:25 POST /api/backup/tier2 (background) +== 18:32:49 restore probe during the copy: +restore probe: HTTP 302 -> /backups/apps?flash=flash.restore.file_started +== 18:32:50 restart the controller (systemctl restart felhom-controller-bootstrap) +18:32:51 controller: Up 1 second (health: starting) | copies: +18:32:55 controller: Up 4 seconds (health: starting) | copies: +18:32:58 controller: Up 8 seconds (healthy) | copies: +18:33:02 controller: Up 11 seconds (healthy) | copies: +18:33:05 controller: Up 14 seconds (healthy) | copies: +18:33:08 controller: Up 17 seconds (healthy) | copies: +18:33:12 controller: Up 21 seconds (healthy) | copies: +18:33:15 controller: Up 24 seconds (healthy) | copies: +18:33:18 controller: Up 28 seconds (healthy) | copies: +18:33:22 controller: Up 31 seconds (healthy) | copies: +18:33:25 controller: Up 34 seconds (healthy) | copies: +18:33:28 controller: Up 38 seconds (healthy) | copies: +18:33:32 controller: Up 41 seconds (healthy) | copies: +18:33:35 controller: Up 44 seconds (healthy) | copies: +18:33:38 controller: Up 48 seconds (healthy) | copies: +18:33:42 controller: Up 51 seconds (healthy) | copies: +18:33:45 controller: Up 54 seconds (healthy) | copies: +18:33:48 controller: Up 58 seconds (healthy) | copies: +18:33:52 controller: Up About a minute (healthy) | copies: +18:33:55 controller: Up About a minute (healthy) | copies: +18:33:58 controller: Up About a minute (healthy) | copies: +18:34:01 controller: Up About a minute (healthy) | copies: +18:34:05 controller: Up About a minute (healthy) | copies: +18:34:08 controller: Up About a minute (healthy) | copies: +18:34:11 controller: Up About a minute (healthy) | copies: +18:34:15 controller: Up About a minute (healthy) | copies: +18:34:18 controller: Up About a minute (healthy) | copies: +18:34:21 controller: Up About a minute (healthy) | copies: +18:34:25 controller: Up About a minute (healthy) | copies: +18:34:28 controller: Up About a minute (healthy) | copies: +18:34:31 controller: Up About a minute (healthy) | copies: +18:34:35 controller: Up About a minute (healthy) | copies: +18:34:38 controller: Up About a minute (healthy) | copies: +18:34:41 controller: Up About a minute (healthy) | copies: +18:34:45 controller: Up About a minute (healthy) | copies: +18:34:48 controller: Up About a minute (healthy) | copies: +18:34:51 controller: Up 2 minutes (healthy) | copies: +18:34:55 controller: Up 2 minutes (healthy) | copies: +18:34:58 controller: Up 2 minutes (healthy) | copies: +18:35:01 controller: Up 2 minutes (healthy) | copies: +== start-up lines after the restart +2026/10/22 18:32:52 [INFO] [tier2] start-up: no leftover second-drive copy container diff --git a/documentation/audits/night-2026-10-23/P1-straycopy/02b-startup-after-restart.txt b/documentation/audits/night-2026-10-23/P1-straycopy/02b-startup-after-restart.txt new file mode 100644 index 00000000..2844e916 --- /dev/null +++ b/documentation/audits/night-2026-10-23/P1-straycopy/02b-startup-after-restart.txt @@ -0,0 +1 @@ +2026/10/22 18:36:59 [WARN] [tier2] start-up: removed a leftover second-drive copy container felhom-tier2-copy-immich-948f2280 — a copy a previous controller process lost; the copy is redone at the next run diff --git a/documentation/audits/night-2026-10-23/P1-straycopy/02c-old-controller-log-tail.txt b/documentation/audits/night-2026-10-23/P1-straycopy/02c-old-controller-log-tail.txt new file mode 100644 index 00000000..8d55e734 --- /dev/null +++ b/documentation/audits/night-2026-10-23/P1-straycopy/02c-old-controller-log-tail.txt @@ -0,0 +1,175 @@ +perl: warning: Setting locale failed. +perl: warning: Please check that your locale settings: + LANGUAGE = (unset), + LC_ALL = (unset), + LC_CTYPE = "UTF-8", + LC_NUMERIC = (unset), + LC_COLLATE = (unset), + LC_TIME = (unset), + LC_MESSAGES = (unset), + LC_MONETARY = (unset), + LC_ADDRESS = (unset), + LC_IDENTIFICATION = (unset), + LC_MEASUREMENT = (unset), + LC_PAPER = (unset), + LC_TELEPHONE = (unset), + LC_NAME = (unset), + LANG = "en_US.UTF-8" + are supported and installed on your system. +perl: warning: Falling back to a fallback locale ("en_US.UTF-8"). +2026/10/22 18:36:49 auth.go:160: [DEBUG] [web] login attempt: visitor 192.168.0.180 (peer 172.18.0.6:60442, X-Forwarded-For "192.168.0.180", CF-Connecting-IP "") +2026/10/22 18:36:49 auth.go:192: [DEBUG] [web] login successful from 192.168.0.180, creating session +2026/10/22 18:36:49 session_store.go:140: [DEBUG] [web] sessions: saved 41 session(s) to dashboard-sessions.json +2026/10/22 18:36:49 auth.go:316: [DEBUG] [web] session created, expires=2026-10-29T18:36:49Z, active_sessions=41 +2026/10/22 18:36:49 auth.go:212: [INFO] [web] Login from 192.168.0.180 +2026/10/22 18:36:49 auth.go:144: [DEBUG] [web] auth: valid session for GET /backups +2026/10/22 18:36:49 server.go:637: [DEBUG] [web] ServeHTTP: GET /backups from 172.18.0.6:60442 +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetInfo starting (hddPath="/mnt/felhom-drives/scratch_hdd", hasCPUCollector=true) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] readMemInfo: guest cap=25898MB (host total was 30714380KB) → used≈11064MB avail≈14834MB +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] readMemInfo: totalKB=30714380 availKB=17593060 → total=25898MB avail=14834MB used=11064MB (42.7%) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] readDiskUsage: path="/" bsize=4096 total=68.4GB used=11.1GB avail=53.7GB (17.1%) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] readDiskUsage: path="/mnt/felhom-drives/scratch_hdd" bsize=4096 total=937.8GB used=201.5GB avail=688.6GB (22.6%) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] readLoadAvg: raw="0.68 1.20 1.23 5/1556 1210" → 1m=0.68 5m=1.20 15m=1.23 +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] readThermalZones: /sys — found 1 zones +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] readTemperature: found via hwmon at /sys — 53.0°C (hwmon2) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetInfo done in 59ms — mem=11064MB/25898MB (42.7%), rootDisk=11.1GB/68.4GB (17.1%), load=0.68/1.20/1.23, temp=53.0°C (hwmon2), cpu=12.7% +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd" total=937.8 GB used=201.5 GB avail=688.6GB (22.6%) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/nextcloud" total=937.8 GB used=201.5 GB avail=688.6GB (22.6%) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/paperless-ngx" total=937.8 GB used=201.5 GB avail=688.6GB (22.6%) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/romm" total=937.8 GB used=201.5 GB avail=688.6GB (22.6%) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/navidrome" total=937.8 GB used=201.5 GB avail=688.6GB (22.6%) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/audiobookshelf" total=937.8 GB used=201.5 GB avail=688.6GB (22.6%) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/immich" total=937.8 GB used=201.5 GB avail=688.6GB (22.6%) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/calibre-web" total=937.8 GB used=201.5 GB avail=688.6GB (22.6%) +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetDiskUsage: statfs("/mnt/felhom-drives/scratch_hdd/userdata/grimmory") failed: no such file or directory +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetDiskUsage: statfs("/mnt/felhom-drives/scratch_hdd/userdata/metube") failed: no such file or directory +2026/10/22 18:36:49 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/sizing-bench" total=31.2 GB used=18.1 GB avail=11.5GB (61.1%) +2026/10/22 18:36:50 auth.go:144: [DEBUG] [web] auth: valid session for POST /api/backup/tier2 +2026/10/22 18:36:50 router.go:78: [DEBUG] [api] POST /api/backup/tier2 (path=/backup/tier2) +2026/10/22 18:36:50 router.go:1323: [INFO] [api] Manual Tier 2 (off-drive) backup triggered +2026/10/22 18:36:52 info.go:13: [DEBUG] [system] GetInfo starting (hddPath="/mnt/felhom-drives/scratch_hdd", hasCPUCollector=true) +2026/10/22 18:36:52 info.go:13: [DEBUG] [system] readMemInfo: guest cap=25898MB (host total was 30714380KB) → used≈11074MB avail≈14824MB +2026/10/22 18:36:52 info.go:13: [DEBUG] [system] readMemInfo: totalKB=30714380 availKB=17580524 → total=25898MB avail=14824MB used=11074MB (42.8%) +2026/10/22 18:36:52 info.go:13: [DEBUG] [system] readDiskUsage: path="/" bsize=4096 total=68.4GB used=11.1GB avail=53.7GB (17.1%) +2026/10/22 18:36:52 info.go:13: [DEBUG] [system] readDiskUsage: path="/mnt/felhom-drives/scratch_hdd" bsize=4096 total=937.8GB used=201.7GB avail=688.4GB (22.7%) +2026/10/22 18:36:52 info.go:13: [DEBUG] [system] readLoadAvg: raw="0.68 1.20 1.23 5/1579 1327" → 1m=0.68 5m=1.20 15m=1.23 +2026/10/22 18:36:52 info.go:13: [DEBUG] [system] readThermalZones: /sys — found 1 zones +2026/10/22 18:36:52 info.go:13: [DEBUG] [system] readTemperature: found via hwmon at /sys — 52.8°C (hwmon2) +2026/10/22 18:36:52 info.go:13: [DEBUG] [system] GetInfo done in 57ms — mem=11074MB/25898MB (42.8%), rootDisk=11.1GB/68.4GB (17.1%), load=0.68/1.20/1.23, temp=52.8°C (hwmon2), cpu=12.7% +2026/10/22 18:36:52 scheduler.go:85: [DEBUG] [scheduler] job status-refresh: execution starting +2026/10/22 18:36:52 scheduler.go:450: [INFO] [scheduler] Running job: stack-scan +2026/10/22 18:36:52 scheduler.go:85: [DEBUG] [scheduler] job after-unclean-boot: execution starting +2026/10/22 18:36:52 scheduler.go:85: [DEBUG] [scheduler] job health-probes: execution starting +2026/10/22 18:36:52 scheduler.go:85: [DEBUG] [scheduler] job stack-scan: execution starting +2026/10/22 18:36:52 scheduler.go:85: [DEBUG] [scheduler] job deadapp-check: execution starting +2026/10/22 18:36:52 scheduler.go:85: [DEBUG] [scheduler] job docker-socket-watch: execution starting +2026/10/22 18:36:52 scheduler.go:85: [DEBUG] [scheduler] job ring-spill: execution starting +2026/10/22 18:36:52 manager.go:838: [INFO] [stacks] Status refresh: 9 containers across 70 stacks +2026/10/22 18:36:52 healthprobe.go:64: [DEBUG] [stacks] RunHealthProbes: skipping immich — last check 3m50s ago, effective interval 5m0s, healthy=true +2026/10/22 18:36:52 healthprobe.go:64: [DEBUG] [stacks] RunHealthProbes: skipping paperless-ngx — last check 3m50s ago, effective interval 5m0s, healthy=true +2026/10/22 18:36:52 healthprobe.go:110: [DEBUG] [stacks] RunHealthProbes: collected 0 targets (2 skipped not due, 0 skipped no container) +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "actualbudget" deployed=false composePath=/opt/docker/stacks/actualbudget/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "adventurelog" deployed=false composePath=/opt/docker/stacks/adventurelog/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "audiobookshelf" deployed=false composePath=/opt/docker/stacks/audiobookshelf/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "bentopdf" deployed=false composePath=/opt/docker/stacks/bentopdf/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "bookstack" deployed=false composePath=/opt/docker/stacks/bookstack/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "calcom" deployed=false composePath=/opt/docker/stacks/calcom/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "calibre-web" deployed=false composePath=/opt/docker/stacks/calibre-web/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "chaoscrash" deployed=false composePath=/opt/docker/stacks/chaoscrash/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "chaosoom" deployed=false composePath=/opt/docker/stacks/chaosoom/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "chaosoomb" deployed=false composePath=/opt/docker/stacks/chaosoomb/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "claper" deployed=false composePath=/opt/docker/stacks/claper/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "code-server" deployed=false composePath=/opt/docker/stacks/code-server/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "crafty-controller" deployed=false composePath=/opt/docker/stacks/crafty-controller/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "dawarich" deployed=false composePath=/opt/docker/stacks/dawarich/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "docmost" deployed=false composePath=/opt/docker/stacks/docmost/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "emby" deployed=false composePath=/opt/docker/stacks/emby/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "filebrowser" deployed=false composePath=/opt/docker/stacks/filebrowser/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "ghost" deployed=false composePath=/opt/docker/stacks/ghost/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "gitea" deployed=false composePath=/opt/docker/stacks/gitea/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "glance" deployed=false composePath=/opt/docker/stacks/glance/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "gokapi" deployed=false composePath=/opt/docker/stacks/gokapi/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "grafana" deployed=false composePath=/opt/docker/stacks/grafana/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "gramps-web" deployed=false composePath=/opt/docker/stacks/gramps-web/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "grimmory" deployed=false composePath=/opt/docker/stacks/grimmory/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "grocy" deployed=false composePath=/opt/docker/stacks/grocy/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "home-assistant" deployed=false composePath=/opt/docker/stacks/home-assistant/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "homebox" deployed=false composePath=/opt/docker/stacks/homebox/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "homepage" deployed=false composePath=/opt/docker/stacks/homepage/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "immich" deployed=true composePath=/opt/docker/stacks/immich/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "jellyfin" deployed=false composePath=/opt/docker/stacks/jellyfin/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "karakeep" deployed=false composePath=/opt/docker/stacks/karakeep/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "kimai" deployed=false composePath=/opt/docker/stacks/kimai/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "komga" deployed=false composePath=/opt/docker/stacks/komga/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "lubelogger" deployed=false composePath=/opt/docker/stacks/lubelogger/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "mealie" deployed=false composePath=/opt/docker/stacks/mealie/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "metube" deployed=false composePath=/opt/docker/stacks/metube/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "n8n" deployed=false composePath=/opt/docker/stacks/n8n/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "navidrome" deployed=false composePath=/opt/docker/stacks/navidrome/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "nextcloud" deployed=false composePath=/opt/docker/stacks/nextcloud/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "nzbget" deployed=false composePath=/opt/docker/stacks/nzbget/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "onlyoffice" deployed=false composePath=/opt/docker/stacks/onlyoffice/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "opengist" deployed=false composePath=/opt/docker/stacks/opengist/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "outline" deployed=false composePath=/opt/docker/stacks/outline/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "paperless-ngx" deployed=true composePath=/opt/docker/stacks/paperless-ngx/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "papra" deployed=false composePath=/opt/docker/stacks/papra/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "plant-it" deployed=false composePath=/opt/docker/stacks/plant-it/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "plex" deployed=false composePath=/opt/docker/stacks/plex/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "privatebin" deployed=true composePath=/opt/docker/stacks/privatebin/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "prowlarr" deployed=false composePath=/opt/docker/stacks/prowlarr/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "qbittorrent" deployed=false composePath=/opt/docker/stacks/qbittorrent/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "radarr" deployed=false composePath=/opt/docker/stacks/radarr/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "radicale" deployed=false composePath=/opt/docker/stacks/radicale/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "rallly" deployed=false composePath=/opt/docker/stacks/rallly/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "recipe-importer" deployed=false composePath=/opt/docker/stacks/recipe-importer/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "romm" deployed=false composePath=/opt/docker/stacks/romm/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "sabnzbd" deployed=false composePath=/opt/docker/stacks/sabnzbd/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "seerr" deployed=false composePath=/opt/docker/stacks/seerr/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "sonarr" deployed=false composePath=/opt/docker/stacks/sonarr/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "sparkyfitness" deployed=false composePath=/opt/docker/stacks/sparkyfitness/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "tandoor" deployed=false composePath=/opt/docker/stacks/tandoor/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "termix" deployed=false composePath=/opt/docker/stacks/termix/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "traefik" deployed=false composePath=/opt/docker/stacks/traefik/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "transmission" deployed=false composePath=/opt/docker/stacks/transmission/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "uptime-kuma" deployed=false composePath=/opt/docker/stacks/uptime-kuma/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "vaultwarden" deployed=false composePath=/opt/docker/stacks/vaultwarden/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "vikunja" deployed=false composePath=/opt/docker/stacks/vikunja/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "wanderer" deployed=false composePath=/opt/docker/stacks/wanderer/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "wger" deployed=false composePath=/opt/docker/stacks/wger/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "wishlist" deployed=false composePath=/opt/docker/stacks/wishlist/docker-compose.yml +2026/10/22 18:36:52 manager.go:675: [DEBUG] [stacks] ScanStacks: found stack "zipline" deployed=false composePath=/opt/docker/stacks/zipline/docker-compose.yml +2026/10/22 18:36:52 manager.go:1959: [DEBUG] [stacks] getCatalogTemplateSlugs: found 65 template slugs in /opt/docker/felhom-controller/data/catalog-cache/templates +2026/10/22 18:36:52 manager.go:756: [DEBUG] [stacks] ScanStacks: catalog has 65 template slugs for orphan detection +2026/10/22 18:36:52 manager.go:787: [INFO] [stacks] ScanStacks complete: 70 stacks found (3 deployed, 67 available) +2026/10/22 18:36:52 manager.go:838: [INFO] [stacks] Status refresh: 9 containers across 70 stacks +2026/10/22 18:36:52 scheduler.go:467: [INFO] [scheduler] Job stack-scan completed (took 127ms) +2026/10/22 18:36:55 auth.go:160: [DEBUG] [web] login attempt: visitor 192.168.0.180 (peer 172.18.0.6:60442, X-Forwarded-For "192.168.0.180", CF-Connecting-IP "") +2026/10/22 18:36:55 auth.go:192: [DEBUG] [web] login successful from 192.168.0.180, creating session +2026/10/22 18:36:55 session_store.go:140: [DEBUG] [web] sessions: saved 42 session(s) to dashboard-sessions.json +2026/10/22 18:36:55 auth.go:316: [DEBUG] [web] session created, expires=2026-10-29T18:36:55Z, active_sessions=42 +2026/10/22 18:36:55 auth.go:212: [INFO] [web] Login from 192.168.0.180 +2026/10/22 18:36:55 auth.go:144: [DEBUG] [web] auth: valid session for GET /backups +2026/10/22 18:36:55 server.go:637: [DEBUG] [web] ServeHTTP: GET /backups from 172.18.0.6:60442 +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetInfo starting (hddPath="/mnt/felhom-drives/scratch_hdd", hasCPUCollector=true) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] readMemInfo: guest cap=25898MB (host total was 30714380KB) → used≈11026MB avail≈14872MB +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] readMemInfo: totalKB=30714380 availKB=17636772 → total=25898MB avail=14872MB used=11026MB (42.6%) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] readDiskUsage: path="/" bsize=4096 total=68.4GB used=11.1GB avail=53.7GB (17.1%) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] readDiskUsage: path="/mnt/felhom-drives/scratch_hdd" bsize=4096 total=937.8GB used=202.4GB avail=687.7GB (22.7%) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] readLoadAvg: raw="0.86 1.23 1.24 7/1592 1409" → 1m=0.86 5m=1.23 15m=1.24 +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] readThermalZones: /sys — found 1 zones +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] readTemperature: found via hwmon at /sys — 50.9°C (hwmon1) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetInfo done in 66ms — mem=11026MB/25898MB (42.6%), rootDisk=11.1GB/68.4GB (17.1%), load=0.86/1.23/1.24, temp=50.9°C (hwmon1), cpu=23.9% +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd" total=937.8 GB used=202.4 GB avail=687.7GB (22.7%) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/nextcloud" total=937.8 GB used=202.4 GB avail=687.7GB (22.7%) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/paperless-ngx" total=937.8 GB used=202.4 GB avail=687.7GB (22.7%) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/romm" total=937.8 GB used=202.4 GB avail=687.7GB (22.7%) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/navidrome" total=937.8 GB used=202.4 GB avail=687.7GB (22.7%) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/audiobookshelf" total=937.8 GB used=202.4 GB avail=687.7GB (22.7%) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/immich" total=937.8 GB used=202.4 GB avail=687.7GB (22.7%) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/felhom-drives/scratch_hdd/userdata/calibre-web" total=937.8 GB used=202.4 GB avail=687.7GB (22.7%) +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetDiskUsage: statfs("/mnt/felhom-drives/scratch_hdd/userdata/grimmory") failed: no such file or directory +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetDiskUsage: statfs("/mnt/felhom-drives/scratch_hdd/userdata/metube") failed: no such file or directory +2026/10/22 18:36:55 info.go:13: [DEBUG] [system] GetDiskUsage: path="/mnt/sizing-bench" total=31.2 GB used=18.1 GB avail=11.5GB (61.1%) +2026/10/22 18:36:55 auth.go:144: [DEBUG] [web] auth: valid session for POST /backup/tier2/restore +2026/10/22 18:36:55 server.go:637: [DEBUG] [web] ServeHTTP: POST /backup/tier2/restore from 172.18.0.6:60442 +2026/10/22 18:36:55 restore_wizard.go:228: [WARN] [restore] restore refused — a second-drive copy is running or may still run (app="immich") diff --git a/documentation/audits/night-2026-10-23/P1-straycopy/03-redo.txt b/documentation/audits/night-2026-10-23/P1-straycopy/03-redo.txt new file mode 100644 index 00000000..dfd6b315 --- /dev/null +++ b/documentation/audits/night-2026-10-23/P1-straycopy/03-redo.txt @@ -0,0 +1,18 @@ +== 18:38:33 redo: POST /api/backup/tier2 +200 +{ + "ok": true, + "message": "2. mentés elindítva" +} +2026/10/22 18:38:33 router.go:1323: [INFO] [api] Manual Tier 2 (off-drive) backup triggered +2026/10/22 18:39:27 tier2.go:491: [INFO] [backup] Tier 2 copied immich → /mnt/felhom-drives/scratch_hdd/backups/secondary/immich (16.5 GB, 2 leg(s), 54s) +2026/10/22 18:39:28 tier2.go:491: [INFO] [backup] Tier 2 copied paperless-ngx → /mnt/sizing-bench/backups/secondary/paperless-ngx (127.4 MB, 1 leg(s), 1s) +2026/10/22 18:39:29 tier2.go:491: [INFO] [backup] Tier 2 copied privatebin → /mnt/felhom-drives/scratch_hdd/backups/secondary/privatebin (8.4 KB, 0 leg(s), 0s) +2026/10/22 18:39:29 tier2.go:553: [INFO] [backup] Tier 2 run complete: 3 app(s) processed (incl. volume-only — F6) +== equality (ls -l | md5, du -sb): source then copy +9ce52e1dc344b168ffd53ca079591eff - +9ce52e1dc344b168ffd53ca079591eff - +17179869184 /mnt/sizing-bench/userdata/media/photos/straycopy-test +17179869184 /mnt/felhom-drives/scratch_hdd/backups/secondary/immich/userdata/media/photos/straycopy-test +== copies left: +(none listed = none left) diff --git a/documentation/audits/night-2026-10-23/P1-straycopy/04-timeout-case.txt b/documentation/audits/night-2026-10-23/P1-straycopy/04-timeout-case.txt new file mode 100644 index 00000000..ea12aa85 --- /dev/null +++ b/documentation/audits/night-2026-10-23/P1-straycopy/04-timeout-case.txt @@ -0,0 +1,32 @@ +== 18:41:13 timeout case: test-only image felhom-controller-test:0.340.0-rc.5-t2to15s = rc.5 + a binary from felhom-controller 912e592 built with -X …internal/backup.tier2CopyTimeoutOverride=15s (never pushed) +felhom-controller-test:0.340.0-rc.5-t2to15s Up 12 seconds (healthy) +18:41:34 copies: felhom-tier2-copy-immich-9b848efc | Up Less than a second | immich; +18:41:38 copies: felhom-tier2-copy-immich-948f2280 | Up 2 seconds | immich; +18:41:41 copies: felhom-tier2-copy-immich-948f2280 | Up 5 seconds | immich; +18:41:44 copies: felhom-tier2-copy-immich-948f2280 | Up 8 seconds | immich; +18:41:47 copies: felhom-tier2-copy-immich-948f2280 | Up 12 seconds | immich; +18:41:51 copies: +18:41:54 copies: +18:41:57 copies: +18:42:00 copies: +18:42:03 copies: +18:42:06 copies: +18:42:10 copies: +18:42:13 copies: +18:42:16 copies: +18:42:19 copies: +== controller log +2026/10/22 18:41:34 router.go:1323: [INFO] [api] Manual Tier 2 (off-drive) backup triggered +2026/10/22 18:41:52 [WARN] [tier2] the copy into /mnt/felhom-drives/scratch_hdd/backups/secondary/immich/userdata/media/photos ran past its time limit (15s) — its container felhom-tier2-copy-immich-948f2280 was removed (removed=true) +2026/10/22 18:41:52 tier2.go:549: [WARN] [backup] Tier 2 failed for immich: tier2 rsync leg userdata/media/photos for immich: copy timed out after 15s: signal: killed: +2026/10/22 18:41:53 tier2.go:491: [INFO] [backup] Tier 2 copied paperless-ngx → /mnt/sizing-bench/backups/secondary/paperless-ngx (127.4 MB, 1 leg(s), 1s) +2026/10/22 18:41:53 tier2.go:491: [INFO] [backup] Tier 2 copied privatebin → /mnt/felhom-drives/scratch_hdd/backups/secondary/privatebin (8.4 KB, 0 leg(s), 0s) +2026/10/22 18:41:53 tier2.go:553: [INFO] [backup] Tier 2 run complete: 3 app(s) processed (incl. volume-only — F6) +== copy size after the timeout (partial, expected < 17179869184): +4393271296 /mnt/felhom-drives/scratch_hdd/backups/secondary/immich/userdata/media/photos/straycopy-test +== copies left: +(none listed = none left) +== 18:42:42 the partial copy does not grow (no copy still running): +4393271296 /mnt/felhom-drives/scratch_hdd/backups/secondary/immich/userdata/media/photos/straycopy-test +4393271296 /mnt/felhom-drives/scratch_hdd/backups/secondary/immich/userdata/media/photos/straycopy-test +0 diff --git a/documentation/audits/night-2026-10-23/P1-straycopy/05-teardown-9202.txt b/documentation/audits/night-2026-10-23/P1-straycopy/05-teardown-9202.txt new file mode 100644 index 00000000..ed8f414a --- /dev/null +++ b/documentation/audits/night-2026-10-23/P1-straycopy/05-teardown-9202.txt @@ -0,0 +1,18 @@ +== teardown 18:43:06 +sh: 1: Syntax error: "(" unexpected <- the first removal failed on quoting; redone below +switched to gitea.dooplex.hu/admin/felhom-controller:0.339.0 at 18:43:09 +healthy after ~10s: Up 7 seconds (healthy) +test image removed +felhom-controller gitea.dooplex.hu/admin/felhom-controller:0.339.0 Up 9 seconds (healthy) +filebrowser gtstef/filebrowser:1.5.6-stable Up 29 hours (healthy) +immich-machine-learning ghcr.io/immich-app/immich-machine-learning:v3.2.4 Up 4 hours (healthy) +immich-postgres ghcr.io/immich-app/postgres:16-vectorchord0.4.3-pgvectors0.2.0 Up 4 hours (healthy) +immich-redis redis:7-alpine Up 4 hours (healthy) +immich-server ghcr.io/immich-app/immich-server:v3.2.4 Up 4 hours (healthy) +traefik traefik:v3.7.13 Up 40 hours +/dev/loop0 32G 19G 12G 62% /mnt +/mnt/felhom-drives/scratch_hdd/backups/secondary/immich/userdata/media/photos: + +/mnt/sizing-bench/userdata/media/photos: +Filesystem Size Used Avail Use% Mounted on +/dev/loop0 32G 2.1G 28G 7% /mnt diff --git a/documentation/audits/night-2026-10-23/P1-straycopy/README.md b/documentation/audits/night-2026-10-23/P1-straycopy/README.md new file mode 100644 index 00000000..a48a2311 --- /dev/null +++ b/documentation/audits/night-2026-10-23/P1-straycopy/README.md @@ -0,0 +1,20 @@ +# Part 1 — the stray-copy fix, 9202 proof (night 2026-10-22 → 23) + +Code: felhom-controller `66a69d4` (the fix) + `912e592` (`--no-healthcheck`). Image `0.340.0-rc.5` (= `66a69d4`). + +| File | What it shows | +|---|---| +| `00-9202-as-found.txt` | 9202 on 0.339.0, no labelled container | +| `01-switch-rc5.txt` | rc.5 start: „start-up: no leftover second-drive copy container" | +| `02a-VOID-test-files-outside-a-leg.txt` | VOID run: the 16 GB test folder sat outside Immich's copied folders, so the copy ended in 2 s, before the probe — the probe was then (correctly) NOT refused and started a restore of the nonexistent app `straycopyprobe`, which failed at once („nincs másodlagos fájlmásolat"); nothing changed | +| `02-restart-mid-copy.txt` | the copy container `felhom-tier2-copy-immich-948f2280` running; the restore probe REFUSED („Éppen fut a második meghajtóra készülő mentési másolat…"); controller restarted; no labelled container 3 s later | +| `02b-startup-after-restart.txt` | „start-up: removed a leftover second-drive copy container felhom-tier2-copy-immich-948f2280" | +| `02c-old-controller-log-tail.txt` | the old controller's log from the trigger to its stop | +| `03-redo.txt` | the copy redone: 16.5 GB, 54 s; source = copy (`ls -l` md5 and `du -sb` equal); no container left | +| `04-timeout-case.txt` | test-only image (rc.5 + a binary from `912e592` with a 15 s copy limit, never pushed): the copy timed out, „its container … was removed (removed=true)", no container left, the partial copy (4.39 GB) stopped growing | +| `05-teardown-9202.txt` | test files removed (source + copy), 9202 back on 0.339.0 healthy, test image removed (9202 and DooPlex) | + +Red-proofs (Docker-free seams, DooPlex): every `TestStrayCopy_*` test seen failing with its mechanism removed — +no `rm -f` after an error (Timeout, Error), no name/label (NamedAndLabelled), the start-up loop not removing +(StartUpRemoves), the stray flag ignored (Unremovable, FailedStartUp), no in-flight record (RefusedWhileACopyRuns), +the web check removed (RestoreRefusedWhileACopyRuns), the main.go call removed (ClearIsWiredBeforeTheScheduler). diff --git a/hub/CHANGELOG.md b/hub/CHANGELOG.md index 377e2867..1cadf226 100644 --- a/hub/CHANGELOG.md +++ b/hub/CHANGELOG.md @@ -1,3 +1,19 @@ +## v0.167.0 (unreleased — committed 2026-10-22/23 night, NOT built, NOT deployed) — D31 and the D30 alarm clear + +- **D31 (operator 2026-10-22, R-1205).** The F-14 PBS auto-re-issue now reads the customer's newest deletion of a host + that HELD A KEY (`store.LatestKeyHoldingHostDeletion`, `escrow_acked = 1`) instead of the newest deletion of any + host. A later install deleted before it made a key (an un-acked record — `DeleteHost` refuses a host with an escrow + row unless acknowledged) owned no tenancy and no longer leaves the next install's whole-box tier waiting for the + operator's press (seen live 2026-10-21). Only keyless deletions, or none → the manual refusal, byte-unchanged. Tests + `TestLatestKeyHoldingHostDeletion_SkipsAKeylessInstall`, `TestPBSDR_D31_AKeylessInstallBetweenDoesNotBlockTheReissue`, + each red-proved. +- **D30 (R-1204).** The agent's re-key (felhom-agent `ae69ad4`) registers the new key on `POST /hosts//wg` (re-key + in place, unchanged); the new key's first handshake clears `wg_tunnel_stale` once — pinned by + `TestD30_TheAlarmClearsWhenTheNewKeyShakesHands` (red-proved). The stale text says an agent with D30 re-keys by itself + within about 15 minutes; the `wg_tunnel_ok` log line is INFO; the source comment no longer says the ok event is + mailed (it is stored, not mailed — review 2026-10-22 night). +- `scripts/wire_contract_gate.py`: `wireguard.last_handshake_age_s` left the unread list (the hub reads it since 0.166.0). + ## 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 diff --git a/hub/internal/api/host_tunnel.go b/hub/internal/api/host_tunnel.go index 5b1f191f..11a53451 100644 --- a/hub/internal/api/host_tunnel.go +++ b/hub/internal/api/host_tunnel.go @@ -10,8 +10,11 @@ import ( // 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. +// (the host_swap shape), and records once when it is healthy again (wg_tunnel_ok is an info event: stored, not +// mailed). Operator-only (notify.operatorOnlyEvents): the household cannot fix it. The repair is D30 (operator +// 2026-10-22): an agent with it makes a new key after 15 minutes of a future-stamped handshake and registers it here +// (re-key in place, the full-list push to ep0); the new key's first handshake clears this alarm — pinned by +// TestD30_TheAlarmClearsWhenTheNewKeyShakesHands. const ( eventWGTunnelStale = "wg_tunnel_stale" eventWGTunnelOK = "wg_tunnel_ok" @@ -36,7 +39,7 @@ func wgTunnelStale(w *hostWireguard) (bool, string) { 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)) + 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 (an agent with the D30 repair makes a new key by itself within about 15 minutes)", 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)) @@ -78,7 +81,7 @@ func (h *Handler) checkWGTunnel(hostID, custID string, w *hostWireguard) { default: return } - h.logger.Printf("[WARN] host %s: %s", hostID, typ) + h.logger.Printf("[%s] host %s: %s", map[bool]string{true: "WARN", false: "INFO"}[stale], hostID, typ) det := map[string]any{"host_id": hostID} if w.LastHandshakeAgeS != nil { det["last_handshake_age_s"] = *w.LastHandshakeAgeS diff --git a/hub/internal/api/host_tunnel_test.go b/hub/internal/api/host_tunnel_test.go index 4ece13db..4d8a9ecd 100644 --- a/hub/internal/api/host_tunnel_test.go +++ b/hub/internal/api/host_tunnel_test.go @@ -76,3 +76,32 @@ func TestR1204_WhatIsJudged(t *testing.T) { } } } + +// D30 (R-1204): after the agent re-keys, the box reports a restarted tunnel with no handshake yet (nothing to judge), +// then the new key's first handshake — which clears the alarm once, and raises nothing new. +// RED-PROOF (2026-10-22 night): with the `!stale && wasStale` case removed from checkWGTunnel, this fails (no ok event). +func TestD30_TheAlarmClearsWhenTheNewKeyShakesHands(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(`{"pubkey":"OLD","registered":true,"active":true,"last_handshake_age_s":0,"handshake_future_s":10800}`) // 3 h ahead + post(`{"pubkey":"NEW","registered":true,"active":true}`) // re-keyed, no handshake yet + if count(eventWGTunnelStale) != 1 || count(eventWGTunnelOK) != 0 { + t.Fatalf("stale %d ok %d, want 1 / 0 before the new key shakes hands", count(eventWGTunnelStale), count(eventWGTunnelOK)) + } + post(`{"pubkey":"NEW","registered":true,"active":true,"last_handshake_age_s":20}`) + post(`{"pubkey":"NEW","registered":true,"active":true,"last_handshake_age_s":110}`) + if count(eventWGTunnelOK) != 1 || count(eventWGTunnelStale) != 1 { + t.Fatalf("stale %d ok %d, want 1 / 1 — the new key's handshake clears the alarm once", count(eventWGTunnelStale), count(eventWGTunnelOK)) + } +} diff --git a/hub/internal/store/host_delete_test.go b/hub/internal/store/host_delete_test.go index 688f7a30..07f6df0c 100644 --- a/hub/internal/store/host_delete_test.go +++ b/hub/internal/store/host_delete_test.go @@ -281,3 +281,40 @@ func TestCountHostArtifacts(t *testing.T) { t.Errorf("unknown host artifacts = %+v, want zero value", empty) } } + +// D31 (R-1205): the F-14 gate's row is the newest deletion of a host that HELD A KEY; a later keyless install's +// un-acked deletion is skipped. RED-PROOF (2026-10-22 night): with the `AND escrow_acked = 1` filter removed, this +// fails (it returns the keyless gen2-host). +func TestLatestKeyHoldingHostDeletion_SkipsAKeylessInstall(t *testing.T) { + s := newTestStore(t) + seedHostWithArtifacts(t, s, "gen1-host", "cust-d31") + if err := s.DeleteHost("gen1-host", true); err != nil { // held a key → acked + t.Fatal(err) + } + if err := s.UpsertHost(&Host{HostID: "gen2-host", CustomerID: "cust-d31", APIKey: "k2"}); err != nil { + t.Fatal(err) + } + if err := s.DeleteHost("gen2-host", true); err != nil { // never made a key → un-acked even with the box ticked + t.Fatal(err) + } + rec, err := s.LatestKeyHoldingHostDeletion("cust-d31") + if err != nil || rec == nil { + t.Fatalf("LatestKeyHoldingHostDeletion = %+v, %v", rec, err) + } + if rec.HostID != "gen1-host" || !rec.EscrowAcked { + t.Errorf("row = %+v, want the key-holding gen1-host", rec) + } + if rec, err := s.LatestKeyHoldingHostDeletion("cust-never"); err != nil || rec != nil { + t.Errorf("no deletions → nil, got %+v, %v", rec, err) + } + s2 := newTestStore(t) + if err := s2.UpsertHost(&Host{HostID: "only-keyless", CustomerID: "cust-k", APIKey: "k"}); err != nil { + t.Fatal(err) + } + if err := s2.DeleteHost("only-keyless", true); err != nil { + t.Fatal(err) + } + if rec, err := s2.LatestKeyHoldingHostDeletion("cust-k"); err != nil || rec != nil { + t.Errorf("only a keyless deletion → nil (the manual path stays), got %+v, %v", rec, err) + } +} diff --git a/hub/internal/store/store.go b/hub/internal/store/store.go index 539efb37..6d385ce9 100644 --- a/hub/internal/store/store.go +++ b/hub/internal/store/store.go @@ -3336,6 +3336,31 @@ func (s *Store) LatestHostDeletion(customerID string) (*HostDeletion, error) { return &d, nil } +// LatestKeyHoldingHostDeletion returns the customer's most recent deletion of a host that HELD A KEY — escrow_acked=1, +// the escrow-ack flow over a real escrow row (nil when there is none). D31 (operator 2026-10-22, R-1205): the F-14 +// gate reads THIS row. An un-acked deletion is a host that never made a key (DeleteHost refuses a host with an escrow +// row unless acknowledged), so it orphaned no tenancy and must not block the re-issue for the next install — the +// escrow carry's own reasoning (escrow_carry.go). Pinned by TestLatestKeyHoldingHostDeletion_SkipsAKeylessInstall +// and TestPBSDR_D31_AKeylessInstallBetweenDoesNotBlockTheReissue. +func (s *Store) LatestKeyHoldingHostDeletion(customerID string) (*HostDeletion, error) { + var d HostDeletion + var deletedAt string + err := s.db.QueryRow(` + SELECT host_id, customer_id, deleted_at + FROM host_deletions WHERE customer_id = ? AND escrow_acked = 1 + ORDER BY id DESC LIMIT 1`, customerID, + ).Scan(&d.HostID, &d.CustomerID, &deletedAt) + if err == sql.ErrNoRows { + return nil, nil + } + if err != nil { + return nil, err + } + d.DeletedAt = parseSQLiteTime(deletedAt) + d.EscrowAcked = true + return &d, nil +} + // UpsertHost creates or updates a host identity (used by the admin mint). On // conflict it updates only operator-settable identity fields + updated_at; it does // NOT touch the reality columns (agent_version/last_report_at) or the inert intent diff --git a/hub/internal/web/pbsdr.go b/hub/internal/web/pbsdr.go index af6a3265..5ae1a16d 100644 --- a/hub/internal/web/pbsdr.go +++ b/hub/internal/web/pbsdr.go @@ -235,11 +235,13 @@ func (s *Server) pbsdrProvisionAtom(ctx context.Context, customerID string, host // half-torn earlier attempt, or the F-14 shape: host deleted, tenancy survived). // // F-14 gate (operator ruling 2026-07-13): auto-re-issue is permitted ONLY when the - // hub's own deletion record shows the tenancy's owning host — the customer's most - // recent host deletion — was removed through the escrow-ack flow. Acknowledged - // destruction is not silent re-keying; the old secret went down with the acked host. - // No record / un-acked record → the refusal below, byte-unchanged (manual path). - rec, derr := s.store.LatestHostDeletion(customerID) + // hub's own deletion record shows the tenancy's owning host was removed through the + // escrow-ack flow. Acknowledged destruction is not silent re-keying; the old secret went + // down with the acked host. D31 (operator 2026-10-22, R-1205): the owning host is the + // newest deleted host that HELD A KEY — a later install deleted before it made a key + // (an un-acked record) owned nothing and no longer blocks this. No key-holding record → + // the refusal below, byte-unchanged (manual path). + rec, derr := s.store.LatestKeyHoldingHostDeletion(customerID) if derr != nil { return "", fmt.Errorf("pbsdr: deletion-provenance lookup for %s: %w", customerID, derr) } diff --git a/hub/internal/web/pbsdr_test.go b/hub/internal/web/pbsdr_test.go index d8a87f18..c8a23adb 100644 --- a/hub/internal/web/pbsdr_test.go +++ b/hub/internal/web/pbsdr_test.go @@ -457,7 +457,7 @@ func TestPBSDR_F14AutoReissueOnAckedDeletion(t *testing.T) { } // F-14 scenario B (the never-silently-re-key law): a surviving tenancy WITHOUT an acked -// deletion record — none at all, or the latest one un-acked — keeps the current refusal and +// deletion record — none at all, or only un-acked ones (D31: a keyless install) — keeps the current refusal and // records ZERO re-issue calls (the exact non-effect). // RED-PROOF (§10 B): removing the record check in pbsdrProvisionAtom (auto-reissue // unconditionally) → the zero-reissue assertions here fail. @@ -499,6 +499,40 @@ func TestPBSDR_F14NoRecordNeverRekeys(t *testing.T) { }) } +// D31 (operator 2026-10-22, R-1205 — seen live 2026-10-21): the tenancy's owning host was deleted through the escrow-ack +// flow, then a SECOND install was deleted before it made a key. The re-issue for the third install proceeds. +// RED-PROOF (2026-10-22 night): with the gate reading LatestHostDeletion again (the newest row, un-acked), this fails +// with the 502 refusal and zero re-issue calls. +func TestPBSDR_D31_AKeylessInstallBetweenDoesNotBlockTheReissue(t *testing.T) { + fake := &fakeTenancy{provisionErr: tenantsync.ErrTokenExists, secret: "REISSUED-SECRET"} + s, st, _ := newPBSDRServer(t, fake) + if err := st.UpsertHost(&store.Host{HostID: "peti-00-dead", CustomerID: "peti", APIKey: "oldkey"}); err != nil { + t.Fatal(err) + } + if _, _, err := st.SaveHostEscrow("peti-00-dead", []byte("opaque"), "fp", "posture", "2026-07-01T00:00:00Z", ""); err != nil { + t.Fatal(err) + } + if err := st.DeleteHost("peti-00-dead", true); err != nil { + t.Fatal(err) + } + if err := st.UpsertHost(&store.Host{HostID: "peti-00-short", CustomerID: "peti", APIKey: "shortkey"}); err != nil { + t.Fatal(err) + } + if err := st.DeleteHost("peti-00-short", true); err != nil { // no escrow row → an un-acked record + t.Fatal(err) + } + rr := postUpdate(t, s, url.Values{"dr_tier": {"on"}}) + if rr.Code != 303 { + t.Fatalf("enable = %d (%s), want 303 — a keyless install between must not block the re-issue", rr.Code, rr.Body.String()) + } + if fake.reissueCalls != 1 { + t.Errorf("reissue calls = %d, want 1", fake.reissueCalls) + } + if desc, _, _ := hostState(t, st); desc == nil || !desc.Enabled { + t.Fatalf("descriptor after the re-issue = %+v", desc) + } +} + func TestPBSDR_Reissue(t *testing.T) { fake := &fakeTenancy{secret: "OLD-SECRET"} s, st, logBuf := newPBSDRServer(t, fake) diff --git a/scripts/wire_contract_gate.py b/scripts/wire_contract_gate.py index 9b99e64c..28af22c7 100644 --- a/scripts/wire_contract_gate.py +++ b/scripts/wire_contract_gate.py @@ -259,9 +259,7 @@ ALLOWLIST = { "does not bite here. **Delete with its siblings.**"), - (_AH, "wireguard.last_handshake_age_s"): ( - "redundant: hub-side wgsync reconciles peers from its own state, and the OOB path's own " - "wg_handshake_age_s IS now decoded (into HostOOBRow, for the alert text)."), + # wireguard.last_handshake_age_s left this list 2026-10-22 night: the hub reads it (api/host_tunnel.go, R-1204). # ---- R-319: guest_net AND ALL SEVEN CHILDREN ARE GONE FROM THIS LIST ---- # They are no longer allowlisted because they are no longer unconsumed: the hub models the R-54