From 2584dfb9388501fae23dd98999efe279cf1a4487 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Tue, 4 Aug 2026 09:05:53 +0200 Subject: [PATCH] R-193: a guest rebuild silently drops the offsite tier; R-192 cause established MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Operator confirms no hub-side offsite config change, so the regression was not an action. Evidence: demo-hp's controller went 0.187.0 -> 0.192.0 at 06:12:18 with a new config hash and the agent re-keyed its leaf three minutes earlier — a guest rebuild. The last pre-rebuild report shows the tier fully healthy: escrowed, last success 02:16:39Z, 15 snapshots, 40.9 MB. No offsite object in the 108 reports since. Mechanism: the restic credential is delivered once. demo-hp consumed its secret on 2026-07-23; the rebuilt controller has no copy and no way to request another. demo-felhom survived the SAME rebuild only because its secret was still unconsumed — it consumed it four seconds after its config hash changed and was reporting offsite again 76 seconds later. That difference was luck, not design. Also sharpens R-192: the self-heal's guard refuses when any report since the consume carried an offbox target, but that query reads the OLDEST 500 reports — all of which predate the rebuild. Healthy history before a rebuild is not evidence the credential still works, which is why the automation that exists for this case declined to act. --- STATUS.md | 17 ++++++++++------- documentation/backlog/OPEN-ITEMS.md | 3 ++- 2 files changed, 12 insertions(+), 8 deletions(-) diff --git a/STATUS.md b/STATUS.md index 943d589..f86bfad 100644 --- a/STATUS.md +++ b/STATUS.md @@ -20,13 +20,16 @@ Proven end to end on real hardware. ## What's broken -- **One demo machine has no off-site copy of its app data, and has not since yesterday morning.** The - second demo machine (`demo-hp`) stopped reporting an off-site backup at 08:12 on 3 August and has - not reported one in 108 check-ins since. The daily email you are getting about it is right that - something is wrong, but **its explanation is wrong** — it says the password was never applied, when - in fact it was applied on 23 July and then stopped working eleven days later. The automatic repair - declines, correctly, because it can see it is a different problem — but says nothing about why. - *(R-192)* +- **One demo machine has no off-site copy of its app data, and rebuilding it is what took it away.** + `demo-hp` was rebuilt on 3 August; before that its off-site backup was healthy and had run + successfully at 04:16 that morning (15 snapshots). The rebuilt machine came up without it and has + not had it in 108 check-ins since. **The cause is that the off-site password is delivered exactly + once and a rebuilt machine cannot ask for another** — the other demo machine survived the same + rebuild only because it happened to have an unused password waiting for it, and recovered in 76 + seconds. Nothing about that difference was designed. *(R-193)* +- **The daily email about it tells you the wrong story**, and the automatic repair that exists for + this declines without saying why. The message says the password was never applied; it was, on + 23 July, and worked for eleven days. *(R-192)* - **The weekly off-site backup reports FAILED although it worked.** It uploads correctly and then trips on a tidy-up step it is deliberately not allowed to perform, so the job ends in an error and you get an email. The backup itself is safe and on the endpoint. Both demo machines do it; one diff --git a/documentation/backlog/OPEN-ITEMS.md b/documentation/backlog/OPEN-ITEMS.md index fa703b3..ed785f6 100644 --- a/documentation/backlog/OPEN-ITEMS.md +++ b/documentation/backlog/OPEN-ITEMS.md @@ -35,7 +35,8 @@ State: `BLOCKED` · `READY` · `WAITING-ON-OPERATOR` · `WATCHING`. Every row ha | **R-189** | **A passing restore-test can be invisible to the hub forever — and R-86 made that window a week instead of a day.** The agent reports `restore_tests[]` from `internal/backup.Store`, which is **in-memory** (its own comment: *"lost on restart; the cadence re-populates"*), and the hub's report interval is 900 s. An agent restart inside that window drops the result. That used to self-heal within 24 h because the next cadence re-tested the same tier; **under per-archive due-ness the agent will NOT re-test a proven archive**, so the hub can stay ignorant of a proof until the NEXT archive generation — a week on the offsite tier. **Observed live, 2026-08-03:** the 15:25:14 PASS on `felhom-pbs` (a real 14.5 GB offsite restore) reached **no** host-report — the hub logged `0 restore-tests` at 15:28:00 and 15:32:14 — because the agent was restarted at 15:27:57 for the v0.121.1 deploy, 2 m 43 s after the run and before the next report | **CLOSED — SHIPPED + PROVEN-LIVE 2026-08-03** (agent **v0.122.0**) | — | **The persisted proof already exists and is not reported.** `RestoreTestState` (on disk, per tier, R-86: with the archive id) survives exactly this, and `RestoreTestState.Snapshot()` carries the doc comment *"for the host-report gauge"* — **and has no production caller at all** (grep, 2026-08-03). That is this project's own *seam built but never wired* class, fifth instance, and a comment asserting an invariant with no test pinning it, both in one method. **Severity is bounded, and worth stating so it is not over-ranked:** the hub scans its retained window, archives keep arriving, and R-86's per-tier window for the offsite tier is 12 days against a 7-day archive rhythm — so ONE lost report is tolerated. What is not tolerable is that the loss is **silent** and that the box will not repeat the work. **Fix shape:** report the persisted per-tier proof (target, archive, proven_at) alongside the in-memory latest run, and let the hub's `lastProvenPerTier` read it — a report-contract change, so it touches `internal/hub/report.go` + `contract_test.go` + the hub's checker, and it is a spec, not a one-liner **FIXED.** `RestoreTestState` now stores the **tier** and what was **verified** beside the archive (recorded at proof time, from the run's own result — deriving them later would need a storage lookup that can fail on the one path where failing means mislabelling a proof), exposes `ProvenRestoreTests`, and `Collector.SetProvenRestoreTests` merges it with the in-memory result. **Merge rule: one entry per tier, newest by `TestedAt` wins** — a fresh failure beats a stored success (the failure is the news and lives nowhere else), a stored success beats a stale in-memory entry after a restart, and a tier never appears twice (two entries would read at the hub as two tests). An unparseable timestamp counts as OLDER, so a malformed entry cannot displace a good one. **It refuses to lie:** a record missing the archive OR the tier produces NO entry, and run mechanics (scratch VMID, duration) are not re-invented — an absent duration is not a claim, a fabricated one would be. **The asymmetry is now written where it will be read:** only successes are persisted, because a success SUPPRESSES future work (a proven archive is never re-tested, so a lost proof leaves the box quietly less tested than it believes) while a failure CAUSES future work and heals itself at the next evaluation. **`Store`'s comment was corrected in place** — *"lost on restart; the cadence re-populates"* was true under a timer and became false the moment R-86 shipped; leaving it is how the next reader concludes this is handled. **The seam that had no caller is now pinned by an AST test** (`TestMainWiresTheDurableRestoreTestProof`), because `Snapshot()` claimed a *"host-report gauge"* in its doc comment for weeks with nothing calling it. **MIGRATION, stated because it is visible on the live box:** a pre-R-189 record carries an archive but no tier and is therefore NOT reportable — upgrading does not retroactively make an old proof visible to the hub; the tier's next real proof fills it in. Observed on demo-felhom immediately after the upgrade: still `0 restore-tests` until a fresh run. | CC | | **R-190** | **A storage ACL that demonstrably WORKED in the morning was gone by mid-morning, and nothing recorded its removal.** On demo-felhom, a `vzdump` by `felhom-agent@pve!agent` with `--storage felhom-backup` completed **OK at 04:44:50 CEST 2026-08-03** (task log read in full). From **09:24:56** the same path returned `HTTP 403 … missing privilege Datastore.Allocate at /storage/felhom-backup`, six times through the day, until the grant was re-applied by hand at 18:54. By ~14:50 `pveum acl list` showed **no row at all** for that path | **OPEN** | — | **Why this is not just R-185 restated:** R-185's mechanism (the installer's Scenario-F arm resolves a pre-existing target without granting) explains a box that NEVER had the grant. This box HAD it and lost it, inside five hours, with the machine up throughout. **Ruled out, each by measurement:** a host reinstall (`uptime` = 12 days); any `pveum`/ACL/`user.cfg` activity in syslog between 04:00 and 10:00 (none); any ACL entry in `/cluster/log` (none). **Correlated, not established:** `host_leaf_changed` at 09:15 and `controller_started` at 09:19 — guest 9201 was reprovisioned nine minutes before the first 403. PVE removes ACLs at `/vms/` when a guest is destroyed (`AccessControl::remove_vm_access`, the F-LEAK mechanism); whether any path can take a `/storage/` row with it has NOT been established and is the first thing to check. **Why it matters more than the grant did:** a permission that can vanish silently makes every ACL-based guarantee on these hosts provisional, and the agent's new store-grant probe (v0.123.0) now detects the STATE but says nothing about the TRANSITION. **Worth pairing with:** whether the probe should report a grant it once had and no longer has as a distinct, louder signal than one it never had | CC | | **R-191** | **Every weekly offsite backup UPLOADS successfully and then FAILS the job on a prune the box is deliberately not allowed to do — on both demo boxes.** Measured on demo-felhom 2026-08-04 06:49–06:53: the upload completed (223 s, 629 MiB of 1.874 GiB, **67.2 % reused incrementally**), then `ERROR: prune 'ct/9201': proxmox-backup-client failed: Error: permission check failed - missing Datastore.Modify\|Datastore.Prune on /datastore/felhom-offsite/demo-felhom` → `ERROR: Backup of VM 9201 failed - error pruning backups` → `TASK ERROR: job errors`. The hub raised `whole_guest_backup_failed` | **OPEN** | — | **This is R-89's rule not reaching the config.** R-89 moved PBS pruning SERVER-SIDE — *"boxes set `keep_last: 0`, ep0 runs prune jobs; box tokens stay write-only, never widen the grant"*. The token behaves exactly as designed: it refuses. But **both** demo boxes still arm the offsite tier with `keep_last=2 prune_pbs_allowed=true` (`backup_targets: [{target_id: felhom-pbs, cadence_seconds: 604800, keep_last: 2}]`), so every run asks for a prune that must fail. **The data is SAFE and that is why this is not a P1:** the snapshot lands before the prune is attempted; what is wrong is the job's VERDICT and the weekly operator e-mail it produces. **But it is corrosive in the specific way this project keeps finding:** a backup that reports FAILED while succeeding trains the operator to discount `whole_guest_backup_failed`, which is the same alert that would carry a real one — and it is exactly the failure the R-100 corollary warns about, an alarm whose text is true and whose trigger is not the thing you would act on. **Fix is one config line per box** (`keep_last: 0` on the PBS tier) plus whatever writes it on a fresh install; **deliberately NOT applied in this session** — the session was a runbook with an explicit "change nothing, and if a change appears necessary, stop and report" rule, and a retention field on a live backup tier is not a change to slip into an observation run. **Check before fixing:** whether ep0's prune jobs actually cover these two namespaces, or the snapshots simply accumulate once the box stops asking | CC | -| **R-192** | **`offsite_delivery_stuck` tells the operator the opposite of what the detector measured, and the self-heal silently refuses for exactly the reason the message denies.** demo-hp has been e-mailing this daily since 2026-08-03 06:12 UTC: *"one-time password consumed 284h ago and **500 report(s) since carry no offbox target** — the credential is likely burned (apply died between consume and persist). Re-issue delivers a fresh one."* **Measured against the hub's own data: all 500 of those reports DO carry an offbox target** | **OPEN** | — | **What actually happened on that box:** the credential was consumed 2026-07-23 09:53:41 and **applied successfully** — the controller reported an `offsite` object continuously until **2026-08-03 05:59:21 UTC**, then it **vanished at 06:12:19** and has been absent for **108 consecutive reports** since. So this is a **regressed apply**, not a burned credential. **Two distinct defects, and the second explains the first's invisibility.** **(a)** `maybeEmitStuck` builds its message from `status.ReportsSinceConsume` (the TOTAL) while hardcoding the phrase *"carry no offbox target"*, and never consults `status.OffsiteReportsSinceConsume` — which is the field that says the opposite. The recommended action (*Re-issue*) is aimed at a failure mode that did not occur. This is R-100's corollary again: an alarm whose text stopped matching what its verdict counts. **(b)** `maybeHeal` refuses **silently** (`OffsiteReportsSinceConsume != 0` → *"regressed-apply shape → operator's call"*, a bare `return` with no log line), so the operator gets a daily e-mail with the wrong story, no heal, and nothing anywhere saying why the heal declined. `offsite_credential_restaged` has **never** fired, on any customer. **The underlying condition is REAL and is the part that matters:** demo-hp currently reports no offsite target at all, i.e. that box's customer app-data has **no off-site copy right now** — and it has been that way since 08:12 CEST on 2026-08-03. A spot check inside the controller container found no restic environment, consistent with the report. **What removed it is not established** and is the first thing to find out. **Fix shape:** the message must state which shape was detected (burned vs regressed) and say what to do for each; the heal's refusal must log its reason; and the regressed shape probably deserves its own event type rather than borrowing the burned one. **Do NOT 'fix' it by widening the heal to restage over a regression** — the guard is right, only mute | CC | +| **R-192** | **`offsite_delivery_stuck` tells the operator the opposite of what the detector measured, and the self-heal silently refuses for exactly the reason the message denies.** demo-hp has been e-mailing this daily since 2026-08-03 06:12 UTC: *"one-time password consumed 284h ago and **500 report(s) since carry no offbox target** — the credential is likely burned (apply died between consume and persist). Re-issue delivers a fresh one."* **Measured against the hub's own data: all 500 of those reports DO carry an offbox target** | **OPEN** | — | **What actually happened on that box:** the credential was consumed 2026-07-23 09:53:41 and **applied successfully** — the controller reported an `offsite` object continuously until **2026-08-03 05:59:21 UTC**, then it **vanished at 06:12:19** and has been absent for **108 consecutive reports** since. So this is a **regressed apply**, not a burned credential. **Two distinct defects, and the second explains the first's invisibility.** **(a)** `maybeEmitStuck` builds its message from `status.ReportsSinceConsume` (the TOTAL) while hardcoding the phrase *"carry no offbox target"*, and never consults `status.OffsiteReportsSinceConsume` — which is the field that says the opposite. The recommended action (*Re-issue*) is aimed at a failure mode that did not occur. This is R-100's corollary again: an alarm whose text stopped matching what its verdict counts. **(b)** `maybeHeal` refuses **silently** (`OffsiteReportsSinceConsume != 0` → *"regressed-apply shape → operator's call"*, a bare `return` with no log line), so the operator gets a daily e-mail with the wrong story, no heal, and nothing anywhere saying why the heal declined. `offsite_credential_restaged` has **never** fired, on any customer. **The underlying condition is REAL and is the part that matters:** demo-hp currently reports no offsite target at all, i.e. that box's customer app-data has **no off-site copy right now** — and it has been that way since 08:12 CEST on 2026-08-03. A spot check inside the controller container found no restic environment, consistent with the report. **What removed it is not established** and is the first thing to find out. **Fix shape:** the message must state which shape was detected (burned vs regressed) and say what to do for each; the heal's refusal must log its reason; and the regressed shape probably deserves its own event type rather than borrowing the burned one. **Do NOT 'fix' it by widening the heal to restage over a regression** — the guard is right, only mute **CAUSE ESTABLISHED 2026-08-04 (operator confirms no hub-side offsite config change).** The regression is a **guest REBUILD**: at 06:09:40 `host_leaf_changed` (agent re-keyed), at 06:12:18 `controller_started (0.192.0)` — the controller went **0.187.0 → 0.192.0** with a **new config hash** (`1f725a2e843c` → `744e83d72c80`) — and the report at 06:12:19 is the first without `offsite`. The pre-rebuild object was fully healthy: `escrow_state: escrowed, last_status: ok, last_success 2026-08-03T02:16:39Z, snapshot_count 15, repo_size 40.9 MB`. → **R-193** owns the rebuild half. **AND THE HEAL'S GUARD IS WRONG FOR EXACTLY THIS CASE, which is why the automation that exists to fix it declined.** `maybeHeal` refuses when `OffsiteReportsSinceConsume != 0`, reading that as *"the apply regressed, so it is the operator's call"*. But `CountReportsOffsiteSince` counts the **OLDEST 500 reports since the consume** (`ORDER BY id LIMIT 500`) — for demo-hp all 500 predate the rebuild. **Offbox evidence from before a rebuild is not evidence that the credential still works**, so the guard reads healthy history as a reason not to heal a box that demonstrably cannot apply. The fix is to judge on RECENT evidence (e.g. the latest N reports, or evidence after the newest `controller_started`), not on everything since the consume. | CC | +| **R-193** | **A guest rebuild silently drops the off-site app-data tier, and nothing restages the credential.** demo-hp was rebuilt on 2026-08-03 (controller 0.187.0 → 0.192.0, new config hash, agent leaf re-keyed at 06:09:40). Before it, the offsite tier was healthy and working — `escrow_state: escrowed`, `last_status: ok`, last success **02:16:39Z that morning**, **15 snapshots, 40.9 MB**. After it: no `offsite` object in any of **108** reports, and **no off-site copy of that customer's app data since 08:12 CEST on 2026-08-03** | **OPEN** | — | **Mechanism, fully evidenced.** The restic credential reaches a box exactly once, as a one-time secret. demo-hp's was consumed **2026-07-23 09:53:41**; the rebuilt controller came up with a fresh data volume, no copy of it, and **no way to ask for another** — the hub is the only side that can stage one, and it will not re-stage a consumed secret on its own (the R-71c self-heal would, but it refuses — see R-192). **demo-felhom survived the SAME rebuild by luck, and the contrast is the proof:** its secret was created 2026-07-21 and still **UNCONSUMED**, so when its config hash changed at 07:17:54 and `offsite` dropped for exactly one report, it consumed the staged secret at **07:17:58** and was reporting `offsite` again by 07:19:10. One box had a spare credential staged and recovered in 76 seconds; the other did not and has been unprotected for a day. **That difference was not a design decision — it was an accident of which box happened to have an unconsumed secret lying around.** **Why this is not just "re-issue it":** the remedy (Re-issue) resets the sub-account password via the Hetzner API and, per R-39's record, **rotates the restic password and makes the escrow STALE** — so it needs the recovery-code ceremony re-run, and the continuity of the 15 existing snapshots under the new credential must be VERIFIED, not assumed (`hub v0.60.0` retains superseded escrow, and the orphan guard is move-aside-never-delete). That is an operator act with a customer-facing consequence, so it is not something to fire automatically without deciding the escrow question first. **What to design:** a rebuild is a normal, expected event on these boxes — the offsite tier must survive one, either by the hub restaging automatically when a re-enrolled box reports no offsite (the R-192 guard fix makes this safe), or by the credential being recoverable from escrow at re-bootstrap rather than delivered once and unrecoverable | CC | | — | Storage Box **snapshots** on `storage-box-pool-1` — plan SET (daily 00:00, keep 7) but **0 taken yet** | WATCHING | first run tonight 00:00 | Confirm `size_snapshots > 0` tomorrow; until then the mitigation is armed, not proven | CC | | — | `PBS-storage-1` (u629193, box 611421) still `status=active`, 19.9 MB | WAITING-ON-OPERATOR | operator console | Delete the box | operator | | **R-90** | ~~ep0 RAM headroom — 4 GiB swap survived its first reboot 2026-07-27; 3.8 GB RAM unchanged~~ | **CLOSED — the operator rescaled ep0 to a CX33 on 2026-08-03** | — | **MEASURED ON THE BOX, not read from an invoice:** `felhom-hetzner` reports `Mem: 7757` MB total (**8 GB**, was 3.8) and `nproc` **4**. **The interim lever survived and was checked rather than assumed** — a resize is a stop/start, so "the swapfile is still there" was an assumption until measured: `/swapfile`, 4 GiB, dated `Jul 27 14:40`, **active** (`swapon --show` → `/swapfile file 4G 0B -2`), 0 B in use on an idle box. **THE 40 GB LOCAL DISK DID NOT CHANGE** and must not be "corrected" alongside the RAM: `/` is 38 G, 58% used. This was a CPU/RAM resize only, so every disk figure in the runbooks still stands — the separate 98 G volume at `/mnt/pbs-datastore` (R-82 P0.3) is unaffected. **Why this was BLOCKED and no longer is:** the row recorded CX33 as *"confirmed unavailable even powered OFF"* — the Cost-Optimized line's limited availability, not a power-state problem. It became available and the operator took it. **Documentation corrected** (`RUNBOOK-ep0-datastore-volume`, `RUNBOOK-pbs-prune-serverside` ×2, `runbooks/offsite-endpoint.md` ×2, `runbooks/target-selection.md`) and **audit/evidence documents ANNOTATED, not revised** (`SPIKE-connectivity-wireguard-2026-07-03`, campaign-10 `phaseA-journal`) — they record what was true when written and that is their value. **Still open and still the operator's, deliberately untouched:** `target-selection.md`'s *"D-d did not name ep0 either way. Confirm it explicitly."* | — |