diff --git a/CONTEXT.md b/CONTEXT.md index 8ca3e08..a16458f 100644 --- a/CONTEXT.md +++ b/CONTEXT.md @@ -7,7 +7,22 @@ > > Ask Claude Code: "Please update CONTEXT.md with what we did today" -Last updated: 2026-07-26 (v0.173.0 — R-77 endpoint-drift detection + samba gate + channel log honesty) +Last updated: 2026-07-28 (v0.180.0 — F-OBS: the dead-app check gets a positive observable) + +> **2026-07-28 — v0.180.0 (F-OBS).** Source: `audits/CAMPAIGN-8-backup-restore-2026-07-27.md`. +> On a default `logging.level: info` box there was **no positive observable that `deadapp-check` had +> run**: its per-cycle line goes through `Scheduler.dbg()`, gated on `level==debug`, so on a default +> box it was never *produced* and could not even reach the always-DEBUG ring. "No alarms" was +> therefore indistinguishable from "the detector never ran" — standing rule 3's exact fallacy, and it +> undermines F-CRIT-1's fix, which is a fix to **this same detector**. +> `noteDeadAppScan()` now emits an INFO line every **20th** scan (10 min at the 30 s cadence) carrying +> scans-since-boot / evaluated / currently-down. It reports **what it saw**, not that it ran, and it +> summarises rather than floods — one line per run is 2880/day, which is what made silence attractive +> in the first place. Both bounds are pinned by test in the direction that would break them. +> **The same shape then turned up in the agent's brand-new guest-power watchdog** (v0.107.0, shipped +> hours earlier): it logged only at startup and when it acted. Fixed in agent v0.109.0 with the same +> pattern. The anti-pattern reproduces itself — which is the argument for not having dropped this part. +> Live on demo-hp at INFO on a default-level box; deployed on both boxes. Detail: `REPORT.md`. > **2026-07-26 — v0.173.0 (R-77).** Source: `audits/DIAG-agent-channel-2026-07-26.md`. > diff --git a/REPORT.md b/REPORT.md index a6d13f7..12c9529 100644 --- a/REPORT.md +++ b/REPORT.md @@ -1,193 +1,111 @@ -# REPORT — F-CRIT-1 + F-A1: one alarm that never fired, one that fired wrongly (v0.179.0) (2026-07-28) +# REPORT — F-OBS: the dead-app check gets a positive observable (v0.180.0) (2026-07-28) -**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). +**Overwritten** per the standing rule. Controller **v0.179.0 → v0.180.0**. One Campaign 8 finding, +the smallest of the three in this task's scope — and the one the task marked droppable. It was not +dropped, because it is what makes the *other two* fixes trustworthy in the field. + +Companions this session: `felhom-agent` v0.107.0 → v0.109.0 (F-REBOOT) and `felhom.eu` host-install +v1.21.0 (F-LEAK). No wire/contract change here; no agent change required. ## 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. +Controller `0.179.0` live on both boxes at start; agent `0.106.0`; `felhom-controller fb91c8d`, +`felhom-agent af1c21a`, `felhom.eu d0cec9d`, all clean. --- -## F-CRIT-1 — a failed app restart never alarmed. Two independent causes. +## The finding -### 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`. +On a default `logging.level: info` box there was **no positive observable that `deadapp-check` had +run**. Its per-cycle scheduler line goes through `Scheduler.dbg()`, which is gated on +`logging.level == debug` — so on a default box the line was never *produced* and therefore could not +even reach the always-DEBUG ring. A 30 s interval also puts the job on the scheduler's quiet path. -### 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. +So **"no alarms" was indistinguishable from "the detector never ran"**. That is exactly the fallacy +this project has a standing rule against (rule 3: an absent log line is not evidence of correct +behaviour), and it directly undermines confidence in F-CRIT-1's fix — which is a fix to *this same +detector*. Without an observable, the only field evidence that F-CRIT-1 works would be silence. -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: +## The fix -```go -userStopped := st.State == stacks.StateStopped && !failedRestart[st.Name] -down := stacks.IsDownState(st.State) && !userStopped && !quiesced[st.Name] +`noteDeadAppScan(logger, scans, evaluated, down)` — a pure, separately testable function emitting an +**INFO** line every **20th** scan (`deadAppHeartbeatEvery`), i.e. every 10 minutes at the job's 30 s +cadence: + +``` +[INFO] [deadapp] check alive — N scans since boot, M evaluated, D currently down ``` -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. +Two things it deliberately does: -### 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. +- **Carries what it saw, not that it ran.** An operator needs to separate "running, everything up" + from "running, 2 apps down". A bare liveness ping cannot express the second, and the second is the + interesting state. +- **Summarises rather than floods.** One line per run is 2880/day, which is precisely the pressure + that made silence attractive to the original author — so a fix that floods is not a fix. ---- +The function is pure and takes the logger as a parameter specifically so the *emitted line* can be +asserted. The original mistake was invisible because it lived inline with nothing pinning its output. -## 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-proofs — all 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` | +| 1 | delete the `logger.Printf` (or the whole call from the job closure) | `no observable emitted at scan 20 — silence is indistinguishable from not running` | +| 2 | change the guard to `scans%1 != 0` (emit every run) | `emitted 60 lines across 60 scans — that is the flood that made silence attractive` | -`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.) +Two further tests are tripwires rather than red-proofs: the observable must be at **INFO** (a +`logging.level: info` box would otherwise never see it) and the cadence must stay inside 15 minutes, +so a stalled detector is obvious well within the 180 s alarm grace this check feeds. Off-cadence scans +must stay quiet, and a nil logger must not panic — the job closure has no recovery. + +`go build`, `go vet ./...`, `go test ./...` — green, run separately from the commit. --- -## §5 — LIVE replay of BOTH findings on demo-hp, with the hub DB as arbiter +## Live, on demo-hp -### 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)` | +Endpoint-level/journal method (no browser on DooPlex, per the standing constraint): -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) +[INFO] [deadapp] check alive — 20 scans since boot, 5 evaluated, 0 currently down ``` -### 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 -``` +Present at **INFO** on a box whose `logging.level` is the default `info` — which is the whole point, +and the thing the previous behaviour could not do. The same observable is what let F-CRIT-1's Scenario +B replay earlier today assert *"9 dead-app scans during the silent window"* rather than merely +*"nothing was logged"*: the silence was proven to be suppression, not a dead detector. -### 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 | +**demo-felhom** received the same deploy with no injection and is quiet apart from its own heartbeat — +the fix is not chattering on an untouched box. -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. +## The same shape, found in my own new code + +Applying this finding's check to the agent's brand-new guest-power watchdog (shipped hours earlier in +`felhom-agent` v0.107.0) showed it had **exactly this defect**: it logged at startup and when it +*acted*, and was otherwise silent, so its health could only be inferred from absence. Fixed in agent +**v0.109.0** with the same pattern (INFO summary every 10th sweep, carrying what it saw, aborted sweeps +not counted). Detail in `felhom-agent/REPORT.md`. + +That is the argument for not dropping this part: the anti-pattern reproduces itself, and the fix is +what makes it visible. --- ## Deployed & fleet state +`felhom-controller` **0.180.0** on **demo-hp** (`Up, healthy`) and **demo-felhom**, both healthy. +Cadences untouched. Agent **0.109.0** on both boxes. -`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. +## NOT yet live-validated (carried forward) +- **Fault 4** — restic transport interruption; four injection approaches defeated by guest-bridged + networking. Still the most valuable follow-up. +- **R-100** (new, filed today) — a restic offsite tier that fails nightly never goes stale on the hub: + `isStale` reads only `LastRun` (`hub/internal/monitor/offsite.go:120`), which the controller writes + **unconditionally** on failure (`controller/internal/backup/offbox.go:716`). F-CRIT-2's defect class, + one layer up. Investigated, deliberately **not** fixed. - **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 +- `contentionAlarmAfter` (3h) — unit-tested with an injected clock, **not** live; a live proof needs a + gate wedged for three hours. +- 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.