From 6b7d516ce5a9cfb0fe8bfca8046f8b86abe4271f Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Tue, 28 Jul 2026 13:35:27 +0200 Subject: [PATCH] REPORT + OPEN-ITEMS: R-100 closed and proven live; R-101 filed --- REPORT-r100.md | 194 ++++++++++++++++++++++++++++ documentation/backlog/OPEN-ITEMS.md | 3 +- 2 files changed, 196 insertions(+), 1 deletion(-) create mode 100644 REPORT-r100.md diff --git a/REPORT-r100.md b/REPORT-r100.md new file mode 100644 index 0000000..00324f4 --- /dev/null +++ b/REPORT-r100.md @@ -0,0 +1,194 @@ +# REPORT — R-100: a failing offsite tier must go stale (2026-07-28) + +Hub **v0.79.0 → v0.80.0**; companion `felhom-controller` **v0.180.0 → v0.181.0** (the producer, shipped +first). Written as `REPORT-r100.md` so the shared `REPORT.md` is not clobbered. + +## Baselines (reconfirmed, not copied) +`felhom.eu 6369570`, `felhom-controller 4056fec`, `felhom-agent d5c7691` — all = origin/main. The only +dirt in `felhom.eu` was a **foreign** `documentation/PROMPT-TEMPLATE.md` (shared worktree, untouched). +Hub manifest **and** running pod both `0.79.0`; `staleAfter` = 48h; controller 0.180.0 and agent 0.110.0 +live on both boxes. + +--- + +## The premise was wrong, and it was mine + +R-100 was filed yesterday claiming *"the operator's fleet-wide alarm plane is silent"*. Phase 0 refuted +that, twice: + +1. **A failing offsite run does alarm.** `main.go:655` wires `SetOffboxNotify` → `NotifyBackupFailed`; + the notify cooldown is 6h against a 24h cadence, so a nightly failure alarms nightly. Live hub DB: + `backup_failed | operator | sent | 5`, latest 2026-07-27 17:42. The `isStale` doc comment — + *"a recent-but-failing run is NOT stale (backup_failed owns that signal)"* — was **accurate**. +2. **The orphaned-repo path I expected to be an indefinite hole is already covered.** The scheduled run + returns early at `offbox.go:606`, *before* the `LastRun` write at `:716`, so `LastRun` freezes and + `offsite_stale` fires normally. + +I could find no failure mode that both advances `LastRun` and produces no operator signal. + +**The real defect — defeated defence in depth.** `offsite_stale` is the hub-side, *pull-based* net that +exists to be independent of controller-*pushed* events. Anchoring it on `LastRun` made it depend on the +very thing it backs up: when the push is lost, the net cannot compensate, because the failing controller +keeps refreshing the field the net reads. **F-HUB — this campaign's own finding, the hub dropping an +event under `SQLITE_BUSY` with no retry** — is exactly that loss. + +**Honest severity: MEDIUM**, not the top-ranked item. The fix is unchanged; the justification is not. + +--- + +## Phase 0 answers + +**P0.1 — a last-success timestamp did not exist.** `OffboxTarget` carried `LastRun`/`LastStatus`/ +`LastError`/`LastDuration` only. Recording one is a new field, not a transmission of something known. + +**P0.2 — `LastStatus` on the wire**, from 4000 live reports (not from source alone): + +| value | count | paired with | +|---|---|---| +| `ok` | 2269 | `last_run` set | +| absent/null | 541 | `last_run` **empty** — never-ran | +| `error` | 27 | `last_run` set | +| **`running`** | 7 | a report captured **mid-run** | + +Plus 1156 reports with no `offsite` object at all. **The legacy trap — status absent *with* a real +`last_run` — occurs 0 times**, because `LastStatus="running"` is written the moment a run starts. It is +still handled explicitly, but it is not a live shape. `running` being real is why the verdict ignores +status entirely. + +**P0.3 — sweep** + +| tier | `LastRun` written on failure? | read as success by a verdict? | +|---|---|---| +| **Offsite restic** | YES (`offbox.go:716`) | **YES — hub `isStale`.** The defect | +| **Tier 2 cross-drive** | YES (`recordTier2Failure`) | No hub verdict; UI only → **R-101, filed** | +| Tier 1 recovery units | **NO** — derived from an actual artifact | structurally immune | +| Shares offsite leg | YES | `sharing.html:180` shows the time only when status=="ok" — honest | +| DB dump | n/a — **event-based** (`db_dump_completed`/`db_dump_failed`) | immune by design | + +`offsite.go` is the **only** hub verdict anchored on a `LastRun`-shaped field. The deadline checker +already uses distinct success/failure *events* — the pattern this converges on. + +**P0.4 — the customer is NOT shown a failed offsite run as successful.** `backups_remote.html:34-36` +leads with the status (`✓ Rendben` / `✗ Hiba` / `Fut…`). Two narrower Tier-2 instances → **R-101**. + +--- + +## The fix + +**Controller v0.181.0 (producer, shipped first).** `OffboxTarget.LastSuccess`, carried on the report as +`last_success`. The rule is a pure function called unconditionally beside the `LastRun` write: + +```go +func offboxAnchorAfterRun(prev, at string, runErr error) string { + if runErr != nil { return prev } // failures neither advance nor clear + return at +} +``` + +Both directions are separate bugs: a failure must not **advance** it (the original defect) and must not +**clear** it (one bad night making an established tier read as never-succeeded). + +**Two silent-wipe sites found and closed** — the "seam built but never wired" shape, where the field +exists, the writer sets it, and an unrelated routine path zeroes it: +- `offboxConfigHandler` rebuilds the target from the form and copies runtime status field by field, so + an ordinary settings save would have erased the anchor; +- `ApplyOffsiteTarget` does the same on a hub re-apply. + +Neither would have surfaced until the verdict changed, days later. **The first was proven live** — see +below. + +**Hub v0.80.0.** Three deliberate branches: +- **never ran** — unchanged v0.73.0 anchored behaviour, still keyed on `last_run` on purpose: that field + answers "has anything ever happened here", and a box whose *first* run failed is a run, not a newborn. +- **legacy** (`last_run` set, no `last_success`) — degrades **explicitly** to the old behaviour, logged + **once** per customer. Absence-as-failure would alarm the whole un-upgraded fleet; absence-as-success + keeps the bug. Same degrade direction as R-88 Part 2's `age_state`. +- **anchored** — counts from `last_success`; `last_status` is deliberately not consulted, because + "error ⇒ stale" pages on every blip (the F-A1 noise path). + +**The alarm text had to move with the verdict.** `emitStale` still said `last run 8h ago` while firing on +a six-day-old success — a true alarm that reads as false. `staleAge` now separates *"runs are happening +and failing — check the error, not the schedule"* from *"the offsite leg is silently not running"*. + +--- + +## Red-proofs — all observed failing + +| # | red-proof | observed failure | +|---|---|---| +| A | restore the `LastRun` anchor | `a tier that has not succeeded in 6 days reads as FRESH — that is R-100` | +| B | delete the never-ran branch | `a newborn box alarmed — this is the 2026-07-23 cry-wolf that v0.73.0 fixed` | +| C | collapse to `LastStatus == "error"` | `a single transient failure alarmed — 20h ... well inside the 48h threshold` | +| D | delete the legacy degrade | `a legacy controller alarmed — that is a fleet-wide alarm storm on an un-upgraded fleet` | +| + | drop the `runErr` guard (controller) | `a FAILED run advanced LastSuccess ... that is the R-100 defect in mirror image` | +| + | always return `prev` | `a successful run did not advance the anchor` | +| + | drop the wire field | `OffboxReportStatus dropped LastSuccess — the hub would degrade forever` | +| + | drop the handler preservation | `a settings save erased LastSuccess` | + +**A hollow test of my own, caught by red-proofing it.** The first version of the controller test +re-implemented the rule in a local closure — mutating production code left it **green**. That is why +`offboxAnchorAfterRun` was extracted: the test now calls the real rule. + +Fixtures are the **real** wire shapes from P0.2, not invented JSON. +`go build`/`go vet`/`go test` green in both repos (hub 17 pkgs, controller 27 pkgs), run separately +from every commit. + +--- + +## §6 — LIVE, on demo-hp (disposable; `peti-felhom` never touched) + +A genuine restic failure was induced by pointing the target at a **closed port** (23 → 2) — it creates +nothing, touches no data, and is exactly reversible. + +``` +success run → last_status=ok last_run=11:24:20Z last_success=11:24:20Z +INJECT port 23 → 2 ... and the settings save PRESERVED last_success = 11:24:20Z ← the wipe-site fix, live +failing run → last_status=error last_run=11:25:48Z last_success=11:24:20Z ← ANCHOR HELD +``` + +**As the hub received it:** + +| box | status | `last_run` | `last_success` | anchor | +|---|---|---|---|---| +| **demo-hp** (induced failure) | `error` | 11:25:48Z | **11:24:20Z** | **HELD** | +| **demo-felhom** (healthy) | `ok` | 11:29:22Z | **11:29:22Z** | **advanced** | + +Also observed live, unplanned: **Scenario E**. Both boxes were still on the old controller at hub +startup, and the degrade logged **exactly once per customer** — +`[WARN] [offsite] demo-hp: controller sends no last_success — staleness degraded to the last-ATTEMPT +anchor`. Two lines, two customers, same second. + +**No spurious alarms:** 0 `offsite_stale` events since deploy (correct — both tiers succeeded minutes +ago). `backup_failed` fired for demo-hp at 11:25:48 from the induced failure, confirming the +pre-existing channel is intact and re-confirming the Phase 0 correction. + +**Config restored** and verified field by field: `host=u629488-sub3.your-storagebox.de port=23 +user=u629488-sub3 repo=/home/felhom-repo enabled=True escrow=escrowed`. + +### Proven live vs. proven by injected clock — stated plainly +- **Live:** the anchor does not advance on failure; it does on success; it survives a settings save; + `last_success` reaches the hub; the legacy degrade fires once per customer; no spurious alarms. +- **Unit, injected clock only:** the 48h **threshold** behaviour itself — Scenarios A/B/C/D turning on + elapsed time. A live threshold test would take days. **The threshold was NOT proven live.** + +--- + +## Part 2 — the rule +**"Presence is not success"** added to `CLAUDE.md` and its versioned copy, with both instances +(F-CRIT-2's phantom ctime, R-100's `LastRun`) and the corollary R-100's fix produced: when a verdict +changes which field it counts from, the **alarm text must change with it**. `// R-100` notes sit at +`isStale` and at the controller write site, each naming the test that pins it. + +## Filed, not fixed +- **R-101** — Tier-2 `LastRun` is also written on failure, and three customer surfaces render it without + a status (two degraded branches plus the restore-confirm dialog). No hub verdict reads it. + +## NOT yet live-validated (carried forward) +- **The 48h staleness threshold itself** (see above) — and with it Scenario A end-to-end: no + `offsite_stale` event has yet been *observed firing* from a genuinely stale success anchor, because + that needs 48h of failure. +- **Fault 4** — restic transport interruption; four injection approaches defeated by guest-bridged + networking. (This task's closed-port injection sidesteps it rather than solving it.) +- **R-99** — prune never removes phantom snapshots. +- **R-101** — filed today, unvalidated. +- `contentionAlarmAfter` (3h) — injected clock only. diff --git a/documentation/backlog/OPEN-ITEMS.md b/documentation/backlog/OPEN-ITEMS.md index 85cc140..7de4046 100644 --- a/documentation/backlog/OPEN-ITEMS.md +++ b/documentation/backlog/OPEN-ITEMS.md @@ -26,7 +26,8 @@ State: `BLOCKED` · `READY` · `WAITING-ON-OPERATOR` · `WATCHING`. Every row ha | **R-99** | Server-side prune **never removes** a phantom snapshot. Confirmed it does NOT count them toward `keep-last` (dry-run kept 2 real + the phantom) so there is **no retention/data-loss bug** — but one accumulates per aborted upload, forever | READY (S) | — | Decide a cleanup path. Deletion on a **customer** datastore is a separate ruling — detection shipped, removal deliberately not automated | CC | | **F-CRIT-1** | ~~An app that **fails to restart** after a quiesce never alarms on any channel — `restartAll` discarded the error AND `StateStopped` was whitelisted on invariant I1, which the quiesce path had made false~~ | **SHIPPED + PROVEN-LIVE** (controller v0.179.0, 2026-07-28) | — | Both causes fixed. Live on demo-hp: alarmed 9s after grace expiry, banner shows `(stopped)`; a deliberate user stop stayed silent through 9 dead-app scans | — | | **F-A1** | ~~A restore-test in flight made a healthy backup report as FAILED (HTTP 409 read as a tier failure): breaker armed + operator emailed, on both boxes~~ | **SHIPPED + PROVEN-LIVE** (controller v0.179.0, 2026-07-28) | — | 409 → contention: tier stays DUE, dropped before anything stops (15m), and BLOCKED alarm if contention outlives the agent's 120m ceiling (3h). Hub DB: 409 → **0** operator emails, real failure → **1** | — | -| **R-100** | **A restic offsite tier that fails every night never goes stale on the hub.** `isStale()` reads only `LastRun` (`hub/internal/monitor/offsite.go:120,127,131`) and the controller writes `LastRun` **unconditionally**, outside the error branch (`controller/internal/backup/offbox.go:716`, with `LastStatus="error"` set at :725). So a tier failing nightly keeps a fresh clock, `isStale` is permanently false, and the operator's fleet-wide alarm plane is silent. `LastStatus` reaches the hub and is **only logged** (`offsite.go:270`) — it drives no checker and no notification | READY (S) | — | **This is F-CRIT-2's defect class on the hub, for the restic tier**: a failed run resetting the freshness clock. Gate staleness on the last *successful* run, not the last attempt. Found by Part 4 investigation 2026-07-28; NOT fixed (investigation-only scope) | CC | +| **R-100** | ~~A restic offsite tier that fails every night never goes stale on the hub — `isStale` counted from `LastRun`, which the controller writes unconditionally on failure~~ | **SHIPPED + PROVEN-LIVE** (controller v0.181.0 + hub v0.80.0, 2026-07-28) | — | Anchored on a new `last_success`. **Severity corrected during Phase 0: this was NOT a silence** — `backup_failed` does fire nightly and reaches the operator (live DB: 5 sends). The real defect is **defeated defence in depth**: the hub-side *pull* net was anchored on a field the failing controller keeps refreshing, so it could not compensate for a lost *push* (cf. F-HUB). Live on demo-hp: induced failure → `last_run` advanced 11:25:48Z, `last_success` **held** 11:24:20Z; demo-felhom healthy → anchor advanced. Legacy degrade logged once per customer, live | — | +| **R-101** | **Tier-2 (cross-drive) `LastRun` is also written on failure** (`recordTier2Failure`), and three customer surfaces render it **without** a status: the `Tier2DestDisconnected` and `Tier2DestInactive` branches of `backups_apps.html`, and the restore-confirm dialog (`Legutóbbi másolat: {{.Tier2LastRun}}`) — which presents a possibly-failed run's timestamp at the moment the customer decides whether to restore | READY (S) | — | Found by R-100's P0.3/P0.4 sweep; **filed not fixed** (out of that task's path). No hub verdict reads it, so this is a UI-honesty issue, not an alarm one. The two degraded branches do carry a `tag-warn`; the restore-confirm is the sharpest instance. Fix: pair the timestamp with the status everywhere, as the main Tier-2 branch already does | CC | | **F-REBOOT** | ~~A guest rebooted during its backup does not come back — shutdown completes, start never happens, no self-heal; 9m47s total appliance outage with every alarm silent~~ | **SHIPPED + PROVEN-LIVE** (agent v0.107.0, 2026-07-28) | — | 60 s guest-power watchdog; `onboot` is the deliberate-stop discriminator (already the stale-lock path's, and what `pve-guests` consults), retry bounded 3x/1m-2m-4m then escalates once. Live on demo-hp: **120 s unattended** vs the incident's 587 s with a human; Scenario B proven (an `onboot:0` guest left stopped) | — | | **F-LEAK** | ~~A failed restore-test cannot destroy its own scratch guest (403 `VM.Allocate`); the 10-slot VMID band shrinks silently~~ | **SHIPPED + PROVEN-LIVE** (agent v0.110.0 + host-install v1.21.0, 2026-07-28) | — | **Three attempts, two refuted live.** (1) Pool adoption: `PUT /pools/{pool}` also needs `VM.Allocate` on the VM — membership cannot bootstrap its own authority. (2) Per-path `/vms/990000..990009` ACLs: work, but PVE's destroy calls `remove_vm_access` (`LXC.pm:906`) which deletes every ACL at `/vms/` — **consumed by the op it authorises**, one use per slot. (3) SHIPPED: 4th root-fenced exception, band enforced in sudoers **literally** (`pct destroy 99000[0-9] --purge`) + in code + at the caller; API destroy still tried first. Live: band PERMITTED, `9201`/`9100`/`9999`/`990010`/`1` REFUSED, and `pct start 990000` REFUSED too | — | | **F-OBS** | ~~`deadapp-check` leaves NO positive observable on a default (info-level) box — "no alarms" was indistinguishable from "never ran"~~ | **SHIPPED + PROVEN-LIVE** (controller v0.180.0 + agent v0.109.0, 2026-07-28) | — | INFO summary every 20th scan carrying scans/evaluated/down. **Agent v0.109.0 fixes the same shape in the guest-power watchdog shipped hours earlier in v0.107.0** — it logged only at startup and when it acted, so its health could be read only from absence | — |