admin/felhom-controller
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

REPORT + CONTEXT: F-OBS shipped (v0.180.0); same shape found and fixed in the agent watchdog

Browse Source
This commit is contained in:
authentik Default Admin
2026-07-28 11:22:04 +02:00
parent fb91c8d766
commit 4056feccee
2 changed files with 90 additions and 157 deletions
Download Patch File Download Diff File Expand all files Collapse all files
CONTEXT.md
+16 -1
View File
@@ -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`.
>
REPORT.md
+73 -155
View File
@@ -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.
- `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.