night 2026-09-25: DRILL record, Part D real night, STATUS morning note, register 341 -> 338
gates / gates (push) Successful in 27s
gates / gates (push) Successful in 27s
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:
@@ -1256,6 +1256,8 @@ product's own form (`POST /backups/window` — measured: the three legs reschedu
|
||||
(c) the gate interlock is `quiesce.Options.UpdateLegFn` with decision 31's in-flight grace; (d) the switch is
|
||||
`settings.json` `app_update.unattended`, absent = ON, a card on the settings page; `stacks.update_window` removed;
|
||||
(e) the live proof: `audits/DRILL-night-2026-09-25.md` Part C (four nights on 9202) and Part D (the demo boxes).
|
||||
**The demo boxes' first real automatic night (2026-09-25):** demo-felhom's leg ran at 04:15:46 after the off-site
|
||||
copy and took opengist 1.13 → 1.15 in 20 s; demo-hp's found nothing to take. Both summaries reached the hub.
|
||||
**Found live, not in the brief:** the leg presses the next app in the same second the previous step ends, so "a
|
||||
controller killed BETWEEN two apps" lands inside the next step's early phases — which the guarded update puts back
|
||||
(Scenario G); the rest of the night is lost (R-686).
|
||||
|
||||
@@ -0,0 +1,193 @@
|
||||
# DRILL — night 2026-09-25: the fixed agent delivered, the HP box backs up again, automatic updates built, proven, and watched through the demo boxes' first real night
|
||||
|
||||
Brief: "NIGHT SHIFT 2026-09-24/25". Architecture read before any claim: `09-update-architecture.md` §3 decisions
|
||||
11–30 and §6.4.2 (the spec for Part B), `03-host-agent.md`, `07-backup-architecture.md`, `08-alarm-ladder.md`,
|
||||
`04-control-plane-authorization.md` §2–§3.1. Evidence: `audits/night-2026-09-25/` (A, B, C, D, E, F, G, tools).
|
||||
|
||||
## Not done, or changed
|
||||
|
||||
- **An unplanned whole-box backup of demo-hp 9201 ran for 5 min 16 s (22:40:21–22:45:37 CEST) and was aborted by
|
||||
me.** It came from my own live test of agent v0.134.0 (R-685), which was meant to prove a REFUSAL: the first build
|
||||
read free space from `GET /storage`, which carries no usage, so the check failed open and a real vzdump started.
|
||||
I stopped the task; vzdump removed its temporary files; no archive, no lock; root disk back to 60 %; the guest was
|
||||
suspended 2 s (snapshot mode), its apps kept running. This breached the brief's fence "no whole-box backup on a
|
||||
demo box except Part A4". Fixed before release (free space from `GET /nodes/<node>/storage`), red-proofed twice,
|
||||
and re-proven with safe builds that stop before any vzdump (`F/F1-*`, `F/F2-*`).
|
||||
- **The floor was raised at 22:59 CEST, not "around 02:00".** Part C had passed; raising early gave 3.5 hours to
|
||||
see both boxes arrive and read their switch and window before the night. Both arrived in ~15 s.
|
||||
- **Part F ran BEFORE Part D, and its controller half is not done.** Agent v0.134.0 (the space check) was released,
|
||||
signed and delivered to both demo boxes (Part F's live proof passed). The controller's backup-page line for a space
|
||||
skip needs a controller release, and v0.271.0 was already the night's one — R-685 stays open for that half.
|
||||
**R-671, R-670, R-677 were not started** — each needs a controller release (one per repo per night).
|
||||
- **Both agent_update jobs of 0.134.0 were queued within a minute**, not one box after the other's commit (each is
|
||||
per-box by signature; the 0.132.0 delivery did the same). 0.133.0 went strictly one after the other.
|
||||
- **Part C's accidents: two ran live, two could not** on a scratch box without an off-site tier and an agent — the
|
||||
off-site leg FAILING and W+5h reached with steps left are unit-proven only (R-687). "The controller killed BETWEEN
|
||||
two apps" landed INSIDE the next app's step: the leg presses the next app in the same second (see Part C).
|
||||
- **Part D: no whole-box backup followed the leg tonight, so the backup gate never had to wait.** demo-hp's last
|
||||
whole-box backup was Part A4's (21:59), so it is not due until this evening; demo-felhom's is due ~07:27, after the
|
||||
session. Both legs ended by 04:19, before the gate opened at 04:30. The gate's wait is unit-proven and red-proofed
|
||||
only (R-687 updated).
|
||||
- **One step per app per night** (decision 33) follows the brief's own words; §6.4.2 (a)'s "rescan between steps"
|
||||
read as climbing several — recorded as a decision the operator may widen.
|
||||
|
||||
**Interventions: 0** on product behaviour during the real night (nothing was touched on the demo boxes between the
|
||||
floor raise and the end of the night except to read). **The demo boxes' real night: demo-felhom 1 step done
|
||||
(opengist 1.13 → 1.15, 20 s), demo-hp nothing to do (every app current); 0 undone, 0 held, 0 skipped.** **The one
|
||||
result that matters most:** the automatic leg ran unattended on both demo boxes exactly where the chain puts it —
|
||||
after the off-site copy — pressed only the one tested step waiting, and reported itself to the hub.
|
||||
|
||||
|
||||
## Part B — controller v0.271.0 (`9cf13a3`, CI job 974 success)
|
||||
|
||||
Built exactly §6.4.2 point 6 (a)–(d) plus R-680, R-678, decision 13's marks, the older-than-ladder rule, the switch
|
||||
and the events rule. As built: `stacks/unattended.go` (`RunUpdateLeg`), `chainUpdateLeg` in `cmd/controller/main.go`
|
||||
(the `offbox-backup` job), `quiesce.Options.UpdateLegFn`, `backupwindow.UpdateLegStopOffsetMin`, `settings.json`
|
||||
`app_update.unattended` (absent = ON) with its card on /settings, app.yaml `failed_update_step` and
|
||||
`last_auto_update`, the report's `update_leg`, `backup.FreshWholeCopy`; `stacks.update_window` removed. Decisions
|
||||
31–33 taken unattended (`09` §3). **Red-proofs — 11, each seen failing, tree restored after each**
|
||||
(`night-2026-09-25/B/redproofs/`): the leg on every off-site path (a deferred call: error and panic cases fail without
|
||||
it); the gate deferring while the leg runs and not at W+5h; the leg starting nothing at W+5h; one step per app a
|
||||
night; the failed step skipped; `needs_person` skipped; `files_may_change` without a whole copy skipped; no crash-loop
|
||||
verdict during a step (the first version of this test passed under the mutation — its container was set before the
|
||||
leg's rescan rebuilt the stack; fixed and re-seen red); the steps-left count fresh at `done`; the switch ON by
|
||||
default; the leg wired at startup. Gates green; one parity snapshot regenerated for the new card (diff: additions only).
|
||||
|
||||
## Part A — the agent, the restore test, the HP backup
|
||||
|
||||
**A1 — agent v0.133.0 signed and delivered, one box after the other** (ruling 1, 2026-09-16). Package sha256
|
||||
`3aa30345…e69b6` verified against the published package before signing (`A/A1-*.txt`).
|
||||
|
||||
| box | signed (UTC) | box took it | AUTHORIZED → COMPLETED | committed | hub reads |
|
||||
|---|---|---|---|---|---|
|
||||
| demo-felhom-8363b5 | 19:25:30 | 21:34:05 CEST | job `c4b592ff7c9ff307` | 21:35:09 | 0.133.0 |
|
||||
| demo-hp-bb76ea | 19:35:55 | 21:48:58 CEST | job `36aab1ed8ad00979` | 21:50:02 | 0.133.0 |
|
||||
|
||||
Peti's box: never signed for.
|
||||
|
||||
**A2 — the restore test back on, both boxes.** `agent.json.pre-r672` copied back; the diff was only
|
||||
`restore_test_eval_interval_seconds: -1` (and the trailing newline). The `-1` config is kept as
|
||||
`agent.json.night-0925-off`. Start-up line on both: `restore-test scheduler starting (per-archive due-check)
|
||||
eval_interval=6h0m0s settle=24h0m0s`.
|
||||
|
||||
**A3 — one on-demand restore test.** demo-felhom: **PASS** — scratch 990000 restored, booted, verified,
|
||||
torn down in 1 min 25 s; pool 3.13 % → peak 5.68 % → 3.13 %; preflight "required 12.8 GB, avail 362.8 GB".
|
||||
demo-hp: **REFUSED, correctly** — "restoring 21.1 GiB (vzdump log: total bytes written) needs 30.3 GiB free, has
|
||||
22.1 GiB", exit 4, pool 59.01 % before and after, nothing created.
|
||||
|
||||
**A4 — HP whole-box backups, option A.** Before: root disk (`local`) 89 % used, 4.3 GB free, three 9201 archives
|
||||
(6.2, 6.3, 7.4 GB), retention 3. Changed: `local_backup_retention` 3 → 1 (saved copy
|
||||
`agent.json.pre-a4-retention`), agent restarted, the two oldest archives removed with PVE's own
|
||||
`pvesm prune-backups local --vmid 9201 --keep-last 1` (dry-run shown first) → 58 % used, 16.8 GB free. **Why the
|
||||
prune by hand:** PVE prunes AFTER a successful backup, so lowering the retention alone would not have let the next
|
||||
backup fit. One whole-box backup by the product's own button (`POST /api/guest-backup/trigger`, the Mentések
|
||||
page) — 9201's apps were stopped for it (snapshot mode, resumed at "snapshotted"): local archive **8.18 GB** in
|
||||
7 min, then the PBS tier (the button covers every tier) 23.2 GB in 4.5 min; the new prune kept 1 archive; root
|
||||
60 %; all 20 app containers healthy. The product row is **R-685**.
|
||||
## Part C — the proof on 9202: six simulated nights
|
||||
|
||||
Controller v0.271.0 on 9202 only (`C/C0-deploy-9202.txt`), drill catalog (`C/C0-repoint-drill.txt`, health timeout
|
||||
90 s). Four apps installed through the product at the ladder's first `from`, then the drill put back at the head:
|
||||
wishlist 1 step behind, navidrome 2, romm 3, vikunja 1 with a failing step (its head probe on port 8999). Marks
|
||||
set in the drill: navidrome step 1 `needs_person`, wishlist's step `files_may_change`. Data seeded through each
|
||||
app's own front door and read back after EVERY night (`C/data-readback.txt`: 8 of 8 rounds, 4 of 4 apps, each
|
||||
fixture with its negative control). The window was moved through the product's own form (`POST /backups/window`)
|
||||
so the off-site job — and the leg chained to it — fired two minutes later.
|
||||
|
||||
| night | what it proved | leg summary (the box's own line) | pages (hu + en) |
|
||||
|---|---|---|---|
|
||||
| 1 | the chain on a box with NO off-site target ("the off-site leg does nothing; the update leg runs now"); one step per app; `needs_person` skipped; `files_may_change` taken WITH a whole copy (wishlist); a failing step undone | `done=2 undone=1 held=0 failed=0 skipped=1 in 3m6s [skipped: navidrome=needs_person]` — romm 60.1 s, vikunja undone 105.2 s, wishlist 20.1 s | „Automatikus frissítés 2026-09-24 22:31-kor — sikeres." / "Automatic update at … — done."; vikunja's undone sentence in both |
|
||||
| 2 | R-680 live: the undone step is NOT pressed again; navidrome's `files_may_change` step taken (its music folder is `excluded`, so its own unit is whole) | `done=2 undone=0 … skipped=1 in 1m10s [skipped: vikunja=failed_before]` | badges current / behind as expected |
|
||||
| 3 — accident | controller killed (kill -9) the moment navidrome's step ended | the leg had pressed romm IN THE SAME SECOND; the kill landed before romm's `up` → pin and definition put back, romm runs its previous version, page: „A frissítés megszakadt, mert a vezérlő újraindult…" / "The update was interrupted…"; the leg was not resumed (R-686) | all data read back |
|
||||
| 4 — accident | power cut (`pct stop`/`pct start` of 9202) while romm's step was `verifying` | box up in 13 s; "resumed 1 interrupted update(s)"; romm healthy after 30 s, DONE in 1 m 32 s; no automatic-update line on the page (the leg died — R-686) | all data read back |
|
||||
| 5 | the switch OFF (`POST /settings/app-update`, page reads unchecked) | `done=0 … stopped=switched_off in 0s` — nothing pressed | — |
|
||||
| 6 | the switch ON again; the catalog RE-TESTED vikunja's step (probe fixed, new `tested_at`) → the ladder print changed → R-680's record no longer binds | `done=1 … in 10s` — vikunja done | „Automatikus frissítés … 22:58-kor — sikeres." |
|
||||
|
||||
**Not run live, and why (R-687):** W+5h reached with steps left (the leg starts at W+105m; needs a 3-hour leg — unit
|
||||
test `TestLeg_NoStepAtOrAfterW5h`); the off-site leg FAILING (9202 has no off-site tier — unit test
|
||||
`TestChainUpdateLeg_EveryPath` covers error and panic); a `files_may_change` step WITHOUT a whole copy (every app
|
||||
given the mark was whole on 9202); the full-system gate's deferral (9202 has no agent, so no quiesce loop).
|
||||
|
||||
**Verdict: Part C passed** — every accident that could run on 9202 ended with the app healthy, the data read back,
|
||||
and a true sentence on its page; the four not-runnable cases are named, unit-proven and in the register.
|
||||
|
||||
## Part D — the demo boxes' first real automatic night
|
||||
|
||||
Floor 0.271.0 (declared MinAgent 0.131.0) saved 20:59:04Z, read back; both boxes on 0.271.0 ~15 s later
|
||||
(`D/D1`, `D/D2`). Before the night, per box (`D/D3`, `D/D0`): switch ON (key absent = the default; demo-hp's
|
||||
settings page reads it checked in both languages), window 02:30 (off-site + update leg at 04:15, gate [04:30, 08:30)).
|
||||
Tested steps waiting: **demo-felhom — opengist 1.13 → 1.15; demo-hp — none** (all 10 apps at the catalog head).
|
||||
Agents: 0.134.0 on both (Part F). Nothing was touched on either box during the night except to read.
|
||||
|
||||
**demo-felhom (N100), leg by leg** (`D/D6-demo-felhom-night-full.log`): db-dump 02:30:00 (0.8 s) → Tier 2 03:30:00
|
||||
→ off-site 04:15:00–04:15:46 (1 app, 11 snapshots, 42 s) → **update leg 04:15:46–04:16:06: opengist pressed; safety
|
||||
dump, undo copy (0.2 MiB), pin, pull, start, verify healthy after 10 s, DONE in 17 s; `done=1 undone=0 held=0 failed=0
|
||||
skipped=0 in 20s`**. After: container `opengist:1.15` healthy; app.yaml `last_auto_update: done 1.13 → 1.15` (the page
|
||||
line). One WARN worth keeping: the volume "carries no compose label (recreated by a restore before v0.268.0 — R-658)
|
||||
— copied by name" — the R-658 fallback working. No mail (a successful step sends none).
|
||||
|
||||
**demo-hp** (`D/D6-demo-hp-night-full.log`): db-dump 02:30:00–02:31:59 → Tier 2 03:30:00–03:30:24 → off-site
|
||||
04:15:00–04:18:41 (9 apps, 90 snapshots, 3 min 35 s, OK) → **update leg 04:18:41: nothing to press, `done=0 … in
|
||||
0s`**.
|
||||
|
||||
**The hub** holds both summaries in its stored reports (received 02:44Z; `D/D7-hub-report-update-leg.txt`, read from a
|
||||
copy of the hub DB taken with its -wal, then deleted). **Whole-box backups:** none ran tonight on either box — not
|
||||
due (see "Not done"); both agents alive (627 / 1,069 journal lines since 02:25, the 10-minute janitor on schedule).
|
||||
**No app ended held or stopped.**
|
||||
|
||||
## Part E — two apps moved
|
||||
|
||||
Venue: bench LXC **9401** on demo-hp (created and destroyed tonight — no permission check refused either; the
|
||||
Debian template it needed was removed again), harness v3; box walk on 9202 through the real guarded Update.
|
||||
**Negative control: `n8n=alpine:3.20` → `failed`.** A bench setup miss is recorded: the first queue ran without
|
||||
the `traefik-public` network and returned `inconclusive — FROM deploy failed` (kept as `*-noNetwork`); re-run.
|
||||
|
||||
| app | step | bench | box | memory peak (own) | catalog commit (CI) |
|
||||
|---|---|---|---|---|---|
|
||||
| n8n | 2.41.1 → 2.41.2 | proven | proven | 22.4 % | `f14a608` (job 980) |
|
||||
| mealie | v3.27.0 → v3.28.0 | proven | proven | 23.1 % | `b996218` (job 981) |
|
||||
|
||||
Published at 02:31–02:32, after the demo boxes' night began and on neither box's app list. Not moved, with the
|
||||
reason for each: catalog `REPORT.md` (drift `E/E0-drift.log`).
|
||||
|
||||
## Part F — agent v0.134.0 (R-685 agent half)
|
||||
|
||||
Released by `scripts/release-agent.sh` (tag `v0.134.0` at `0722b2c`, sha256 `7593bebe…81c72d`, verified by download;
|
||||
CI jobs 975–977). A vzdump to a local target needs free ≥ newest archive × 1.25 + 1 GiB; a shortfall is a named skip
|
||||
before anything starts; fail-open on PBS / first backup / unknown usage. Live, safe builds (a hard stop before vzdump):
|
||||
×10 → "local has 14.9 GiB free; … needs about 77.2 GiB" refused; ×1.25 → "space preflight passed" need 11.3 GB,
|
||||
avail 16.0 GB. Signed to both demo boxes (`F/F3-*`): demo-felhom committed 22:52:45, demo-hp 22:58:53; hub reads 0.134.0.
|
||||
The incident above belongs to this part.
|
||||
|
||||
## Teardown — three layers
|
||||
|
||||
- **Machine:** 9202 back on the live catalog (`catalog-cache` at `c802509` at the time; the controller follows `main`),
|
||||
window 02:30 again, the six drill apps removed through the product (0 containers, 0 volumes, 0 undo copies); left by
|
||||
name on the scratch drive: `userdata/navidrome`, `userdata/romm` (the remove kept drive data — R-442's fail-closed
|
||||
path on 9202). The switch key on 9202 is now explicit `true` (was absent = ON). 9202 stays on controller 0.271.0 (the
|
||||
floor). Bench 9401 destroyed (hostname checked first), template removed.
|
||||
- **Host:** demo-hp `pct list` 9201 + 9202, local-lvm 60.05 %, root 60 %; demo-felhom 9201 only, local-lvm 3.16 %.
|
||||
Config changes kept on purpose: restore test ON (both), `local_backup_retention: 1` (demo-hp). No test binaries left
|
||||
in /tmp.
|
||||
- **Hub:** global floor 0.271.0 (MinAgent 0.131.0); both demo boxes 0.271.0 / agent 0.134.0. Drill repo reset to live
|
||||
`main` (`dd9c6ad`), private, Actions off.
|
||||
|
||||
## Claims in the brief that turned out wrong (or right)
|
||||
|
||||
1. *The off-site job function is the single place the leg can be chained from on every path* — **TRUE for every path
|
||||
of the job, with one exception outside it:** a box with backups disabled registers no off-site job at all, so no
|
||||
leg (the update itself would refuse `no_backup` there anyway). The job's own early returns and the scheduler's "not
|
||||
configured" skip all return into `chainUpdateLeg`. A controller restart after the job fired loses the rest of the
|
||||
night (R-686).
|
||||
2. *A demo box has a tested step waiting tonight* — **TRUE for demo-felhom (opengist), FALSE for demo-hp.**
|
||||
3. *The whole-box backup lands on demo-hp's root disk* — **TRUE** (`local` = `/var/lib/vz`, root LV).
|
||||
4. *Decision 28's suppressions cover a deploy's first start* — **WRONG.** `Deploying` clears when `compose up -d`
|
||||
returns; a first start that restarts ≥ 6 times in 10 min is stopped (R-676 updated). An automatic step, its verify
|
||||
and its undo ARE covered (pinned by a test).
|
||||
|
||||
## Register
|
||||
|
||||
Before: **341 rows / 685,148 B**. After: **338 rows / 682,053 B**. Opened R-685 (backup-fit warning; agent half
|
||||
shipped, controller page half open), R-686 (no resume of the leg after a restart), R-687 (live-proof gaps). Closed
|
||||
R-672, R-673 (delivered), R-684 (option A), R-680, R-678, R-643. Updated R-676 (deploy first start), R-450 (narrowed
|
||||
to part 10).
|
||||
@@ -0,0 +1,28 @@
|
||||
2026/09/25 02:15:00 [INFO] [scheduler] Running job: offbox-backup
|
||||
2026/09/25 02:15:00 [INFO] [offbox] backup run started (1 app(s) toggled)
|
||||
2026/09/25 02:15:00 [INFO] [offbox] pre-push dump leg completed in 795ms — snapshot pair is coherent
|
||||
2026/09/25 02:15:08 [INFO] [offbox] backed up opengist (/mnt/sys_drive/felhom-data/backups/primary/opengist, 0 mandatory path(s))
|
||||
2026/09/25 02:15:46 [INFO] [offbox] backup OK: 1 app(s) backed up, 11 snapshot(s), 42s
|
||||
2026/09/25 02:15:46 [INFO] [update-leg] started (after-offsite): window 02:30, no step starts at or after 07:30
|
||||
2026/09/25 02:15:46 [INFO] [stacks] update opengist: accepted — guarded update started
|
||||
2026/09/25 02:15:46 [INFO] [update-leg] opengist: step pressed opengist=ghcr.io/thomiceli/opengist:1.13 → opengist=ghcr.io/thomiceli/opengist:1.15
|
||||
2026/09/25 02:15:46 [INFO] [stacks] update opengist: phase checking
|
||||
2026/09/25 02:15:46 [INFO] [stacks] update opengist: ladder — the last step (1 of 1) — the catalog's current definition
|
||||
2026/09/25 02:15:46 [INFO] [stacks] update opengist: precondition met — Tier 1 (own recovery unit) copy from 2026-09-25T02:15:00Z (1m0s old, limit 24h0m0s)
|
||||
2026/09/25 02:15:46 [INFO] [stacks] update opengist: phase safety-dump
|
||||
2026/09/25 02:15:46 [INFO] [stacks] update opengist: safety dump done (0 file(s)) []
|
||||
2026/09/25 02:15:47 [WARN] [stacks] update opengist: volume(s) [opengist_opengist_data] carry no compose label (recreated by a restore before v0.268.0 — R-658) — copied by name
|
||||
2026/09/25 02:15:47 [INFO] [stacks] update opengist: the undo copy will hold 1 named volume(s), 0.2 MiB
|
||||
2026/09/25 02:15:47 [INFO] [stacks] update opengist: phase pinning
|
||||
2026/09/25 02:15:47 [INFO] [stacks] update opengist: pin advanced to /opt/docker/felhom-controller/data/catalog-cache/templates/opengist/docker-compose.yml (opengist=ghcr.io/thomiceli/opengist:1.15)
|
||||
2026/09/25 02:15:47 [INFO] [stacks] update opengist: phase pulling
|
||||
2026/09/25 02:15:53 [INFO] [stacks] update opengist: phase copying
|
||||
2026/09/25 02:15:53 [INFO] [stacks] update opengist: phase copying
|
||||
2026/09/25 02:15:53 [INFO] [stacks] update opengist: copied opengist_opengist_data → opengist_opengist_data.pre-update-20260925T021553Z in 293ms
|
||||
2026/09/25 02:15:53 [INFO] [stacks] update opengist: phase starting
|
||||
2026/09/25 02:15:54 [INFO] [stacks] update opengist: phase verifying
|
||||
2026/09/25 02:16:04 [INFO] [stacks] update opengist: healthy after 10s (the app's health check passed)
|
||||
2026/09/25 02:16:04 [INFO] [stacks] update opengist: DONE in 17s
|
||||
2026/09/25 02:16:06 [INFO] [update-leg] opengist: step ended done after 20.1 s
|
||||
2026/09/25 02:16:06 [INFO] [update-leg] update leg (after-offsite): done=1 undone=0 held=0 failed=0 skipped=0 in 20s [skipped: ]
|
||||
2026/09/25 02:16:06 [INFO] [scheduler] Job offbox-backup completed (took 1m6.957s)
|
||||
@@ -0,0 +1,16 @@
|
||||
2026/09/25 02:15:00 scheduler.go:346: [INFO] [scheduler] Running job: offbox-backup
|
||||
2026/09/25 02:15:00 offbox.go:922: [INFO] [offbox] backup run started (9 app(s) toggled)
|
||||
2026/09/25 02:16:54 offbox.go:969: [INFO] [offbox] pre-push dump leg completed in 1m54.507s — snapshot pair is coherent
|
||||
2026/09/25 02:17:12 offbox.go:1388: [INFO] [offbox] backed up kimai (/mnt/sys_drive/felhom-data/backups/primary/kimai, 0 mandatory path(s))
|
||||
2026/09/25 02:17:15 offbox.go:1388: [INFO] [offbox] backed up opengist (/mnt/sys_drive/felhom-data/backups/primary/opengist, 0 mandatory path(s))
|
||||
2026/09/25 02:17:26 offbox.go:1388: [INFO] [offbox] backed up paperless-ngx (/mnt/felhom-drives/hdd_1/backups/primary/paperless-ngx, 1 mandatory path(s))
|
||||
2026/09/25 02:17:35 offbox.go:1388: [INFO] [offbox] backed up romm (/mnt/felhom-drives/hdd_1/backups/primary/romm, 0 mandatory path(s))
|
||||
2026/09/25 02:17:39 offbox.go:1385: [WARN] [offbox] backed up bentopdf (/mnt/sys_drive/felhom-data/backups/primary/bentopdf, 0 mandatory path(s)) — but the recovery unit carried NO database dump and NO volume tar, so this snapshot holds none of the app's data; the next run with a dump leg will replace it
|
||||
2026/09/25 02:17:45 offbox.go:1388: [INFO] [offbox] backed up bookstack (/mnt/sys_drive/felhom-data/backups/primary/bookstack, 0 mandatory path(s))
|
||||
2026/09/25 02:17:50 offbox.go:1388: [INFO] [offbox] backed up calibre-web (/mnt/felhom-drives/hdd_1/backups/primary/calibre-web, 1 mandatory path(s))
|
||||
2026/09/25 02:17:54 offbox.go:1388: [INFO] [offbox] backed up privatebin (/mnt/sys_drive/felhom-data/backups/primary/privatebin, 0 mandatory path(s))
|
||||
2026/09/25 02:18:00 offbox.go:1388: [INFO] [offbox] backed up docmost (/mnt/sys_drive/felhom-data/backups/primary/docmost, 0 mandatory path(s))
|
||||
2026/09/25 02:18:41 offbox.go:1158: [INFO] [offbox] backup OK: 9 app(s) backed up, 90 snapshot(s), 3m35s
|
||||
2026/09/25 02:18:41 unattended.go:254: [INFO] [update-leg] started (after-offsite): window 02:30, no step starts at or after 07:30
|
||||
2026/09/25 02:18:41 unattended.go:235: [INFO] [update-leg] update leg (after-offsite): done=0 undone=0 held=0 failed=0 skipped=0 in 0s [skipped: ]
|
||||
2026/09/25 02:18:41 scheduler.go:363: [INFO] [scheduler] Job offbox-backup completed (took 3m41.126s)
|
||||
@@ -0,0 +1,14 @@
|
||||
ghcr.io/thomiceli/opengist:1.15 Up 4 minutes (healthy)
|
||||
last_auto_update:
|
||||
2026/09/25 02:15:00 [INFO] [scheduler] Running job: offbox-backup
|
||||
2026/09/25 02:15:00 [INFO] [offbox] backup run started (1 app(s) toggled)
|
||||
2026/09/25 02:15:00 [INFO] [offbox] pre-push dump leg completed in 795ms — snapshot pair is coherent
|
||||
2026/09/25 02:15:08 [INFO] [offbox] backed up opengist (/mnt/sys_drive/felhom-data/backups/primary/opengist, 0 mandatory path(s))
|
||||
2026/09/25 02:15:46 [INFO] [offbox] backup OK: 1 app(s) backed up, 11 snapshot(s), 42s
|
||||
last_auto_update:
|
||||
at: "2026-09-25T02:15:46Z"
|
||||
outcome: done
|
||||
from:
|
||||
opengist: ghcr.io/thomiceli/opengist:1.13
|
||||
to:
|
||||
opengist: ghcr.io/thomiceli/opengist:1.15
|
||||
@@ -0,0 +1,30 @@
|
||||
2026/09/25 00:30:00 [INFO] [scheduler] Running job: db-dump
|
||||
2026/09/25 00:30:00 [INFO] [scheduler] Job db-dump completed (took 804ms)
|
||||
2026/09/25 01:30:00 [INFO] [scheduler] Running job: tier2-backup
|
||||
2026/09/25 01:30:00 [INFO] [scheduler] Job tier2-backup completed (took 5ms)
|
||||
2026/09/25 02:15:00 [INFO] [scheduler] Running job: offbox-backup
|
||||
2026/09/25 02:15:00 [INFO] [offbox] backup run started (1 app(s) toggled)
|
||||
2026/09/25 02:15:46 [INFO] [offbox] backup OK: 1 app(s) backed up, 11 snapshot(s), 42s
|
||||
2026/09/25 02:15:46 [INFO] [update-leg] started (after-offsite): window 02:30, no step starts at or after 07:30
|
||||
2026/09/25 02:15:46 [INFO] [stacks] update opengist: accepted — guarded update started
|
||||
2026/09/25 02:15:46 [INFO] [update-leg] opengist: step pressed opengist=ghcr.io/thomiceli/opengist:1.13 → opengist=ghcr.io/thomiceli/opengist:1.15
|
||||
2026/09/25 02:15:46 [INFO] [stacks] update opengist: phase checking
|
||||
2026/09/25 02:15:46 [INFO] [stacks] update opengist: ladder — the last step (1 of 1) — the catalog's current definition
|
||||
2026/09/25 02:15:46 [INFO] [stacks] update opengist: precondition met — Tier 1 (own recovery unit) copy from 2026-09-25T02:15:00Z (1m0s old, limit 24h0m0s)
|
||||
2026/09/25 02:15:46 [INFO] [stacks] update opengist: phase safety-dump
|
||||
2026/09/25 02:15:46 [INFO] [stacks] update opengist: safety dump done (0 file(s)) []
|
||||
2026/09/25 02:15:47 [WARN] [stacks] update opengist: volume(s) [opengist_opengist_data] carry no compose label (recreated by a restore before v0.268.0 — R-658) — copied by name
|
||||
2026/09/25 02:15:47 [INFO] [stacks] update opengist: the undo copy will hold 1 named volume(s), 0.2 MiB
|
||||
2026/09/25 02:15:47 [INFO] [stacks] update opengist: phase pinning
|
||||
2026/09/25 02:15:47 [INFO] [stacks] update opengist: pin advanced to /opt/docker/felhom-controller/data/catalog-cache/templates/opengist/docker-compose.yml (opengist=ghcr.io/thomiceli/opengist:1.15)
|
||||
2026/09/25 02:15:47 [INFO] [stacks] update opengist: phase pulling
|
||||
2026/09/25 02:15:53 [INFO] [stacks] update opengist: phase copying
|
||||
2026/09/25 02:15:53 [INFO] [stacks] update opengist: phase copying
|
||||
2026/09/25 02:15:53 [INFO] [stacks] update opengist: copied opengist_opengist_data → opengist_opengist_data.pre-update-20260925T021553Z in 293ms
|
||||
2026/09/25 02:15:53 [INFO] [stacks] update opengist: phase starting
|
||||
2026/09/25 02:15:54 [INFO] [stacks] update opengist: phase verifying
|
||||
2026/09/25 02:16:04 [INFO] [stacks] update opengist: healthy after 10s (the app's health check passed)
|
||||
2026/09/25 02:16:04 [INFO] [stacks] update opengist: DONE in 17s
|
||||
2026/09/25 02:16:06 [INFO] [update-leg] opengist: step ended done after 20.1 s
|
||||
2026/09/25 02:16:06 [INFO] [update-leg] update leg (after-offsite): done=1 undone=0 held=0 failed=0 skipped=0 in 20s [skipped: ]
|
||||
2026/09/25 02:16:06 [INFO] [scheduler] Job offbox-backup completed (took 1m6.957s)
|
||||
@@ -0,0 +1,10 @@
|
||||
2026/09/25 00:30:00 scheduler.go:346: [INFO] [scheduler] Running job: db-dump
|
||||
2026/09/25 00:31:59 scheduler.go:363: [INFO] [scheduler] Job db-dump completed (took 1m59.507s)
|
||||
2026/09/25 01:30:00 scheduler.go:346: [INFO] [scheduler] Running job: tier2-backup
|
||||
2026/09/25 01:30:24 scheduler.go:363: [INFO] [scheduler] Job tier2-backup completed (took 24.096s)
|
||||
2026/09/25 02:15:00 scheduler.go:346: [INFO] [scheduler] Running job: offbox-backup
|
||||
2026/09/25 02:15:00 offbox.go:922: [INFO] [offbox] backup run started (9 app(s) toggled)
|
||||
2026/09/25 02:18:41 offbox.go:1158: [INFO] [offbox] backup OK: 9 app(s) backed up, 90 snapshot(s), 3m35s
|
||||
2026/09/25 02:18:41 unattended.go:254: [INFO] [update-leg] started (after-offsite): window 02:30, no step starts at or after 07:30
|
||||
2026/09/25 02:18:41 unattended.go:235: [INFO] [update-leg] update leg (after-offsite): done=0 undone=0 held=0 failed=0 skipped=0 in 0s [skipped: ]
|
||||
2026/09/25 02:18:41 scheduler.go:363: [INFO] [scheduler] Job offbox-backup completed (took 3m41.126s)
|
||||
@@ -0,0 +1,2 @@
|
||||
demo-felhom report received 2026-09-25 02:44:15 UTC; update_leg = {"trigger": "after-offsite", "started_at": "2026-09-25T02:15:46.825918487Z", "ended_at": "2026-09-25T02:16:06.961273956Z", "deadline": "2026-09-25T07:30:00+02:00", "enabled": true, "done": 1, "undone": 0, "held": 0, "failed": 0, "skipped": 0, "steps": [{"app": "opengist", "outcome": "done", "from": {"opengist": "ghcr.io/thomiceli/opengist:1.13"}, "to": {"opengist": "ghcr.io/thomiceli/opengist:1.15"}, "seconds": 20.1}]}
|
||||
demo-hp report received 2026-09-25 02:44:17 UTC; update_leg = {"trigger": "after-offsite", "started_at": "2026-09-25T02:18:41.05475777Z", "ended_at": "2026-09-25T02:18:41.126639901Z", "deadline": "2026-09-25T07:30:00+02:00", "enabled": true, "done": 0, "undone": 0, "held": 0, "failed": 0, "skipped": 0, "steps": null}
|
||||
@@ -1,2 +1,4 @@
|
||||
drill=c8025093d23c live=c8025093d23c — 2026-09-24T21:50:07+00:00
|
||||
has_actions: False private: True
|
||||
drill=b99621897639 live=b99621897639 — 2026-09-25T00:32:29+00:00 (after the Part E moves)
|
||||
drill=dd9c6ad57b07 live=dd9c6ad57b07 — 2026-09-25T00:32:50+00:00 (final)
|
||||
|
||||
@@ -0,0 +1,40 @@
|
||||
# G5 host + hub layers after — 2026-09-25T02:52:16+00:00
|
||||
== felhom-pve
|
||||
felhom-agent 0.134.0
|
||||
VMID Status Lock Name
|
||||
9201 running demo-felhom
|
||||
Name Type Status Total (KiB) Used (KiB) Available (KiB) %
|
||||
felhom-backup dir active 960303848 11072284 900377052 1.15%
|
||||
felhom-pbs pbs active 0 0 0 0.00%
|
||||
local dir active 98497780 28725888 64722344 29.16%
|
||||
local-lvm lvmthin active 365760512 11558032 354202479 3.16%
|
||||
data 3.16 0.58
|
||||
/dev/mapper/pve-root 94G 28G 62G 31% /
|
||||
agent.json
|
||||
agent.json.bak-r191
|
||||
agent.json.campaign8-before
|
||||
agent.json.campaign9-before
|
||||
agent.json.campaign9-prev
|
||||
agent.json.night-0925-off
|
||||
agent.json.pre-e-target-move
|
||||
agent.json.pre-prunegate.bak
|
||||
agent.json.pre-r672
|
||||
== hp
|
||||
felhom-agent 0.134.0
|
||||
VMID Status Lock Name
|
||||
9201 running demo-hp
|
||||
9202 running demo-hp-scratch
|
||||
Name Type Status Total (KiB) Used (KiB) Available (KiB) %
|
||||
felhom-pbs pbs active 0 0 0 0.00%
|
||||
local dir active 40453376 22725576 15640684 56.18%
|
||||
local-lvm lvmthin active 56487936 33921005 22566930 60.05%
|
||||
nvme-scratch dir active 983379700 74952044 858401044 7.62%
|
||||
data 60.05 2.67
|
||||
/dev/mapper/pve-root 39G 22G 15G 60% /
|
||||
agent.json
|
||||
agent.json.night-0925-off
|
||||
agent.json.pre-a4-retention
|
||||
agent.json.pre-r672
|
||||
== hub
|
||||
Effective floor: v0.271.0 — source: DB (hub_settings) ; env
|
||||
Customer Status Events Last Seen CPU Memory Disk Containers Last Backup Version Demo Ügyfél OK — 8 min ago 1% 16% 2% 1/1 – 0.271.0 Demo HP OK 2 4 4 8 min ago 10% 19% 33%/8% 20/20 – 0.271.0 Peti Proxmox DOWN — 71d ago 9% 66% 7% 2/2 – 0.115.0 Tester 1 DOWN 3 8d ago 13% 60% 29%/1% 22/22 – 0.245.0 Auto-refreshes every 60 seconds · Felhom Hub 0.124.0
|
||||
@@ -24,3 +24,7 @@ Capacity: phase0-capacity.txt. demo-felhom pool 3.13 %, root 31 %. demo-hp pool
|
||||
- [x] E bench 9401 created+destroyed (template removed); n8n 2.41.1→2.41.2 and mealie v3.27.0→v3.28.0 PROVEN on bench AND box; control failed (correct). TODO after 02:30: --write-ladder both, commit each, push, CI. Then reset drill again.
|
||||
- [x] G partial: 9202 apps removed via product, window 02:30, live catalog c802509 (switch key now explicit true), drill reset to live
|
||||
- [ ] 02:31 publish E; 04:10 start D watch (d_watch.py) on both boxes
|
||||
- [x] E published: n8n f14a608, mealie b996218 (CI 980/981), catalog CHANGELOG/REPORT dd9c6ad (982); drill reset to dd9c6ad
|
||||
- [x] D real night: demo-felhom opengist done 20 s; demo-hp 0 steps; hub has both update_leg; no whole-box backup due on either (gate never waited)
|
||||
- [x] G all three layers recorded (G1..G5); report DRILL-night-2026-09-25.md; STATUS; register 338 rows / 682,053 B
|
||||
- unproven.py: NOT WALKED 35 of 55 (unchanged)
|
||||
|
||||
@@ -1,31 +0,0 @@
|
||||
## Part A — the agent, the restore test, the HP backup
|
||||
|
||||
**A1 — agent v0.133.0 signed and delivered, one box after the other** (ruling 1, 2026-09-16). Package sha256
|
||||
`3aa30345…e69b6` verified against the published package before signing (`A/A1-*.txt`).
|
||||
|
||||
| box | signed (UTC) | box took it | AUTHORIZED → COMPLETED | committed | hub reads |
|
||||
|---|---|---|---|---|---|
|
||||
| demo-felhom-8363b5 | 19:25:30 | 21:34:05 CEST | job `c4b592ff7c9ff307` | 21:35:09 | 0.133.0 |
|
||||
| demo-hp-bb76ea | 19:35:55 | 21:48:58 CEST | job `36aab1ed8ad00979` | 21:50:02 | 0.133.0 |
|
||||
|
||||
Peti's box: never signed for.
|
||||
|
||||
**A2 — the restore test back on, both boxes.** `agent.json.pre-r672` copied back; the diff was only
|
||||
`restore_test_eval_interval_seconds: -1` (and the trailing newline). The `-1` config is kept as
|
||||
`agent.json.night-0925-off`. Start-up line on both: `restore-test scheduler starting (per-archive due-check)
|
||||
eval_interval=6h0m0s settle=24h0m0s`.
|
||||
|
||||
**A3 — one on-demand restore test.** demo-felhom: **PASS** — scratch 990000 restored, booted, verified,
|
||||
torn down in 1 min 25 s; pool 3.13 % → peak 5.68 % → 3.13 %; preflight "required 12.8 GB, avail 362.8 GB".
|
||||
demo-hp: **REFUSED, correctly** — "restoring 21.1 GiB (vzdump log: total bytes written) needs 30.3 GiB free, has
|
||||
22.1 GiB", exit 4, pool 59.01 % before and after, nothing created.
|
||||
|
||||
**A4 — HP whole-box backups, option A.** Before: root disk (`local`) 89 % used, 4.3 GB free, three 9201 archives
|
||||
(6.2, 6.3, 7.4 GB), retention 3. Changed: `local_backup_retention` 3 → 1 (saved copy
|
||||
`agent.json.pre-a4-retention`), agent restarted, the two oldest archives removed with PVE's own
|
||||
`pvesm prune-backups local --vmid 9201 --keep-last 1` (dry-run shown first) → 58 % used, 16.8 GB free. **Why the
|
||||
prune by hand:** PVE prunes AFTER a successful backup, so lowering the retention alone would not have let the next
|
||||
backup fit. One whole-box backup by the product's own button (`POST /api/guest-backup/trigger`, the Mentések
|
||||
page) — 9201's apps were stopped for it (snapshot mode, resumed at "snapshotted"): local archive **8.18 GB** in
|
||||
7 min, then the PBS tier (the button covers every tier) 23.2 GB in 4.5 min; the new prune kept 1 archive; root
|
||||
60 %; all 20 app containers healthy. The product row is **R-685**.
|
||||
@@ -1,26 +0,0 @@
|
||||
## Part C — the proof on 9202: six simulated nights
|
||||
|
||||
Controller v0.271.0 on 9202 only (`C/C0-deploy-9202.txt`), drill catalog (`C/C0-repoint-drill.txt`, health timeout
|
||||
90 s). Four apps installed through the product at the ladder's first `from`, then the drill put back at the head:
|
||||
wishlist 1 step behind, navidrome 2, romm 3, vikunja 1 with a failing step (its head probe on port 8999). Marks
|
||||
set in the drill: navidrome step 1 `needs_person`, wishlist's step `files_may_change`. Data seeded through each
|
||||
app's own front door and read back after EVERY night (`C/data-readback.txt`: 8 of 8 rounds, 4 of 4 apps, each
|
||||
fixture with its negative control). The window was moved through the product's own form (`POST /backups/window`)
|
||||
so the off-site job — and the leg chained to it — fired two minutes later.
|
||||
|
||||
| night | what it proved | leg summary (the box's own line) | pages (hu + en) |
|
||||
|---|---|---|---|
|
||||
| 1 | the chain on a box with NO off-site target ("the off-site leg does nothing; the update leg runs now"); one step per app; `needs_person` skipped; `files_may_change` taken WITH a whole copy (wishlist); a failing step undone | `done=2 undone=1 held=0 failed=0 skipped=1 in 3m6s [skipped: navidrome=needs_person]` — romm 60.1 s, vikunja undone 105.2 s, wishlist 20.1 s | „Automatikus frissítés 2026-09-24 22:31-kor — sikeres." / "Automatic update at … — done."; vikunja's undone sentence in both |
|
||||
| 2 | R-680 live: the undone step is NOT pressed again; navidrome's `files_may_change` step taken (its music folder is `excluded`, so its own unit is whole) | `done=2 undone=0 … skipped=1 in 1m10s [skipped: vikunja=failed_before]` | badges current / behind as expected |
|
||||
| 3 — accident | controller killed (kill -9) the moment navidrome's step ended | the leg had pressed romm IN THE SAME SECOND; the kill landed before romm's `up` → pin and definition put back, romm runs its previous version, page: „A frissítés megszakadt, mert a vezérlő újraindult…" / "The update was interrupted…"; the leg was not resumed (R-686) | all data read back |
|
||||
| 4 — accident | power cut (`pct stop`/`pct start` of 9202) while romm's step was `verifying` | box up in 13 s; "resumed 1 interrupted update(s)"; romm healthy after 30 s, DONE in 1 m 32 s; no automatic-update line on the page (the leg died — R-686) | all data read back |
|
||||
| 5 | the switch OFF (`POST /settings/app-update`, page reads unchecked) | `done=0 … stopped=switched_off in 0s` — nothing pressed | — |
|
||||
| 6 | the switch ON again; the catalog RE-TESTED vikunja's step (probe fixed, new `tested_at`) → the ladder print changed → R-680's record no longer binds | `done=1 … in 10s` — vikunja done | „Automatikus frissítés … 22:58-kor — sikeres." |
|
||||
|
||||
**Not run live, and why (R-687):** W+5h reached with steps left (the leg starts at W+105m; needs a 3-hour leg — unit
|
||||
test `TestLeg_NoStepAtOrAfterW5h`); the off-site leg FAILING (9202 has no off-site tier — unit test
|
||||
`TestChainUpdateLeg_EveryPath` covers error and panic); a `files_may_change` step WITHOUT a whole copy (every app
|
||||
given the mark was whole on 9202); the full-system gate's deferral (9202 has no agent, so no quiesce loop).
|
||||
|
||||
**Verdict: Part C passed** — every accident that could run on 9202 ended with the app healthy, the data read back,
|
||||
and a true sentence on its page; the four not-runnable cases are named, unit-proven and in the register.
|
||||
@@ -391,3 +391,4 @@ Compressed here to title, shipping version, evidence, and the sentences that sta
|
||||
| **R-684** | **demo-hp's whole-box backups could not fit on its root-disk target (P2).** Operator ruling 2026-09-24 evening, option A: retention 3 → 1 (`local_backup_retention`), the two oldest archives pruned by PVE's own prune, and one backup by the product's trigger fitted (8.18 GB; root 89 % → 60 %). The product lesson — warn BEFORE the night — is R-685 (agent v0.134.0 skips with a reason). | ruling 2026-09-24; applied 2026-09-24 night | `git show 75ff264:documentation/backlog/OPEN-ITEMS.md`; `audits/night-2026-09-25/A/A4-hp-backup-space.txt`, `A4-hp-backup-run.txt` |
|
||||
| **R-680** | **The box did not remember a failed update step (P2).** Controller v0.271.0: an undone or held step is recorded in app.yaml (`failed_update_step`, tied to the ladder's print); the automatic leg skips it until the catalog's ladder changes; a person can still press. Live on 9202: vikunja undone night 1, skipped `failed_before` night 2, re-tried after the catalog re-tested it. | v0.271.0, 2026-09-25 | `git show 75ff264:documentation/backlog/OPEN-ITEMS.md`; `audits/night-2026-09-25/C/`; `B/redproofs/R680-*` |
|
||||
| **R-678** | **After a step ended `done`, steps-left and the badge stayed stale (P3).** Controller v0.271.0: the update re-reads the app's catalog fields BEFORE it says done (and after an undo). Live on 9202: every automatic step's page read current at the leg's end. | v0.271.0, 2026-09-25 | `git show 75ff264:documentation/backlog/OPEN-ITEMS.md`; `B/redproofs/R678-*` |
|
||||
| **R-643** | **The ruled chain left the automatic update leg at most 15 minutes a night (P2).** Decision 20, built in controller v0.271.0: the full-system backup's gate defers while the leg runs, until W+5h (then only for a step in flight, cap W+5h30m — decision 31); the leg starts no step at or after W+5h; one shared constant. Unit + red-proof (`TestD20_GateWaitsForTheLeg`); live on the demo boxes: see the night record Part D. | v0.271.0, 2026-09-25 | `git show 75ff264:documentation/backlog/OPEN-ITEMS.md`; `audits/night-2026-09-25/B/redproofs/D20-*` |
|
||||
|
||||
File diff suppressed because one or more lines are too long
Reference in New Issue
Block a user