From a63409c8437bfa8b93875781045c8abee2bb6334 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Tue, 28 Jul 2026 09:47:55 +0200 Subject: [PATCH] =?UTF-8?q?docs:=20F-CRIT-1=20+=20F-A1=20=E2=80=94=20REPOR?= =?UTF-8?q?T,=20CONTEXT=20(v0.179.0)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Six red-proofs with observed failure text, the bounds chosen for contention (15m retry / 3h alarm) justified against the agent's own 120m PBS restore-test ceiling and the 12m01s longest observed restore-test, and the live replay of both findings on demo-hp with the hub DB as arbiter: - failed restart alarmed 9s after grace expiry; banner shows (stopped) - a deliberate user stop stayed silent through 9 dead-app scans - 409 contention produced 0 operator emails (8 -> 8) - a real transport failure produced 1 (8 -> 9) Same box, same event type; the only difference is 409 vs a genuine error. --- REPORT.md | 253 ++++++++++++++++++++++++++++++++++++++---------------- 1 file changed, 181 insertions(+), 72 deletions(-) diff --git a/REPORT.md b/REPORT.md index 7680d74..a6d13f7 100644 --- a/REPORT.md +++ b/REPORT.md @@ -1,84 +1,193 @@ -# REPORT — R-88 Part 2 (controller) + R-97c follow-through (v0.178.0) (2026-07-27) +# REPORT — F-CRIT-1 + F-A1: one alarm that never fired, one that fired wrongly (v0.179.0) (2026-07-28) -**Overwritten** per the standing rule. Controller **v0.177.0 → v0.178.0**. -**MinAgent: 0.105.0** — the `age_state` semantics. Deployed AFTER agent v0.105.0 on both boxes. +**Overwritten** per the standing rule. Controller **v0.178.0 → v0.179.0**. Both Campaign 8 findings, +fixed together because both are "the alarm is wrong" and both live in `internal/quiesce` plus its +`classifyRunStates` consumer. No wire/contract change; no agent behaviour change (its 409 is correct +and was left alone — only a wrong comment there was corrected). -## What changed +## Baselines (reconfirmed, not copied) +Controller `0.178.0` live on both boxes; agent `0.106.0`; `felhom-controller 8f46495`, +`felhom.eu d0cec9d`, `felhom-agent af1c21a`, all clean. -`scheduledRunAllowed` fired the safety valve on ANY nil age. It now requires a licence: +--- -| `age_state` | licenses the valve? | why | -|---|---|---| -| `absent` | **yes** | the agent looked; nothing is there | -| `unknown` | **no** | unreadable storage — the whole point of R-88 | -| `known` | n/a | a real age; the comparison decides | -| *(empty)* | **yes** | pre-v0.105.0 agent — deliberate, see below | +## F-CRIT-1 — a failed app restart never alarmed. Two independent causes. -**A missing field means LEGACY, not unknown.** Reading an old agent's silence as "unknown" looks -safer and regresses Scenario D: the valve would stop firing on every un-upgraded box, so a genuinely -new box would never take its first backup outside its window and nobody would notice for weeks. The -MinAgent floor drives the upgrade; the valve is not the place to force it. Logged **once** per -process (the `logTierDegradeOnce` shape). An unrecognised FUTURE value also maps to legacy — a newer -agent inventing a fourth state must not inherit "unknown" semantics from a controller that has never -heard of it. +### Cause 1 — the outcome was thrown away +`restartAll` returned nothing; a failed `StartStack` was logged and dropped on the spot, so no +caller could learn a customer's app had not come back. It now **returns the stacks that failed**, and +both call sites (the cycle's unquiesce and crash recovery) record the result via +`noteRestartOutcome`. -**Untouched, as required:** the R-88 Part 1 breaker and its timings, `dropBackedOffTiers`, the window -bounds, and `TriggerNow` (still ungated by everything). +### Cause 2 — a documented invariant the quiesce path had made false +`classifyRunStates` whitelists `StateStopped` because v0.164.0 correctly refused to alarm on +deliberate user stops, resting on I1: *"StateStopped means deployed, deliberately stopped by the +user."* **The quiesce loop stops stacks by the same `docker compose down` path**, so a stack it +stopped and then failed to restart is also `StateStopped` — byte-identical on the Docker side — and +was whitelisted into total silence. -## The near-miss worth reporting +No state test can separate them; they *are* the same state. The distinguishing fact is that the loop +**tried to restart it and could not**, now surfaced by `Loop.FailedRestarts()`. That set is the only +thing that lifts the whitelist: -`TieredBackend` is satisfied by a **runtime** type assertion in `resolveDueTiers` -(`l.backend.(TieredBackend)`), not at compile time. When `DueFor`'s signature changed, the whole repo -**built and vetted clean** while `quiesceBackend` silently stopped satisfying the interface. That -would have shipped, degraded every box to the untargeted single-tier path, and lost R-82's multi-tier -backups entirely — **with no error anywhere**. `TestQuiesceBackendSatisfiesTieredBackend` is now the -compile-time witness; it caught this during the change. Sixth instance of the inert-seam class. - -## R-97c follow-through - -The comment in `internal/notify/notifier.go` claiming these event types are operator-only "because -they have no customerMessages entry" was **wrong** and is corrected. The hub falls back to the raw -message when the entry is missing, and the only customer gate is `prefs.EnabledEvents` — pure -configuration. Enforcement is hub-side `operatorOnlyEvents` (hub >= v0.79.0). - -## Tests — 27 packages ok, 0 failed; `build`/`vet`/`test` each rc=0, run separately, vet unpiped - -+7 (6 age-state + 1 interface witness). Red-proofs observed and restored: - -| Scenario | Mutation | Observed | -|---|---|---| -| **A** | `unknown` licenses the valve (pre-fix) | `R-88 Part 2: an UNKNOWN age bypassed the backup window and stopped 1 stack(s) — an unreadable storage must not masquerade as a first-ever backup` | -| **B** | drop `absent` from the licence | `a genuine first-ever backup (absent) must RUN outside the window; 0 stack(s) stopped — the safety valve was lost and a new box would starve` | -| **C** | treat legacy as unknown | `C: a pre-v0.105.0 agent must behave EXACTLY as before — nil age fires the valve. 0 stack(s) stopped; an un-upgraded box just silently stopped backing up outside its window` | - -**C asserts behaviour, not the log line** — a controller that logs the degrade and then defers would -pass a log-only assertion while silently changing behaviour on every un-upgraded box. - -## Deployed + verified - -Agent v0.105.0 first, then controller v0.178.0 — demo-hp, then demo-felhom. Both `Up (healthy)`. - -**The MinAgent floor is satisfied, proven positively:** zero `pre-v0.105.0` degrade warnings on -either box (they would fire on the first due tier against an old agent), and the live wire carries -the field: - -``` -tier=local due=True age_state=known age_seconds=91097 reason=older than cadence -tier=felhom-pbs due=False age_state=known age_seconds=100172 reason=within cadence window +```go +userStopped := st.State == stacks.StateStopped && !failedRestart[st.Name] +down := stacks.IsDownState(st.State) && !userStopped && !quiesced[st.Name] ``` -**And the gate is demonstrably working on a known age:** `local` is genuinely due (25.3 h against a -24 h cadence) at 18:11 Budapest — outside `[04:30, 08:30)` and well under the 48 h valve threshold — -so it correctly **defers**. No vzdump has run since the incident's last failure at 07:13:06 UTC. -Zero spurious backoff/suppression lines, zero startup errors on both boxes. +The flag is only ever consulted for an already-down stack, so a stale entry cannot manufacture an +alarm on a healthy app; it clears the moment a later restart of that stack succeeds. -## NOT yet live-validated +### Why the existing tests missed it +R-97b's Scenario F asserted that **suppression expires**. It never asserted that **an alarm +follows**. Suppression lifted correctly and the whitelist ate the alarm one layer down — a green, +red-proofed suite over a production path broken two independent ways. That is why §5 exists. -- **No `unknown` state has ever been observed on real hardware** — both boxes report `known`. The - fix's central path is unit-proven only; reproducing it live means making PBS unreadable, which must - not be done to ep0. -- **No R-88 backoff has ever armed on real hardware** (carried forward, unchanged). -- **R-97b's app-alarm suppression has never fired live** — it needs a real quiesce cycle. -- **The legacy-agent path is now unobservable on this fleet** — both agents are v0.105.0, so - Scenario C rests on tests alone from here. -- demo-felhom's first in-window scheduled backup lands 2026-07-28 at the earliest. +--- + +## F-A1 — a correct refusal reported as a failure + +HTTP 409 from `POST /backup` is the agent's R-85 single-flight gate refusing while a restore-test +holds it. The start path had no 409 branch, so it called `noteTierFailure`: breaker armed, +`whole_guest_backup_failed` emailed. At real cadences a ~12-minute restore-test against a daily +backup collides roughly once per 420 guest-days — about **every 4 days on a 100-guest fleet** — +training the operator to ignore the alarm and quietly undoing R-97a. + +409 is now contention: `agentapi` returns a typed `*StatusError` on POST (it was `fmt.Errorf`, i.e. +string-only), the adapter maps 409 → `quiesce.ErrTierBusy` at the same seam that maps 404 → +`ErrTiersUnsupported`, and the loop defers. No breaker, no event, no email; the tier stays **DUE**. + +### The two traps, and the bounds chosen + +**Silence.** "Just ignore 409" would let a wedged restore-test block backups forever with nobody +told. So contention outliving **`contentionAlarmAfter` = 3h** raises its own signal, headlined +**BLOCKED**, not FAILED. The bound is set by the agent's own ceiling, not taste: its PBS restore-test +task is capped at **120 minutes** (`config.RestoreTestPBSRestoreTimeout`, default 120m), after which +the agent times out and releases the gate itself — so contention outliving that is a *stuck* gate, +not a busy one. 3h adds an hour of margin for teardown and 5-minute poll granularity, and is 15× +the longest contention actually observed (12m01s). + +**App thrash.** Removing the failure treatment also removes the breaker's deferral, which had been +(accidentally) preventing a re-quiesce every 5 minutes. Without a replacement the customer's apps +would be stopped and restarted on **every poll** for the whole restore-test — worse than the bug. A +contended tier is therefore dropped from the due set **before anything stops**, on +**`contentionRetryAfter` = 15m** (longest observed restore-test 12m01s; the agent's local +restore-test wait is 10m), capping churn at 4/hour instead of 12/hour. + +--- + +## Red-proofs — all six observed failing + +| # | red-proof | observed failure | +|---|---|---| +| 1 | restore the unconditional `StateStopped` whitelist | `a stack that FAILED to restart is silent (Down=false) — this is F-CRIT-1` · `absent from the dashboard dead-list` | +| 2 | treat every `StateStopped` as a failed restart | `a deliberate user stop alarmed — that is the v0.164.0 regression this must not reintroduce` · `stopped alarmed with no failed restarts` | +| 3 | make `restartAll` drop its errors again | `restartAll returned [], want exactly [immich]` · `want immich to be recorded as a failed restart, got map[]` | +| 4 | remove the 409 branch | `runOnce: start backup on (untargeted): quiesce: tier busy — a concurrent heavy operation holds the agent: agentapi: POST /backup: HTTP 409` | +| 5 | treat all errors as contention | `breaker did not arm on a real 500 (failures=0) — a real 500 was swallowed as contention` · `operator was NOT notified of a real failure` | +| 6 | remove the contention alarm bound | `no alarm after 3h0m0s of unbroken contention — that is a silence path, the exact thing this fix must not create` | + +`go build`, `go vet ./...`, `go test ./...` — all green, run separately from the commit. +(Red-proof 6 first produced a *compile* error, which is a weaker proof; it was redone so the code +compiles and the alarm simply never fires.) + +--- + +## §5 — LIVE replay of BOTH findings on demo-hp, with the hub DB as arbiter + +### F-CRIT-1 +One image tag made unresolvable, then a normal quiesce: +``` +06:54:30 unquiescing (snapshotted (early resume, last tier)): restarting 1 stack(s) +06:54:36 [ERROR] [quiesce] restart paperless-ngx: starting stack paperless-ngx: exit code 1 + containers: 0 +``` +| moment | result | +|---|---| +| during grace (06:54:59) | 0 events, 0 banner markers, 0 pushes — **suppressed** | +| grace expiry | 06:54:30 + 180s = **06:57:30** | +| **06:57:39** | `PushEvent: type=app_start_failed severity=warn` → hub `Event from demo-hp: app_start_failed` | +| dashboard | `alert-icon … Telepített alkalmazás nem fut: Paperless-ngx (stopped)` | + +The banner names the `(stopped)` state explicitly — the whitelist was lifted, not bypassed. Nine +seconds after the window closed, on the first scan. + +### Scenario B live — the inverse, same box +The app was restored to healthy, then stopped **deliberately** via the UI path: +``` +containers after deliberate stop: 0 stack state: stopped +deadapp scans during the silent window: 9 +app_start_failed events for demo-hp TODAY (events table) = 1 ← still just the failed restart +``` +Same box, same `stopped` state, opposite outcomes — driven purely by whether the loop failed to +restart it. The 9 scans are the positive observable that the silence is suppression, not a dead +detector. + +### F-A1 +A restore-test was forced to hold the gate, then a backup triggered: +``` +agent: backup refused — a heavy operation is already in flight busy=restore-test (both tiers) +controller: tier local is BUSY — the agent refused ... This is contention, NOT a failure: + the tier stays due and retries in 15m0s (contended for 0s) +controller: tier felhom-pbs is BUSY — ... same +controller: unquiescing (last tier is busy — deferring to a later cycle): restarting 1 stack(s) +``` + +### Scenario G live — the inverse, same box, same event type +A **real** transport failure (PBS path dropped at nft, not a 409): +``` +07:41:47 [WARN] tier felhom-pbs: backup job ... failed +07:41:47 [WARN] tier felhom-pbs has now failed 1 time(s) in a row — deferring by 15m0s +07:41:47 [INFO] Event pushed: whole_guest_backup_failed (error) — Whole-guest backup FAILED on the felhom-pbs tier +``` + +### The hub DB, not the logs — the decisive numbers +| injection | `whole_guest_backup_failed` sent(operator), demo-hp | +|---|---| +| baseline before either replay | **8** | +| after the **409** contention replay | **8** — zero spurious emails | +| after the **real failure** (Scenario G) | **9** — fired 09:41:48 CEST | + +Breaker arming lines since deploy: **0** for the 409, **1** for the real failure. Same box, same +day, same event type; the only difference is 409 versus a genuine error. + +### Scenario F live +After contention cleared, the backup **ran and both tiers succeeded** (`tier local: done`, +`tier felhom-pbs: snapshotted`) — contention did not poison the tier. The armed breaker from +Scenario G was then cleared by a successful backup, with +`whole_guest_backup_recovered` emitted. + +--- + +## Deployed & fleet state + +`felhom-controller 0.179.0` on **demo-hp** and **demo-felhom**, both healthy. demo-felhom 15/15 +containers, demo-hp 8/8, zero unhealthy, no nft leftovers, cadences untouched +(`local 0`, `rt 302400`, `felhom-pbs 604800`), agent `0.106.0` on both. + +**demo-felhom had no injection and produced 0 event/alarm lines since its deploy** — the fix is not +chattering on an untouched box. + +One leftover of my own making was cleaned up: Scenario G's block failed a restore-test mid-flight, +which leaked scratch guest `990000` — the already-filed F-LEAK/R-99 behaviour (a failed restore-test +cannot destroy its own scratch guest, 403 `VM.Allocate`). Destroyed; `pct list` shows only 9201. + +## Comments corrected (three of the six catalogued) +- `classifyRunStates` I1 — now states what `StateStopped` actually means and names the quiesce path. +- `quiesce.go`'s "would record a spurious failure" — records that this was not hypothetical until now. +- agent `inflight.go`'s "a caller that cannot acquire DEFERS" — records that this was true of the + restore-test caller and not the backup caller; fixed controller-side. + +Standing rule added to **both** copies of `CLAUDE.md` (live + versioned): *a comment asserting an +invariant needs a test pinning it, or it is a wish*, with all six instances catalogued. + +## NOT yet live-validated (carried forward, minus what this closes) +- Fault 4 — restic transport interruption; four injection approaches defeated by guest-bridged + networking. **Still the most valuable follow-up**: F-CRIT-2 answered the phantom question for PBS + and it remains open for restic. +- **R-99** — prune never removes phantom snapshots (no retention bug; they accumulate). +- **F-LEAK** — a failed restore-test cannot destroy its own scratch guest; observed again here. +- Fault 12 (host reboot mid-backup); the three-way backup+restore-test+GC overlap; the agent's DR + bring-up path (`ModeDRGuestLoss`), still read-only-verified. +- `contentionAlarmAfter` (3h) itself — proven by unit test with an injected clock, **not** live; a + live proof needs a gate wedged for three hours.