admin/felhom.eu
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

hub v0.167.0 source (not built, not deployed): D31 — the F-14 PBS auto re-issue reads the newest deletion of a host that held a key, a keyless install between no longer blocks it (R-1205); D30 — the new key's handshake clears wg_tunnel_stale (pinned), wording; wire gate entry; Part 1 stray-copy 9202 evidence
gates / gates (push) Successful in 15m46s
Details

Browse Source
This commit is contained in:
authentik Default Admin
2026-10-22 21:04:42 +02:00
parent 96ac07e168
commit 84751cb0ce
18 changed files with 517 additions and 13 deletions
Download Patch File Download Diff File Expand all files Collapse all files
documentation/audits/night-2026-10-23/P1-straycopy/00-9202-as-found.txt
+14
View File
@@ -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
documentation/audits/night-2026-10-23/P1-straycopy/01-switch-rc5.txt
+5
View File
@@ -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
documentation/audits/night-2026-10-23/P1-straycopy/02-restart-mid-copy.txt
+30
View File
@@ -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:
documentation/audits/night-2026-10-23/P1-straycopy/02a-VOID-test-files-outside-a-leg.txt
+47
View File
@@ -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
documentation/audits/night-2026-10-23/P1-straycopy/02b-startup-after-restart.txt
+1
View File
@@ -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
documentation/audits/night-2026-10-23/P1-straycopy/02c-old-controller-log-tail.txt
+175
View File
@@ -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")
documentation/audits/night-2026-10-23/P1-straycopy/03-redo.txt
+18
View File
@@ -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)
documentation/audits/night-2026-10-23/P1-straycopy/04-timeout-case.txt
+32
View File
@@ -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
documentation/audits/night-2026-10-23/P1-straycopy/05-teardown-9202.txt
+18
View File
@@ -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
documentation/audits/night-2026-10-23/P1-straycopy/README.md
+20
View File
@@ -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).
hub/CHANGELOG.md
+16
View File
@@ -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/<id>/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
hub/internal/api/host_tunnel.go
+7 -4
View File
@@ -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
hub/internal/api/host_tunnel_test.go
+29
View File
@@ -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))
}
}
hub/internal/store/host_delete_test.go
+37
View File
@@ -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)
}
}
hub/internal/store/store.go
+25
View File
@@ -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
hub/internal/web/pbsdr.go
+7 -5
View File
@@ -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)
}
hub/internal/web/pbsdr_test.go
+35 -1
View File
@@ -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)
scripts/wire_contract_gate.py
+1 -3
View File
@@ -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