docs: F-CRIT-1 + F-A1 — REPORT, CONTEXT (v0.179.0)
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.
This commit is contained in:
@@ -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**.
|
**Overwritten** per the standing rule. Controller **v0.178.0 → v0.179.0**. Both Campaign 8 findings,
|
||||||
**MinAgent: 0.105.0** — the `age_state` semantics. Deployed AFTER agent v0.105.0 on both boxes.
|
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 |
|
## F-CRIT-1 — a failed app restart never alarmed. Two independent causes.
|
||||||
|---|---|---|
|
|
||||||
| `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 |
|
|
||||||
|
|
||||||
**A missing field means LEGACY, not unknown.** Reading an old agent's silence as "unknown" looks
|
### Cause 1 — the outcome was thrown away
|
||||||
safer and regresses Scenario D: the valve would stop firing on every un-upgraded box, so a genuinely
|
`restartAll` returned nothing; a failed `StartStack` was logged and dropped on the spot, so no
|
||||||
new box would never take its first backup outside its window and nobody would notice for weeks. The
|
caller could learn a customer's app had not come back. It now **returns the stacks that failed**, and
|
||||||
MinAgent floor drives the upgrade; the valve is not the place to force it. Logged **once** per
|
both call sites (the cycle's unquiesce and crash recovery) record the result via
|
||||||
process (the `logTierDegradeOnce` shape). An unrecognised FUTURE value also maps to legacy — a newer
|
`noteRestartOutcome`.
|
||||||
agent inventing a fourth state must not inherit "unknown" semantics from a controller that has never
|
|
||||||
heard of it.
|
|
||||||
|
|
||||||
**Untouched, as required:** the R-88 Part 1 breaker and its timings, `dropBackedOffTiers`, the window
|
### Cause 2 — a documented invariant the quiesce path had made false
|
||||||
bounds, and `TriggerNow` (still ungated by everything).
|
`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`
|
```go
|
||||||
(`l.backend.(TieredBackend)`), not at compile time. When `DueFor`'s signature changed, the whole repo
|
userStopped := st.State == stacks.StateStopped && !failedRestart[st.Name]
|
||||||
**built and vetted clean** while `quiesceBackend` silently stopped satisfying the interface. That
|
down := stacks.IsDownState(st.State) && !userStopped && !quiesced[st.Name]
|
||||||
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
|
|
||||||
```
|
```
|
||||||
|
|
||||||
**And the gate is demonstrably working on a known age:** `local` is genuinely due (25.3 h against a
|
The flag is only ever consulted for an already-down stack, so a stale entry cannot manufacture an
|
||||||
24 h cadence) at 18:11 Budapest — outside `[04:30, 08:30)` and well under the 48 h valve threshold —
|
alarm on a healthy app; it clears the moment a later restart of that stack succeeds.
|
||||||
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.
|
|
||||||
|
|
||||||
## 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.
|
## F-A1 — a correct refusal reported as a failure
|
||||||
- **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.
|
HTTP 409 from `POST /backup` is the agent's R-85 single-flight gate refusing while a restore-test
|
||||||
- **The legacy-agent path is now unobservable on this fleet** — both agents are v0.105.0, so
|
holds it. The start path had no 409 branch, so it called `noteTierFailure`: breaker armed,
|
||||||
Scenario C rests on tests alone from here.
|
`whole_guest_backup_failed` emailed. At real cadences a ~12-minute restore-test against a daily
|
||||||
- demo-felhom's first in-window scheduled backup lands 2026-07-28 at the earliest.
|
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.
|
||||||
|
|||||||
Reference in New Issue
Block a user