catch-up session 2026-10-05: design 07 §6.1.1 (a box that is not always on), 08 §6.4; rulings 109-111, CC decisions 112-118; R-871/R-873..R-877 closed, R-872 narrowed (dated check), R-878 opened; live evidence; STATUS
gates / gates (push) Successful in 33s

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0159rPz1ZhFKsS53msqPYxtS
This commit is contained in:
2026-10-05 10:29:22 +02:00
parent ff25f1076d
commit 9bb45eaaa2
34 changed files with 790 additions and 18 deletions
@@ -0,0 +1,9 @@
08:27:24
('Tester-2-be8404', '0.142.0', '2026-10-04 18:05:48', None)
('demo-felhom-8363b5', '0.145.0', '2026-10-05 08:23:56', '0.145.0')
('demo-hp-bb76ea', '0.145.0', '2026-10-05 08:27:06', '0.145.0')
('tester-1-d70be4', '0.145.0', '2026-10-05 08:27:31', '0.145.0')
== demo-hp: agent felhom-agent 0.145.0 | controller 0.295.0 | healthy 20 of 21 | guard 1
== felhom-pve: agent felhom-agent 0.145.0 | controller 0.295.0 | healthy 4 of 5 | guard 1
Oct 05 10:08:58 demo-felhom felhom-agent[3935656]: time=2026-10-05T10:08:58.009+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: BUN
9202: gitea.dooplex.hu/admin/felhom-controller:0.295.0 Up 29 minutes (healthy)
@@ -0,0 +1,12 @@
### 06:58:03 UTC: set 9202's window to 09:05 (Budapest) by POST /backups/window
HTTP 303
2026/10/05 06:58:05 scheduler.go:172: [INFO] [scheduler] Daily job db-dump rescheduled 02:30 → 09:05 (next run 2026-10-05 09:05 CEST)
2026/10/05 06:58:05 scheduler.go:172: [INFO] [scheduler] Daily job tier2-backup rescheduled 03:30 → 10:05 (next run 2026-10-05 10:05 CEST)
2026/10/05 06:58:05 scheduler.go:172: [INFO] [scheduler] Daily job offbox-backup rescheduled 04:15 → 10:50 (next run 2026-10-05 10:50 CEST)
2026/10/05 06:58:05 scheduler.go:67: [DEBUG] [scheduler] daily job db-dump: rescheduled — recomputing next run
2026/10/05 06:58:05 scheduler.go:67: [DEBUG] [scheduler] daily job tier2-backup: rescheduled — recomputing next run
2026/10/05 06:58:05 scheduler.go:67: [DEBUG] [scheduler] daily job db-dump: next run at 2026-10-05 09:05:00 CEST (waiting 6m54s)
2026/10/05 06:58:05 scheduler.go:67: [DEBUG] [scheduler] daily job tier2-backup: next run at 2026-10-05 10:05:00 CEST (waiting 1h6m54s)
2026/10/05 06:58:05 scheduler.go:67: [DEBUG] [scheduler] daily job offbox-backup: rescheduled — recomputing next run
2026/10/05 06:58:05 scheduler.go:67: [DEBUG] [scheduler] daily job offbox-backup: next run at 2026-10-05 10:50:00 CEST (waiting 1h51m54s)
2026/10/05 06:58:05 backup_handlers.go:65: [INFO] [web] backup window set to 09:05 (legs 09:05/10:05/10:50)
@@ -0,0 +1,9 @@
### 07:03:01 pct shutdown 9202
status: stopped
### 07:08:01 pct start 9202
status: running
### 07:10:35 controller log after the start
2026/10/05 07:08:08 scheduler.go:132: [INFO] [scheduler] Daily job db-dump scheduled for 2026-10-06 09:05 CEST
2026/10/05 07:08:08 scheduler.go:132: [INFO] [scheduler] Daily job tier2-backup scheduled for 2026-10-05 10:05 CEST
2026/10/05 07:08:08 scheduler.go:132: [INFO] [scheduler] Daily job offbox-backup scheduled for 2026-10-05 10:50 CEST
2026/10/05 07:08:08 backup.go:1166: [INFO] [backup] Found 2 DB dump files across drives
@@ -0,0 +1 @@
('demo-felhom', 'backup_catchup_done', 'info', 'Kimaradt mentés pótolva: a doboz ki volt kapcsolva 10:07-kor, a mentés most elkészült.', 'controller', '2026-10-05 08:25:03')
@@ -0,0 +1,12 @@
### 07:29:47 9202: controller 0.295.0 by its bootstrap file
gitea.dooplex.hu/admin/felhom-controller:0.295.0
gitea.dooplex.hu/admin/felhom-controller:0.295.0 started 2026-10-05T07:29:50.143207934Z
2026/10/05 07:29:50 scheduler.go:149: [INFO] [scheduler] Daily job db-dump scheduled for 2026-10-06 09:05 CEST
2026/10/05 07:29:50 nightchain.go:280: [INFO] [catch-up] controller start: no backup leg missed its last scheduled time — nothing to make up
{
"seeded_at": "2026-10-05T07:29:50.484758959Z",
"ended": {},
"db_dump_ok": "0001-01-01T00:00:00Z",
"last_catch_up": "0001-01-01T00:00:00Z",
"banner_dismissed_through": "0001-01-01T00:00:00Z"
}
@@ -0,0 +1,41 @@
### 07:33:00 W = 09:35 Budapest (07:35 UTC). pct shutdown 9202
command 'lxc-stop -n 9202 --nokill --timeout 60' failed: exit code 1
status: stopped
### 07:38:00 pct start 9202
status: running
### 07:39:06 after the start
2026/10/05 07:38:09 scheduler.go:149: [INFO] [scheduler] Daily job db-dump scheduled for 2026-10-06 09:35 CEST
2026/10/05 07:38:09 nightchain.go:291: [INFO] [catch-up] controller start: the box missed [db-dump] (last scheduled 2026-10-05 09:35) — ONE catch-up in 15m0s (backup legs only; app updates wait for a real night)
### 07:53:51 the catch-up
2026/10/05 07:43:09 scheduler.go:381: [INFO] [scheduler] Running job: system-health
2026/10/05 07:43:09 backup.go:1166: [INFO] [backup] Found 2 DB dump files across drives
2026/10/05 07:44:09 scheduler.go:381: [INFO] [scheduler] Running job: stack-scan
2026/10/05 07:46:09 scheduler.go:381: [INFO] [scheduler] Running job: stack-scan
2026/10/05 07:48:09 scheduler.go:381: [INFO] [scheduler] Running job: docker-socket-users
2026/10/05 07:48:09 scheduler.go:381: [INFO] [scheduler] Running job: offsite-credential-retry
2026/10/05 07:48:09 scheduler.go:381: [INFO] [scheduler] Running job: stack-scan
2026/10/05 07:48:09 scheduler.go:381: [INFO] [scheduler] Running job: backup-cache
2026/10/05 07:48:09 scheduler.go:381: [INFO] [scheduler] Running job: system-health
2026/10/05 07:48:09 backup.go:1166: [INFO] [backup] Found 2 DB dump files across drives
2026/10/05 07:50:09 scheduler.go:381: [INFO] [scheduler] Running job: stack-scan
2026/10/05 07:52:09 scheduler.go:381: [INFO] [scheduler] Running job: stack-scan
2026/10/05 07:53:09 nightchain.go:332: [INFO] [catch-up] running the missed db-dump leg
2026/10/05 07:53:09 scheduler.go:381: [INFO] [scheduler] Running job: offsite-credential-retry
2026/10/05 07:53:09 scheduler.go:381: [INFO] [scheduler] Running job: docker-socket-users
2026/10/05 07:53:09 scheduler.go:381: [INFO] [scheduler] Running job: backup-cache
2026/10/05 07:53:09 scheduler.go:381: [INFO] [scheduler] Running job: system-health
2026/10/05 07:53:09 backup.go:1166: [INFO] [backup] Found 2 DB dump files across drives
2026/10/05 07:53:09 dbdump.go:410: [INFO] [backup] DB dump: paperless-postgres → paperless-ngx-postgres.sql (412.6 KB, 436ms, 72 tables)
2026/10/05 07:53:30 nightchain.go:340: [INFO] [catch-up] done: db-dump in 21s (missed at 2026-10-05 09:35)
{
"seeded_at": "2026-10-05T07:29:50.484758959Z",
"ended": {
"db-dump": "2026-10-05T07:53:30.483916689Z"
},
"db_dump_ok": "2026-10-05T07:53:30.484211296Z",
"last_catch_up": "2026-10-05T07:53:30.484384683Z",
"banner_dismissed_through": "0001-01-01T00:00:00Z"
}
2026/10/05 07:38:09 nightchain.go:291: [INFO] [catch-up] controller start: the box missed [db-dump] (last scheduled 2026-10-05 09:35) — ONE catch-up in 15m0s (backup legs only; app updates wait for a real night)
2026/10/05 07:53:09 nightchain.go:332: [INFO] [catch-up] running the missed db-dump leg
2026/10/05 07:53:30 nightchain.go:340: [INFO] [catch-up] done: db-dump in 21s (missed at 2026-10-05 09:35)
@@ -0,0 +1,23 @@
2026/10/05 07:58:35 main.go:340: [INFO] felhom-controller 0.295.0 starting (customer: demo-hp, domain: enkisfelhom.hu)
2026/10/05 07:58:35 scheduler.go:149: [INFO] [scheduler] Daily job tier2-backup scheduled for 2026-10-06 03:30 CEST
2026/10/05 07:58:35 nightchain.go:291: [INFO] [catch-up] controller start: the box missed [db-dump tier2 offsite] (last scheduled 2026-10-05 04:15) — ONE catch-up in 15m0s (backup legs only; app updates wait for a real night)
2026/10/05 08:13:35 nightchain.go:332: [INFO] [catch-up] running the missed db-dump leg
2026/10/05 08:13:36 dbdump.go:410: [INFO] [backup] DB dump: paperless-postgres → paperless-ngx-postgres.sql (413.8 KB, 423ms, 72 tables)
2026/10/05 08:13:57 nightchain.go:332: [INFO] [catch-up] running the missed tier2 leg
2026/10/05 08:13:57 tier2.go:425: [INFO] [backup] Tier 2 copied paperless-ngx → /mnt/sys_drive/felhom-data/backups/secondary/paperless-ngx (82.5 MB, 1 leg(s), 0s) [SSD: state-only]
2026/10/05 08:13:57 tier2.go:425: [INFO] [backup] Tier 2 copied privatebin → /mnt/felhom-drives/scratch_hdd/backups/secondary/privatebin (20.3 KB, 0 leg(s), 0s)
2026/10/05 08:13:57 tier2.go:476: [INFO] [backup] Tier 2 run complete: 2 app(s) processed (incl. volume-only — F6)
2026/10/05 08:13:57 nightchain.go:332: [INFO] [catch-up] running the missed offsite leg
2026/10/05 08:13:57 main.go:1385: [INFO] [offbox] no scheduled off-site target on this box — the off-site leg does nothing
2026/10/05 08:13:57 nightchain.go:340: [INFO] [catch-up] done: db-dump, offsite, tier2 in 22s (missed at 2026-10-05 04:15)
{
"seeded_at": "2026-09-30T07:54:19.875183Z",
"ended": {
"db-dump": "2026-10-05T08:13:57.406392075Z",
"offsite": "2026-10-05T08:13:57.69370068Z",
"tier2": "2026-10-05T08:13:57.693478189Z"
},
"db_dump_ok": "2026-10-05T08:13:57.406683255Z",
"last_catch_up": "2026-10-05T08:13:57.693858077Z",
"banner_dismissed_through": "2026-10-05T00:30:00Z"
}
@@ -0,0 +1,24 @@
### 08:05:01 W = 10:07 Budapest (08:07 UTC). park + stop the controller (apps keep running)
felhom-controller
4
### 08:10:00 start the controller + unpark
felhom-controller
2026/10/05 08:10:02 [INFO] [scheduler] Daily job db-dump scheduled for 2026-10-06 10:07 CEST
### 08:25:04 the catch-up
{
"seeded_at": "2026-10-05T07:29:41.65020944Z",
"ended": {
"db-dump": "2026-10-05T08:25:03.369812125Z"
},
"db_dump_ok": "2026-10-05T08:25:03.370056355Z",
"last_catch_up": "2026-10-05T08:25:03.370196251Z",
"banner_dismissed_through": "0001-01-01T00:00:00Z"
}### 08:25:19 the catch-up lines (this box logs without file:line)
2026/10/05 08:10:02 [INFO] [catch-up] controller start: the box missed [db-dump] (last scheduled 2026-10-05 10:07) — ONE catch-up in 15m0s (backup legs only; app updates wait for a real night)
2026/10/05 08:25:02 [INFO] [catch-up] running the missed db-dump leg
2026/10/05 08:25:03 [INFO] [catch-up] done: db-dump in 1s (missed at 2026-10-05 10:07)
### 08:25:20 window back to 02:30
HTTP 303
2026/10/05 08:25:22 [INFO] [web] backup window set to 02:30 (legs 02:30/03:30/04:15)
ls: cannot access '/var/lib/felhom-agent/guests/9201/controller-parked': No such file or directory
4
@@ -0,0 +1,120 @@
### RED-PROOF scheduler late-fire guard dropped
scheduler_test.go:128: a 6-hour-late fire ran the job (the app-update leg would start at noon)
--- FAIL: TestDaily_LateFireIsSkipped (0.00s)
--- PASS: TestDaily_LateFireIsSkipped/on_time (0.00s)
--- FAIL: TestDaily_LateFireIsSkipped/after_a_suspend (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/scheduler 0.004s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-controller/internal/scheduler 0.456s
### RED-PROOF 1 Missed returns nothing (the old behaviour: no catch-up)
nightchain_test.go:99: no catch-up was scheduled for a box off across W (missed [])
--- FAIL: TestCatchUp_OffAtWThenOn_OneCatchUpAfter15Min (0.00s)
nightchain_test.go:135: the catch-up never finished
--- FAIL: TestCatchUp_TwoMissedNights_One (3.00s)
nightchain_test.go:151: the catch-up never finished
--- FAIL: TestCatchUp_PowerCutMidChain_FinishesTheRest (3.00s)
nightchain_test.go:178: missed [], want tier2 + offsite of the night of the 4th
--- FAIL: TestCatchUp_LegAboutToRun_LeftToNormal (0.00s)
nightchain_test.go:189: the catch-up never finished
--- FAIL: TestCatchUp_NeverRunsAnythingButBackupLegs (3.00s)
nightchain_test.go:206: the catch-up never finished
--- FAIL: TestCatchUp_WaitsForAWholeGuestBackup (3.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 12.015s
FAIL
### RED-PROOF 2 a leg that ran is not checked (Ended ignored)
nightchain_test.go:121: a normal night was made up again: [db-dump tier2 offsite]
--- FAIL: TestCatchUp_NightRan_DaytimeRestart_None (0.00s)
nightchain_test.go:140: after the catch-up nothing is missed any more, got [db-dump tier2 offsite]
--- FAIL: TestCatchUp_TwoMissedNights_One (0.00s)
nightchain_test.go:153: ran [db-dump tier2 offsite], want only tier2 + offsite
--- FAIL: TestCatchUp_PowerCutMidChain_FinishesTheRest (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.009s
FAIL
### RED-PROOF 3 the 15-minute delay dropped
nightchain_test.go:103: the catch-up must wait 15m0s first, slept []
--- FAIL: TestCatchUp_OffAtWThenOn_OneCatchUpAfter15Min (0.00s)
nightchain_test.go:208: slept [1m0s 1m0s 1m0s] — want the 15 min delay then 3 one-minute waits for the quiesce
--- FAIL: TestCatchUp_WaitsForAWholeGuestBackup (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.008s
FAIL
### RED-PROOF 4 a pending catch-up does not block a second one
nightchain_test.go:133: a second catch-up was scheduled while one was pending: [db-dump tier2 offsite]
--- FAIL: TestCatchUp_TwoMissedNights_One (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.009s
FAIL
### RED-PROOF 5 the quiesce wait dropped
nightchain_test.go:208: slept [15m0s] — want the 15 min delay then 3 one-minute waits for the quiesce
--- FAIL: TestCatchUp_WaitsForAWholeGuestBackup (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.009s
FAIL
### RED-PROOF 6 the leave-to-normal rule dropped
nightchain_test.go:174: the dump due in 20 minutes was put in the catch-up: [db-dump tier2 offsite]
--- FAIL: TestCatchUp_LegAboutToRun_LeftToNormal (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.009s
FAIL
### RED-PROOF 8 a fresh ledger counts history as missed
nightchain_test.go:161: a freshly seeded ledger made up [db-dump tier2 offsite]
--- FAIL: TestCatchUp_FreshLedger_None (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.007s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.008s
### RED-PROOF 7 the resume watch compares wall with wall (compiles)
nightchain_test.go:241: a 7-hour suspend was not seen
--- FAIL: TestResumeWatch_SeesASuspend (2.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 2.010s
FAIL
### RED-PROOF 9 the catch-up runs whatever Legs holds (not only the missed chain legs)
nightchain_test.go:153: ran [db-dump tier2 offsite], want only tier2 + offsite
--- FAIL: TestCatchUp_PowerCutMidChain_FinishesTheRest (0.00s)
nightchain_test.go:191: an app update ran inside a catch-up
--- FAIL: TestCatchUp_NeverRunsAnythingButBackupLegs (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.008s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.009s
### RED-PROOF 10 the whole-guest cycle does not wait for a running catch-up
r871_catchup_test.go:21: the backup started while a catch-up ran: start=1 stopped=[nextcloud]
--- FAIL: TestR871_ScheduledCycleWaitsForCatchUp (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/quiesce 0.005s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-controller/internal/quiesce 0.005s
### RED-PROOF 12 the update leg inside the shared off-site body
--- PASS: TestR871_CatchUpWiring (0.01s)
r871_catchup_wiring_test.go:44: the update leg is inside the off-site body the catch-up runs
--- FAIL: TestR871_CatchUpRunsNoUpdateLeg (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/cmd/controller 0.019s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-controller/cmd/controller 0.019s
### RED-PROOF 11 the start trigger not wired (test now keyed on the argument)
r871_catchup_wiring_test.go:37: the catch-up's START trigger (Evaluate(ctx, "controller start")) is called 0 times, want 1
--- FAIL: TestR871_CatchUpWiring (0.02s)
--- PASS: TestR871_CatchUpRunsNoUpdateLeg (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/cmd/controller 0.031s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-controller/cmd/controller 0.026s
### RED-PROOF hub: backup_catchup_done not allowed
r871_catchup_event_test.go:10: backup_catchup_done is not an allowed event type — the box's catch-up line would be dropped with a 400
--- FAIL: TestR871_CatchUpEventIsAllowed (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-hub/internal/api 0.020s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-hub/internal/api 0.019s
@@ -0,0 +1,27 @@
### 07:54:16 banner on 9202 — the ledger set by hand to a box whose last dump is 3 days old (scratch fixture, said so); window back to 02:30
HTTP 303
ledger set: last dump 2026-10-02T07:54:19.875183Z
2026/10/05 07:54:20 nightchain.go:291: [INFO] [catch-up] controller start: the box missed [db-dump tier2 offsite] (last scheduled 2026-10-05 04:15) — ONE catch-up in 15m0s (backup legs only; app updates wait for a real night)
--- the banner as GET /launcher served it (9202, Hungarian household):
<div class="alerts-container">
<div class="alert-banner alert-banner-warning" id="missed-backup-banner">
<span class="alert-icon"><svg class="ico"><use href="#i-triangle-alert"/></svg></span>
<span class="alert-message">A legutóbbi mentés 3 nappal ezelőtt készült. Válassz egy olyan időpontot, amikor a doboz általában be van kapcsolva.</span>
<span class="alert-actions">
<a href="/backups#window_start" class="btn btn-sm btn-primary">Mentési idő módosítása</a>
<form method="POST" action="/backups/missed-banner/dismiss" style="display:inline">
<input type="hidden" name="_csrf" value="(redacted)"><input type="hidden" name="back" value="/launcher">
<button type="submit" class="btn btn-sm btn-outline">Bezárás</button>
</form>
</span>
</div>
</div
### 07:54:54 POST /backups/missed-banner/dismiss (the Bezárás button)
HTTP 302
banner on /launcher after closing: 0
2026/10/05 07:54:46 missed_backup_banner.go:90: [DEBUG] [web] missed-backup banner: rendered on /launcher (last=2026-10-02T07:54:19Z off_at="" suggest="")
2026/10/05 07:54:46 missed_backup_banner.go:90: [DEBUG] [web] missed-backup banner: rendered on /launcher (last=2026-10-02T07:54:19Z off_at="" suggest="")
2026/10/05 07:54:57 missed_backup_banner.go:90: [DEBUG] [web] missed-backup banner: rendered on /launcher (last=2026-10-02T07:54:19Z off_at="" suggest="")
2026/10/05 07:54:57 missed_backup_banner.go:90: [DEBUG] [web] missed-backup banner: rendered on /launcher (last=2026-10-02T07:54:19Z off_at="" suggest="")
2026/10/05 07:54:57 missed_backup_banner.go:100: [INFO] [web] missed-backup banner: closed by the household until the next missed backup time (after 2026-10-05T02:30:00+02:00)
"banner_dismissed_through": "2026-10-05T00:30:00Z"
@@ -0,0 +1,56 @@
### RED-PROOF 1 stale is silent (the old behaviour)
banner_test.go:32: not shown although the last backup is 2 days old
--- FAIL: TestBanner_ShownWithReasonAndSuggestion (0.00s)
banner_test.go:72: the banner did not come back after the next missed backup time
--- FAIL: TestBanner_DismissedThenBackAfterANewMiss (0.00s)
banner_test.go:92: banner = {Show:false LastBackup:2026-10-02 04:20:00 +0200 CEST DaysAgo:3 OffAt:02:30 Suggest:21:00 MissedAt:2026-10-05 02:30:00 +0200 CEST}, want shown with the off-site copy's
--- FAIL: TestBanner_OffsiteTierCounts (0.00s)
banner_test.go:107: banner = {Show:false LastBackup:2026-10-03 02:31:00 +0200 CEST DaysAgo:2 OffAt: Suggest: MissedAt:2026-10-05 02:30:00 +0200 CEST}, want shown, no suggestion, no 'off at'
--- FAIL: TestBanner_NoPatternNoSuggestion (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.005s
FAIL
### RED-PROOF 2 dismissal ignored
banner_test.go:64: a closed banner came back without a new miss
--- FAIL: TestBanner_DismissedThenBackAfterANewMiss (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.005s
FAIL
### RED-PROOF 4 the seed ignored (banner on upgrade day)
banner_test.go:53: shown on the day of the upgrade: {Show:true LastBackup:0001-01-01 00:00:00 +0000 UTC DaysAgo:0 OffAt:02:30 Suggest:21:00 MissedAt:2026-10-05 02:30:00 +0200 CEST}
--- FAIL: TestBanner_NotShownBeforeTheRecordKnows (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.005s
FAIL
### RED-PROOF 5 the off-site tier ignored
banner_test.go:92: banner = {Show:false LastBackup:0001-01-01 00:00:00 +0000 UTC DaysAgo:0 OffAt: Suggest: MissedAt:0001-01-01 00:00:00 +0000 UTC}, want shown with the off-site copy's 3 days
--- FAIL: TestBanner_OffsiteTierCounts (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.004s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.009s
### RED-PROOF 3 a suggestion from noise (no day count) — test noise now evenings on 2 of 7 days
banner_test.go:107: banner = {Show:true LastBackup:2026-10-03 02:31:00 +0200 CEST DaysAgo:2 OffAt: Suggest:21:00 MissedAt:2026-10-05 02:30:00 +0200 CEST}, want shown, no suggestion, no 'off at'
--- FAIL: TestBanner_NoPatternNoSuggestion (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.005s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-controller/internal/nightchain 0.009s
### RED-PROOF 6 the banner not wired into executeTemplate
r871_missed_backup_banner_test.go:37: not shown on /launcher although the last backup is 3 days old
--- FAIL: TestR871_BannerShownThenClosedUntilTheNextMiss (0.06s)
--- PASS: TestR871_BannerNotShownAfterASuccessfulNight (0.06s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/web 0.130s
FAIL
### RED-PROOF 7 the dismissal not recorded
r871_missed_backup_banner_test.go:47: still shown after the household closed it
--- FAIL: TestR871_BannerShownThenClosedUntilTheNextMiss (0.06s)
--- PASS: TestR871_BannerNotShownAfterASuccessfulNight (0.07s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-controller/internal/web 0.145s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-controller/internal/web 0.148s
@@ -0,0 +1,27 @@
### RED-PROOF R-872a: the old skip of a down box
r872_down_box_test.go:60: events map[] — a box off at every deadline must raise the missed-backup alarms, down or not
--- FAIL: TestR872_DownEveryNightRaisesTheMissedAlarms (0.04s)
--- PASS: TestR872_DownWithARecentDumpIsQuiet (0.04s)
--- PASS: TestR872_NewDownBoxIsQuiet (0.03s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-hub/internal/monitor 0.118s
FAIL
### RED-PROOF R-872b: no grace for a new box
--- PASS: TestR872_DownEveryNightRaisesTheMissedAlarms (0.04s)
--- PASS: TestR872_DownWithARecentDumpIsQuiet (0.04s)
r872_down_box_test.go:84: events map[expected_backup_missed:1 expected_dbdump_missed:1] for a box bound a day ago
--- FAIL: TestR872_NewDownBoxIsQuiet (0.03s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-hub/internal/monitor 0.113s
FAIL
### RED-PROOF R-872c: the down dump line shortened to 12 h
--- PASS: TestR872_DownEveryNightRaisesTheMissedAlarms (0.04s)
r872_down_box_test.go:76: events map[expected_dbdump_missed:1] — a dump 20 h ago and a backup 30 h ago are inside the down box's lines
--- FAIL: TestR872_DownWithARecentDumpIsQuiet (0.04s)
r872_down_box_test.go:84: events map[expected_backup_missed:1 expected_dbdump_missed:1] for a box bound a day ago
--- FAIL: TestR872_NewDownBoxIsQuiet (0.03s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-hub/internal/monitor 0.113s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-hub/internal/monitor 38.508s
@@ -0,0 +1,8 @@
### RED-PROOF R-873: the weekly household limit dropped
r873_liveness_weekly_test.go:40: night 2: household 1 mails (want 0 — told once this week), operator 2 (want every edge)
--- FAIL: TestR873_HouseholdHearsAnOutageAtMostWeekly (0.04s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-hub/internal/notify 0.043s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-hub/internal/notify 1.382s
@@ -0,0 +1,11 @@
Oct 05 09:38:46 demo-felhom felhom-agent[3840353]: time=2026-10-05T09:38:46.189+02:00 level=INFO msg="backup: restore-test scheduler shutting down" reason="context canceled"
Oct 05 09:38:46 demo-felhom felhom-agent[3935656]: time=2026-10-05T09:38:46.215+02:00 level=INFO msg="felhom-agent daemon starting" version=0.145.0 host_id=demo-felhom-8363b5 hub_url=https://hub.felhom.eu interval_s=900
Oct 05 09:38:46 demo-felhom felhom-agent[3935656]: time=2026-10-05T09:38:46.836+02:00 level=INFO msg="backup: restore-test scheduler starting (per-archive due-check)" eval_interval=6h0m0s settle=24h0m0s
Oct 05 09:38:48 demo-felhom felhom-agent[3935656]: time=2026-10-05T09:38:48.047+02:00 level=INFO msg="janitor: starting (restore-test scratch retry + stale-lock sweep)" interval=10m0s
Oct 05 10:08:46 demo-felhom felhom-agent[3935656]: time=2026-10-05T10:08:46.837+02:00 level=INFO msg="backup: restore-test first evaluation after start (R-874)" after=30m0s
Oct 05 10:08:47 demo-felhom felhom-agent[3935656]: time=2026-10-05T10:08:47.156+02:00 level=INFO msg="backup: restore-test tier is DUE (per-archive; oldest-proven first among due tiers)" target=felhom-backup archive=felhom-backup:backup/vzdump-lxc-9201-2026_10_04-07_49_00.tar.zst landed=2026-10-04T0
Oct 05 10:08:47 demo-felhom felhom-agent[3935656]: time=2026-10-05T10:08:47.948+02:00 level=INFO msg="restore-test: space preflight passed" storage=local-lvm required_bytes=8002555904 avail_bytes=365212749058
Oct 05 10:08:47 demo-felhom felhom-agent[3935656]: time=2026-10-05T10:08:47.972+02:00 level=INFO msg="restore-test: full-fidelity restore params derived from the archive config" scratch=990000 params=4
Oct 05 10:08:48 demo-felhom felhom-agent[3935656]: time=2026-10-05T10:08:48.047+02:00 level=INFO msg="janitor: stale-lock sweep deferred — a heavy operation is in flight" busy=restore-test
Oct 05 10:09:16 demo-felhom felhom-agent[3935656]: time=2026-10-05T10:09:16.524+02:00 level=INFO msg="restore-test: scratch guest torn down" vmid=990000
Oct 05 10:09:16 demo-felhom felhom-agent[3935656]: time=2026-10-05T10:09:16.524+02:00 level=INFO msg="backup: scheduled restore-test passed" archive=felhom-backup:backup/vzdump-lxc-9201-2026_10_04-07_49_00.tar.zst duration_s=29.36536675
@@ -0,0 +1,9 @@
### RED-PROOF R-874: the first-evaluation timer dropped (back to the bare ticker)
r874_first_eval_test.go:38: no evaluation within 3 s of start (FirstEval 30 ms) — a box with short sessions never gets a restore-test
--- FAIL: TestR874_FirstEvaluationAfterStart (3.01s)
--- PASS: TestR874_CrashLoopNeverEvaluates (0.10s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-agent/internal/backup 3.119s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-agent/internal/backup 0.151s
@@ -0,0 +1,8 @@
### RED-PROOF R-875: the v0.144.1 text back
unsent_test.go:44: health_reason = "sent after the agent stopped mid-pass (R-868)", want the neutral "sent late …"
--- FAIL: TestR868_KilledPassIsReportedAtStart (0.00s)
FAIL
FAIL gitea.dooplex.hu/admin/felhom-agent/internal/osupdate 0.011s
FAIL
### restored
ok gitea.dooplex.hu/admin/felhom-agent/internal/osupdate 1.738s
@@ -0,0 +1,12 @@
### 07:55:21 before
"armed": true,
"last_boot_at": "2026-10-05T06:14:33Z",
"tripped": false,
"unclean_boots_in_window": 0,
09:55:22 up 1:40, 1 user, load average: 2.60, 1.97, 1.49
20
279
### 07:55:24 rollback (13 packages, simulated first)
0 upgraded, 0 newly installed, 13 downgraded, 0 to remove and 0 not upgraded.
0 upgraded, 0 newly installed, 13 downgraded, 0 to remove and 0 not upgraded.
audit rc=0
@@ -0,0 +1,5 @@
07:55:41.640 debug pass started
dpkg running at 07:56:02.802: 302936 /usr/bin/dpkg --force-confold --force-confdef --status-fd 24 --no-triggers --unpack --auto-deconfigure /var/cache
CRASH at 07:56:03.308
Timeout, server 192.168.0.104 not responding.
ssh ended 07:56:10
@@ -0,0 +1,25 @@
ssh back 07:56:56
09:56:56 up 0 min, 1 user, load average: 2.97, 0.65, 0.21
"armed": true,
"last_boot_at": "2026-10-05T07:56:41Z",
"last_boot_unclean": true,
"tripped": false,
"unclean_boots_in_window": 1,
kernel.panic = 10
--- dpkg at boot
audit rc=0
1
bind9-dnsutils 1:9.20.26-1~deb13u1 ii
bind9-host 1:9.20.26-1~deb13u1 ii
bind9-libs 1:9.20.26-1~deb13u1 ii
libpcre2-8-0 10.46-1~deb13u2 ii
libpython3.13-minimal 3.13.5-2+deb13u4 ii
libpython3.13-stdlib 3.13.5-2+deb13u4 ii
libssh2-1t64 1.11.1-1+deb13u1 ii
libssl3t64 3.5.7-1~deb13u2 ii
libxml2 2.12.7+dfsg+really2.9.14-2.1+deb13u1 ii
openssl 3.5.7-1~deb13u2 ii
openssl-provider-legacy 3.5.7-1~deb13u3 ii
python3.13 3.13.5-2+deb13u4 ii
python3.13-minimal 3.13.5-2+deb13u4 ii
08:00:01 apps: 20 of 21 healthy
@@ -0,0 +1,25 @@
### 08:00:01 the next pass — no person touched dpkg
=== felhom-agent 0.145.0 selftest=os-update vmid=9201 ring=0 enabled=true guest-release=false host-release=false appliance=true block=hub ===
"healthy": true,
"outcome": "applied",
"healthy": true,
"outcome": "nothing",
"healthy": true,
"outcome": "nothing",
pass took 1m20.7s
Oct 05 10:00:02 demo-hp felhom-os-apply[16364]: os-apply: START release=ring0-20261005T080001Z layer=guest:9201 lane=fast mode=apply select=pending-fast packages=0
Oct 05 10:00:13 demo-hp felhom-os-apply[16840]: os-apply: REPAIR configured=0 journal=1 fixed=0
Oct 05 10:00:19 demo-hp felhom-os-apply[17215]: os-apply: PLAN upgrade=12 already=0 not-installed=0 from-snapshot=0
Oct 05 10:00:34 demo-hp felhom-os-apply[18302]: os-apply: DONE rc=0 seconds=7.7 upgraded=12 restart-needed=cron,dbus-daemon,sshd,systemd,systemd-journal,systemd-logind,systemd-network reboot-needed=yes
Oct 05 10:00:43 demo-hp felhom-os-apply[18833]: os-apply: START release=ring0-20261005T080001Z layer=host lane=fast mode=apply select=pending-fast packages=0
Oct 05 10:00:47 demo-hp felhom-os-apply[19271]: os-apply: REPAIR configured=0 journal=0 fixed=0
Oct 05 10:00:51 demo-hp felhom-os-apply[19388]: os-apply: PLAN upgrade=0 already=0 not-installed=0 from-snapshot=0
Oct 05 10:00:51 demo-hp felhom-os-apply[19389]: os-apply: DONE rc=0 seconds=0 upgraded=0 (nothing to do)
Oct 05 10:01:04 demo-hp felhom-os-apply[20758]: os-apply: START release=ring0-20261005T080001Z layer=docker:9201 lane=slow mode=apply select=pending-docker packages=0 authority=ring0
Oct 05 10:01:09 demo-hp felhom-os-apply[20997]: os-apply: REPAIR configured=0 journal=0 fixed=0
Oct 05 10:01:14 demo-hp felhom-os-apply[21238]: os-apply: PLAN upgrade=0 already=0 not-installed=0 from-snapshot=0
Oct 05 10:01:14 demo-hp felhom-os-apply[21239]: os-apply: DONE rc=0 seconds=0 upgraded=0 (nothing to do)
audit rc=0
0
0
package list == before the rollback (279 lines)
@@ -0,0 +1,8 @@
--- hub events demo-hp since 07:55 UTC
('controller_started', 'info', 'Controller elindult (0.295.0)', 'controller', '2026-10-05 07:58:50')
('os_update_applied', 'info', 'System security fixes installed on the box (12 package(s)).', 'hub', '2026-10-05 08:00:42')
--- notification_log since 07:55 UTC (all customers)
--- os_reports demo-hp newest 3
(73, '2026-10-05 08:01:22', 'debug', 'nothing', 1, 'docker')
(72, '2026-10-05 08:01:00', 'debug', 'nothing', 1, 'host')
(71, '2026-10-05 08:00:42', 'debug', 'applied', 1, 'guest')
@@ -0,0 +1,17 @@
### RED-PROOF R-876a: the journal does not count (v0.144.1)
FAIL: test_the_next_pass_repairs_by_itself_and_finishes (test_felhom_os_apply.CrashLeftTheJournal.test_the_next_pass_repairs_by_itself_and_finishes)
AssertionError: 18 not less than 16 : the repair must run before the install
Ran 3 tests in 0.032s
FAILED (failures=1)
### RED-PROOF R-876b: no repair+retry when apt says interrupted
FAIL: test_apt_interrupted_is_repaired_and_retried_once (test_felhom_os_apply.CrashLeftTheJournal.test_apt_interrupted_is_repaired_and_retried_once)
AssertionError: 3 != 0 : {'failed': {'dpkg_audit': 'clean', 'rc': 100, 'tail': ["E: dpkg was interrupted, you must manually run 'sudo dpkg --configure -a' to correct the problem."]}, 'health_before': {'containers': {'app': {'health': 'healthy', 'id': 'bbb222', 'state': 'running'}, 'felhom-controller': {'health': 'healthy', 'id': 'aaa111', 'state': 'running'}}, 'controller': 'healthy', 'controller_docker_ok': True, 'docker_ok': True, 'network_ok': True}, 'layer': 'guest', 'mode': 'apply', 'pass_seconds': 0.0, 'plan': {'already': 0, 'from_snapshot': 0, 'not_installed': 0, 'upgrade': 2}, 'refused': None, 'release_id': 'os-t1', 'repair': {'clean_after': True, 'fixed': 0, 'half_configured_before': 0, 'journal_before': 0}, 'vmid': 9201}
Ran 3 tests in 0.026s
FAILED (failures=1)
### RED-PROOF R-876c: repair always runs (R-845 speed lost)
FAIL: test_a_clean_pass_still_costs_one_state_call (test_felhom_os_apply.CrashLeftTheJournal.test_a_clean_pass_still_costs_one_state_call)
AssertionError: 2 != 1 : R-845: a clean pass reads dpkg's state ONCE and runs no repair
Ran 3 tests in 0.035s
FAILED (failures=1)
### restored
OK
@@ -0,0 +1,3 @@
artifacts POST HTTP 303
Location: /configuration?flash=artifacts_set
2026/10/05 09:48:14 [INFO] Artifact manifest set: agent=0.145.0 golden=0.295.0 min_agent="0.131.0" wrapper_sha=false bundle_sha="78c00adce662d2d966b2ac50ebde46cde1ae225f0107c6a7c02b70ec8ce80c4f"
@@ -0,0 +1,3 @@
### 07:31:06 found: VM 341 (Tester 1) stopped since the 06:14 UTC demo-hp crash (no onboot)
status: running
onboot: 1