diff --git a/CHANGELOG.md b/CHANGELOG.md index c897d3f..f5b1c96 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,86 @@ +## v0.224.0 — the backup alarmed about the apps it was holding down (2026-08-30, R-330) +**MinAgent: 0.129.0** (unchanged — no new agent coupling) + +### R-330 — 61 e-mails about apps that were never broken + +**Measured live on `demo-hp` 2026-08-30, controller 0.223.0.** Every night both demo boxes e-mailed +the customer `app_start_failed — "Telepitett alkalmazas nem fut: "` about healthy apps. Both +bursts were the box's own backup: + +| leg (UTC) | window | events | +|---|---|---| +| `db-dump` 00:30 | W (02:30 CEST) | Docmost, Paperless-ngx, RomM | +| `offbox-backup` 02:15 | W+105m (04:15 CEST) | Docmost, Paperless-ngx | + +`DumpAppVolumesSafe` stops a stack (`docker compose down`), tars its volumes and starts it again — +**~13 s per stack, measured** — while `deadapp-check` scans every **30 s**. The scan caught whichever +stack was mid-cycle. Every other scan that day logged `0 currently down`, and the same night's +`[offbox] backup OK: 8 app(s) backed up, 67 snapshot(s)` proves the backup itself was healthy. + +**The defect is not a missing mechanism — it is a mechanism that was never consulted.** +`quiesce/suppress.go` solved exactly this in v0.179.0 (R-97b) and works. But `classifyRunStates` read +only `Loop.SuppressedStacks()`, and the quiesce loop covers the **whole-guest** (vzdump/PBS) backup. +The **per-app** legs stop stacks through `Manager.DumpAppVolumesSafe`, which registered with nothing. +Two mechanisms in this product stop a customer's app on purpose; only one told the alarm. That is the +**"seam built but never wired"** class, and this is its fifth instance — the first where the unwired +half was a *consumer* rather than a producer. + +**The fix sits on `AppStopGuard`, not in a fourth registry.** The guard already brackets every +deliberate stop in the product — `Begin` before the stop, `End` after a successful restart — at all +three call sites (volume dump, off-site reconstitute, `.fab` export), and `main.go` hands the SAME +guard object to the backup manager and the exporter. The fact the alarm needs already existed there +with exactly one writer. `scanDeployedAppRunStates` now takes the union of both suppression sets. + +**All three per-app stop paths are covered by the one change**, not just the nightly one that was +reported. A `.fab` export and an off-site restore stop an app the same way and would alarm the same +way; fixing only the observed leg would have left two loaded guns. + +### It must never latch — the harder half + +Permanent suppression trades a loud false alarm for a silent real one, which is F-CRIT-1 and R-88 +Scenario D over again. `AppStopGuard.End()` runs **only on a restart that succeeded**, so an +open-ended hold is a real hazard here in a way it is not for the quiesce loop, which always releases. +Three independent things stop the window latching: + +1. **`ReleaseFailed`** — a restart that was ATTEMPTED AND BROKE drops the entry **immediately**, so + the app alarms on the very next scan with no delay at all. Wired at every failure path: the volume + dump, the off-site reconstitution's `restartStack`, and the exporter's restart defer (the seam + interface grew the method rather than the exporter keeping its own bookkeeping). +2. **`Begin` REPLACES the set.** The marker file holds one operation, so a new `Begin` proves the + previous one is over; a set stranded by an operation that died mid-window cannot survive into a + later one. +3. **`appStopMaxHold` (6 h)** — a backstop for a hold nothing ever released, logged at WARN when it + fires. Longer than any real hold (13 s dump, minutes for an export, hours at the outside for a + multi-gigabyte reconstitution) and far shorter than "forever". Exceeding it means something is + wrong, and the right answer when something is wrong is to let the alarm through. + +The grace after a successful restart is **180 s, deliberately the same constant as +`quiesce.quiesceAlarmGrace`** and by the same derivation (120 s deploy health timeout; Mealie's 60 s +`start_period` plus check intervals). Two suppression windows over one alarm that disagreed on how +long a restart takes would be a bug waiting to be found on whichever path used the shorter one. + +**The suppression is deliberately NOT persisted.** After a crash the guard holds nothing: `Recover()` +either brings the apps back or leaves them genuinely down, and a down app must alarm. Reviving a +suppression across a restart would silence the exact case the alarm exists for. The durable crash +marker is untouched by all of this and stays the recovery record — `ReleaseFailed` drops the +suppression and **keeps** the marker, and a test pins that. + +### Tests, and what each red-proof actually printed + +`internal/backup/appstop_suppress_test.go` drives the **real** `DumpAppVolumesSafe` and asserts the +suppression set the dead-app scanner actually reads — the consequence, not a log line. Three +red-proofs were run and are recorded in `REPORT.md`: + +- deleting `markStopped` from `Begin` → `suppressed at stop = map[]`, the exact pre-fix shape; +- deleting `ReleaseFailed` from the volume dump → `suppressed = map[bookstack:true] after a restart + that FAILED`; +- passing `nil` instead of `appStopGuard` in `main.go` → the AST wiring test fails. + +That third one is the point: the component was never the broken part, so a test that only injects it +directly would have passed against the shipped defect. `cmd/controller/r330_backup_suppression_test.go` +walks main.go's AST rather than matching a string, because a commented-out call satisfies +`strings.Contains` — a sibling test in that package records paying for exactly that. + ## v0.223.0 — the alarm we had just built reached nobody, and the stop nobody heard (2026-08-23, R-329 + R-386) **MinAgent: 0.129.0** (unchanged — no new agent coupling) diff --git a/REPORT.md b/REPORT.md index 04c079a..7bbb2cc 100644 --- a/REPORT.md +++ b/REPORT.md @@ -1,278 +1,179 @@ -# REPORT — controller v0.223.0 (R-329, R-386, and the compound toggles) +# REPORT — R-330: the nightly backup alarmed about the apps it was holding down -**Session 2026-08-23, UNATTENDED.** Live leg on `demo-hp` (Tier 0), guest 9201. -**No halt condition fired.** Nothing was dropped. +**Controller v0.224.0 · 2026-08-30 · implemented on DooPlex, diagnosed live on `demo-hp`** -## 1. Baselines, and the hub's four numbers as read +This report covers Option A of a two-part request. Option B (the hub Backup card that always reads +`Snapshots 0`) is a separate, still-open defect and is described in §7. -| Repo | at start | at end | +--- + +## 1. What was reported + +61 e-mails, arriving in two bursts every night from both demo boxes: + +``` +[Felhom] demo-hp: app_start_failed +Severity: warning +Time: 2026-08-30 02:30 CEST +Message: Telepített alkalmazás nem fut: Docmost +``` + +## 2. What was actually happening + +**Nothing was broken.** Both boxes were healthy at every check: + +| | `demo-felhom` (N100) | `demo-hp` (HP t740) | |---|---|---| -| felhom-controller | `14137efa` (v0.222.0) | **v0.223.0** deployed | -| felhom.eu | `55274d5e` (hub v0.106.0) | **hub v0.107.0** deployed | -| felhom-agent | `40d857b5` (v0.130.0) | untouched | +| host uptime | 20 d | 8 d 23 h | +| agent | 0.130.0, `active` | 0.130.0, `active` | +| controller | 0.223.0 | 0.223.0 | +| containers | 1/1 | **16/16, all `healthy`** | +| SMART, all disks | PASSED | PASSED | +| `journalctl -u felhom-agent -p warning`, 3 days | no entries | no entries | +| hub health | `ok` | `ok` | -**Hub's four numbers, live from `GET /configuration` before starting:** `golden_version` **0.222.0**, -`agent_version` **0.130.0**, `min_agent` **0.129.0**, controller floor **0.222.0** — all four as the -task predicted. +The alarms are the box's own backup. Both bursts line up exactly with the nightly legs +(`backupwindow`: DB dump at W, tier-2 at W+60m, off-box at W+105m; default W = 02:30 CEST): -## 2. Documents read - -`internal/notify/notifier.go:583-602` (`Severity()`'s doc comment — **it already stated the entire -contract and named both hub locations**), `hub/internal/api/handler.go` (the type rejection and the -severity coercion side by side), `hub/internal/notify/dispatcher.go` (`severityNotifies`, -`ProcessEvent`, `operatorOnlyEvents`, `processOperator`), `internal/stacks/deploy.go` (the -`DesiredState` comment and its one-owner rule), `cmd/controller/main.go` (`classifyRunStates`), -`internal/web/handlers.go` (the compound toggles). - -**§2's conditional is answered: the alarm ladder DOES exist** — -`felhom.eu/documentation/architecture/08-alarm-ladder.md`, written last session. It has been extended -here with §6.1 (the severity contract), §7 (the intent test) and §8 (Part 5's direction). - -## 3. The 1.1 sweep — the result in full - -**Exactly ONE bad severity in the whole controller: `notifier.go:546`, `"warn"`.** Nothing else. - -Verified across Go **and** templates **and** queued-event construction, because the task warned that -reading zero from Go files while the answer sat in a template has produced three wrong conclusions -here: - -- every `emit(...)` / `PushEvent(...)` literal — one offender, the rest valid; -- `internal/channelhealth`'s classifier (the source of `NotifyAgentChannelDown`'s variable) — all - `"warning"`/`"error"`; -- `debug.html`'s operator-triggerable severity `` -spans **three lines**, so a single-line grep read it as `""`. **Both times the hashes matched — -because nothing was saved, not because nothing changed.** Fixed by asserting the refusal banner is -absent. *A warning beside a success is read as a success.* +1. Delete `g.markStopped(stackNames)` from `Begin` → + `suppressed at stop = map[], want bookstack` — the exact shape that produced the e-mails. + (`TestVolumeDump_SuppressionExpires…` and `TestSuppression_CannotOutlive…` also went red.) +2. Delete `m.appStop.ReleaseFailed(stackName)` from the volume dump → + `suppressed = map[bookstack:true] after a restart that FAILED`. +3. Pass `nil` instead of `appStopGuard` in `main.go` → the AST wiring test failed. -### Step 6 — Scenario H: a bad severity to the hub ✅ +Each was restored immediately and `git diff` verified clean afterwards. Red-proof 3 is the load-bearing +one: the component was never the broken part, so a suite that only injected it would have been green +against the shipped defect. -``` -[WARN] [api] Event from demo-hp: severity "warn" is not in {info,warning,error,critical} — coercing -to "info", which severityNotifies DROPS, so this backup_failed alert will reach NOBODY. Fix the -emitting controller; this event is stored but not routed. -``` +**Green gate:** `go build ./... && go vet ./... && go test ./...` in `felhom-controller/controller/` — +clean, no failures. -Both the bad POST and an `error` control returned **200** (nothing lost); the control produced **no** -warning. +## 6. Not done, and why -## 10. The absent-intent count on `demo-hp`, in plain words +- **No live deploy yet.** The build/deploy of 0.224.0 to the two boxes is the next step and is + reported separately; this report covers the change and its unit-land proof only. +- **The `restore-hold` path** (`offbox_reconstitute.go`, an app deliberately held down after a failed + replay) calls `End()`, so it gets the 180 s grace and then alarms. That is **today's behaviour plus + 180 s** and is deliberate: the app really is down, the customer should learn that, and the hold has + its own operator notification (`restoreHoldNotify`) besides. +- **`HeldStacks()` was left alone.** It reads the marker from disk for the boot reconciler and covers + "held right now" but not the post-restart grace — which is precisely the window R-97b proved is + needed. The new in-memory set is a superset for alarm purposes; the durable one stays the recovery + record. -**Zero.** All **8** deployed apps carry `desired_state: running`; none is `stopped` and none is absent. -The unknown-intent fallback therefore suppresses nothing on this box today — the population is already -empty on a machine that has been exercised through the interface. It will be larger on a box upgraded -and left alone, which is why the log line exists rather than a one-off count. +## 7. Found while diagnosing — a second, still-open defect (Option B) -## 11. The dead-branch decision, and the reason +**The hub's customer Backup card is inert for every customer.** It reads +`Snapshots 0 · Repo Size 0 MB · Integrity Unknown` while the same box's log says +`[offbox] backup OK: 8 app(s) backed up, 67 snapshot(s)`. -**KEPT.** `cmd/hub/main.go` wires `dispatcher.ProcessEvent` **directly** as the -`monitor.EventNotifyFunc` for the staleness, host-staleness and offsite-box checkers — those events -never pass the ingest handler, so for them that line is the only severity guard there is. Deleting it -as "dead" would have removed the live half while the dead half supplied the justification. All 90 -severity literals in `internal/monitor` were verified already valid, so the guard is silent because -the producers are correct. +`hub/internal/web/templates/customer_unified.html:284` renders `snapshot_count` / `repo_size_mb` / +`integrity_ok` from the report. Those fields are **declared** in +`controller/internal/report/types.go:105-108` and **assigned nowhere** — a repo-wide grep finds only +the declaration. The controller tracks the real numbers in `internal/backup/offbox.go` (`SnapshotCount`, +line 1043) and serves them on its own API (`internal/web/offbox_handlers.go:295`); they are simply +never copied into the hub report. -## 12. Evidence +**Until it is fixed, that card must not be read as evidence of a missing backup.** It is a two-repo +change (controller report builder + hub) and is Option B of this request. -`felhom.eu/documentation/audits/DRILL-r329-r386-2026-08-23/evidence/` — 26 files: 5 red-proof -transcripts, 20 live-walk files, two full controller-log windows (1041 and 4044 lines) **pulled off -before each revert**, and the hub's own DB queries. +## 8. Also observed (not changed) -## 13. Teardown, three layers, and the end state - -1. **Guest 9201 / apps** — nothing provisioned. **All 17 app containers healthy.** `privatebin`'s - `app.yaml` restored from backup and the backup deleted; intent reads `running`. `demo-hp`'s - notification settings restored to `enabled_events: null`, no e-mail — their pre-drill state. No app - rebuilt, redeployed or restored; planted data untouched. -2. **Bake VM** — powered off, Gitea token and runner script **shredded**, `drill.qcow2` reverted to - `virgin`. Build guest 9100 exists only inside that reverted snapshot. No storage added anywhere, so - `pvesm status` has nothing to compare. -3. **Hub-side, stated explicitly.** The hub was **written** this session, unlike last: the deployment - is v0.107.0 via the manifest, and **two probe events remain as rows for `demo-hp`** from Scenario H - (`backup_failed`, "R-387 scenario H probe" and "…control"). They are inert records; named here - rather than left for someone to find. Nothing else: no appliance registered, no customer created, - no artifact manifest changed, floor untouched. - -**End state:** controller **0.223.0** and hub **0.107.0** deployed; golden **0.223.0** baked and -published but **NOT vouched**; floor still **0.222.0**; all apps running; planted data present. - -## 14. Register size - -| File | Before | After | -|---|---|---| -| `OPEN-ITEMS.md` | 328,325 B | **328,132 B** | -| `CLOSED-ITEMS.md` | 71,441 B | **74,642 B** | - -R-329 and R-386 closed and compressed; **R-387** (closed) and **R-388** (the notification-model -product decision — open, operator's call) filed. - -## 15. Observations - -> **Each item carries `FILED: R-NNN` or `NOT-A-FINDING: ` (gate 11, added 2026-08-23).** -> The markers were added retrospectively on 2026-08-24 when the gate was built: item 1 was the very -> finding that had no row, and adding its marker is the first thing the gate ever asked for. The -> observations' text is unchanged. - -1. **The operator cooldown key has no app identifier, and it now bites.** PrivateBin's alarm four - minutes after BookStack's was logged `suppressed — operator cooldown 1h, - key=demo-hp:app_start_failed`, so **only the first app-down per hour e-mails the operator**. This is - R-182's known cooldown-key shape; it was harmless while `app_start_failed` was undeliverable and is - not any more. **Same pattern as R-329 itself: a known-broken thing moved from unreachable to - load-bearing.** Not fixed here. - FILED: R-389 -2. **The settings page grew 12 → 15 toggles in one session** — one new alarm, plus two compound - toggles split into four. Recorded as the argument inside R-388. - FILED: R-388 -3. `internal/notify/notifier.go` carries **pre-existing** gofmt drift in an unrelated const block, - confirmed by stashing this session's work and re-running `gofmt -l`. Not touched (§12). - NOT-A-FINDING: cosmetic drift in an unrelated const block, predating this work and touching no - behaviour; §12 forbids nearby refactors, so filing a row would only queue a whitespace commit. -4. **The golden-bake runbook still lacks `pveam update`** — second consecutive bake to hit the stale - index on the `virgin` snapshot, presenting as `400 … no such template`. - FILED: R-390 -5. **Deliberately left open, untouched:** R-102, R-359, R-385, and R-388's redesign. - NOT-A-FINDING: this item is a pointer to rows that already exist, not a new observation; it is - here so their absence from this session reads as deliberate rather than forgotten. - -### CI runs, confirmed by ID - -| Commit | Repo | CI `id` | `run_number` | Result | -|---|---|---|---|---| -| `9832760` | felhom-controller | **408** | 88 | success | -| `68a9f54` | felhom.eu | **409** | 261 | success | -| `2f7c9a6` | felhom.eu | **410** | 262 | success | - -(The controller docs commit's run is confirmed after its push and is the next `id` in that repo.) +- **`ssh demo-hp` no longer works** — the tailnet peer `100.76.96.79` has been offline 8 days + (`tailscale status`: `offline, last seen 8d ago`). The box is reachable on the home LAN as + `ssh hp` → `192.168.0.104`, which is what every command in this report used. +- **`drill-r50-0a4f9a` still appears in the hub host list as `DOWN`** — a leftover record from the + R-50 drill whose rig was torn down; not a live box. diff --git a/REUSE.md b/REUSE.md index 2a783a5..3d3c613 100644 --- a/REUSE.md +++ b/REUSE.md @@ -83,7 +83,7 @@ | `quiesce.TieredBackend` + `Loop.resolveDueTiers` / `quiesceAndPollTiers` | controller/internal/quiesce/tiers.go, quiesce.go | `Tiers/DueFor/StartBackupFor/BackupStatusFor`; `resolveDueTiers(ctx) ([]dueTier,bool,error)` | THE R-82 multi-tier backup schedule — several whole-guest tiers (local daily + PBS weekly) reconciled into ONE quiesce window | **Both tiers due ⇒ ONE stop/start pair**, never two (two = two app outages for one night). Tiers run SEQUENTIALLY (vzdump holds a guest lock) and the app stays down until the LAST tier snapshots — resuming earlier loses app-consistency on the DR tier. Order is fast-first (agent advertises primary first) or downtime blows up. `ErrTiersUnsupported` (route 404) ⇒ pre-R-82 agent ⇒ degrade to the untargeted path and **STILL BACK UP** — never read it as "nothing due". | | `quiesce.failureBreaker` + `Loop.dropBackedOffTiers` / `noteTierFailure` / `noteTierSuccess` | controller/internal/quiesce/breaker.go, quiesce.go | `blocked/recordFailure/recordSuccess(target, now)`; `backoffFor(n) time.Duration` | **R-88** — a tier whose backups keep failing stops re-quiescing. Backoff 15m→30m→1h→2h→4h (cap), reset on success | **It gates the QUIESCE, not the backup** — the harm was never the failing backup, it was the app outage taken to attempt it, so backed-off tiers are dropped from the due set BEFORE any stack is stopped. **Per TARGET** — a broken offsite tier must never suppress a healthy local one (`TestBreaker_OneFailingTierDoesNotSuppressAHealthyOne`). **Never permanent** — the cap bounds the retry INTERVAL, it never stops retrying; a latched breaker is a silent backup outage, worse than the loop it replaces. **`TriggerNow` is never gated** (it already bypasses due-ness and the window gate), though a manual run still RECORDS its outcome. **`stillRunning` is NOT a failure** — a first full offsite snapshot legitimately runs for hours. State is **in-memory on purpose**: a restart forgets the backoff and re-attempts, which is the cheap direction to fail. Log the deferral ONCE when armed, never per tick. | | `quiesce.TierNotifier` + `Loop.SetTierNotifier` / `noteTierFailure` / `noteTierSuccess` | controller/internal/quiesce/breaker.go, quiesce.go | `BackupFailed(tier,msg,err)` / `BackupRecovered(tier,msg)`; `SetTierNotifier(n)` INIT-ONLY | **R-97a** — the whole-guest backup tier reports its outcome to the hub | A **seam, not an import** — quiesce keeps no dependency on `internal/notify` (same reason `windowStartFn` is injected). Wired by a setter because main.go builds the notifier AFTER the loop; `nil` = unprovisioned guest, not an error. **Edge-triggered:** failure fires only when the breaker ARMS (`n == 1`), never per retry — the cadence is 15m/30m/1h/2h/4h and an event per attempt is an inbox nobody reads. Recovery rides `recordSuccess`'s existing bool. **Event types are OPERATOR-ONLY** (`whole_guest_backup_failed`/`_recovered`, hub >= v0.78.0) — NOT `backup_failed`, which has a customerMessages entry AND sits in live `enabled_events`, so it would email the CUSTOMER about a backup they cannot act on. `WholeGuestBackupDetails.Tier` is load-bearing: the hub keys its per-tier cooldown on it. | -| `quiesce.Loop.SuppressedStacks` + `markQuiesced` / `markUnquiesced` | controller/internal/quiesce/suppress.go | `() map[string]bool` (nil-safe on a nil *Loop) | **R-97b** — an app THIS controller stopped for a backup is not a fault | Consumed at the SINGLE derivation point `classifyRunStates` (which computes both the banner dead-list and the notifier Down-set — keep it one place). **Cycle-keyed, not state-based:** v0.164.0's `!= StateStopped` filter cannot see an app caught MID-RESTART (`starting`/`unhealthy`), which is how BookStack alarmed on 2026-07-27. The window (`quiesceAlarmGrace` = 180 s, derived from the deploy flow's 120 s health timeout and Mealie's 60 s start_period) **EXPIRES** — permanent suppression turns a loud false alarm into a silent real one. Open-ended while the cycle runs (a first offsite snapshot legitimately takes hours). | +| `quiesce.Loop.SuppressedStacks` + `markQuiesced` / `markUnquiesced` | controller/internal/quiesce/suppress.go | `() map[string]bool` (nil-safe on a nil *Loop) | **R-97b** — an app THIS controller stopped for a backup is not a fault | Consumed at the SINGLE derivation point `classifyRunStates` (which computes both the banner dead-list and the notifier Down-set — keep it one place). **Cycle-keyed, not state-based:** v0.164.0's `!= StateStopped` filter cannot see an app caught MID-RESTART (`starting`/`unhealthy`), which is how BookStack alarmed on 2026-07-27. The window (`quiesceAlarmGrace` = 180 s, derived from the deploy flow's 120 s health timeout and Mealie's 60 s start_period) **EXPIRES** — permanent suppression turns a loud false alarm into a silent real one. Open-ended while the cycle runs (a first offsite snapshot legitimately takes hours). **This set alone is NOT the whole answer** — see `AppStopGuard.SuppressedStacks` (R-330) for the per-app operations; `classifyRunStates` consumes the union of both. | | `agentapi.BackupTiers` / `BackupDueFor` / `StartBackupFor` / `BackupStatusFor` | controller/internal/agentapi/backup_tiers.go | `(ctx[, target]) (…, error)` | The per-tier agent surface (agent >= v0.97.0) | `targetQuery("")` returns an EMPTY suffix so an untargeted call hits the pre-R-82 route byte-for-byte. `BackupTiers` maps a 404 to `ErrTiersUnsupported` — the documented ROUTE-PROBE capability signal, NOT a `featureProbes` row (the loop needs the tier LIST, not a yes/no). | ### Compose ops / stack lifecycle @@ -101,6 +101,7 @@ | `bootrecon.StartGate` (R-171, v0.190.0) | controller/internal/bootrecon/bootrecon.go | `MayStart(stack) (bool, reason)` | THE one question the boot sweep asks before starting anything | **Fail-safe: cannot determine ⇒ return FALSE.** One seam for all three holders (absent drive · quiesce · an in-flight app-data operation) because they differ only in the reason string. Implemented in `main.go` (`bootDriveGate`) reusing `quiesce.SuppressedStacks()`, `AppStopGuard.HeldStacks()` and `Manager.DriveLive` — never re-derive any of them. Held apps go to `Result.HeldByDrive`, **never** `StillDown` (that is the dead-app alarm's bucket) | | the boot settle window (R-157 A, v0.190.0) | controller/cmd/controller/main.go | `bootReconcileSample` / `StableFor` / `Budget` | sample the fleet until it stops changing, then sweep ONCE | **settle + budget + one `DefaultRetryDelay` must stay under `deadAppBootGrace`** — pinned by `TestBootWindow_CommonCaseFitsInsideTheDeadAppGrace`, which is why the budget is 50 s and not 60 s. Sampling is READ-ONLY; sweeping per sample would never see a settled fleet (the sweep's own StartStack changes it). A late recovery is REPORTED (`recordLateRecovery`), never hidden by widening the grace | | `backup.AppStopGuard` (`Begin`/`End`/`Recover`) (R-166, v0.189.0) | controller/internal/backup/appstop_marker.go | `(opID, reason, stacks) error` / `()` / `() *AppStopRecovery` | THE crash marker for stop→work→start windows (volume dump, offbox reconstitute, `.fab` export) | Its **own** file (`appstop-state.json`), never quiesce's — one file, one writer. **A `defer` is NOT the mechanism** (Campaign 8 fault 10: SIGKILL runs no defer); the marker is. Written BEFORE the stop, cleared ONLY after a restart that succeeded; a FAILED restart deliberately KEEPS it. `Recover` RETURNS its outcome rather than notifying, because it must complete before the boot reconciler while the notifier does not exist yet | +| `backup.AppStopGuard.SuppressedStacks` + `markStopped` / `releaseStarted` / `ReleaseFailed` (R-330, v0.224.0) | controller/internal/backup/appstop_suppress.go | `() map[string]bool` (nil-safe on a nil *AppStopGuard); `ReleaseFailed(stacks ...string)` | **R-330** — an app a PER-APP operation is holding stopped (nightly volume dump, offbox reconstitute, `.fab` export) is not a fault | The **twin** of `quiesce.Loop.SuppressedStacks` above, and the two are unioned by `unionSuppressed` in main.go before `classifyRunStates` — **consult BOTH or the bug comes back**: R-330 shipped because the alarm read only the quiesce set while the per-app legs stopped apps through a different path. Rides `Begin`/`End`, so all three call sites got it with no call-site change. Grace is `appStopAlarmGrace` = 180 s, deliberately the SAME constant and derivation as quiesce's — two windows over one alarm that disagreed would be a bug on whichever path used the shorter one. **It must never latch**, and unlike quiesce's loop `End()` runs ONLY on a restart that succeeded: (1) every failure path calls `ReleaseFailed`, which drops the entry IMMEDIATELY so the app alarms on the next scan; (2) `Begin` REPLACES the set (one marker file = one operation); (3) `appStopMaxHold` (6 h) caps an open-ended hold and logs at WARN. **Deliberately NOT persisted** — after a crash the guard holds nothing and a down app must alarm. `ReleaseFailed` drops the suppression and KEEPS the durable marker; the two are independent and a test pins that | | `backup.ErrStartRefused` + `AppStopRecovery.Refused`/`Alarming()` (R-174, v0.191.0) | controller/internal/backup/appstop_marker.go | `errors.Is(err, ErrStartRefused)` / `() bool` | THE refusal-vs-failure split in the app-stop crash recovery | **A gated starter's refusal is NOT a restart failure.** `Recover`'s starter MUST be the gated `gatedAppStopStarter` (cmd/controller/main.go), never the raw `stacks.Manager` — that was the v0.189.0 defect, which started apps onto ABSENT drives at boot (R-171 one path over). A refusal goes to `Refused` (marker KEPT, silent), a real error to `Failed` (marker kept, ALARMS). Collapsing them routes a deliberate hold into `NotifyBackupFailed`, a customer-enabled type — the R-171 false alarm again. `main.go` must guard the notify with `Alarming()`, not `!= nil` | | `Manager.DeleteStack` / `RemoveStack` | controller/internal/stacks/delete.go | `(name, removeHDDData[, backupPaths])` | THE guarded removal paths | Orphan/protected/deploying/running checks + ProtectedHDDPaths filter before any RemoveAll | | `resolveContainerState` / `aggregateState` | controller/internal/stacks/manager.go | `(dockerState, dockerStatus)` / `([]ContainerInfo)` | State classification | `.State` says "running" even when unhealthy — `.Status` parse is the fix | @@ -271,7 +272,7 @@ | `Manager.execFn` (func seam) + `restartPolicyLookup` / `inspectRestartPolicyFn` (R-51, v0.156.0) | controller/internal/stacks/manager.go | nil → real `exec.Command` / `docker inspect -f {{.HostConfig.RestartPolicy.Name}}` | `scriptedDocker` in controller/internal/stacks/degraded_test.go drives the WHOLE production path (docker ps → aggregateState → docker inspect) — an aggregateState-only test proves the function, not the caller. Policy answers are cached per container+state and pruned to the live `docker ps` set; a FAILED inspect is deliberately never cached (a hiccup must not pin a container to "unknown") and reads as SUPERVISED, i.e. fail-closed — the opposite of `IsDownState`'s fail-open, because there the state is ambiguous while here a member is known dead | | `bootrecon.StackProvider` (R-52, v0.156.0) | controller/internal/bootrecon/bootrecon.go | `*stacks.Manager` (GetStacks/StartStack/RefreshStatus) | `fakeStacks` counts StartStack per app; the load-bearing assertion is the NEGATIVE — a zero-container stack (a UI Stop = `compose down` = containers removed) must record **0** starts, while a boot orphan (containers present, Exited) records exactly 1. `Reconciler.sleep` is injected so the 30 s gap costs nothing | | `bootReconcileFn` + `runBootReconcile` (package-main seam, v0.156.0) | controller/cmd/controller/main.go | `bootrecon.New(mgr, logger).Run` | controller/cmd/controller/bootrecon_wiring_test.go. **The wiring itself is asserted by an AST walk** over `func main()`, not a `strings.Contains` — the substring version passed its own red-proof because a commented-out call still contains the string. Comments are not callers | -| `classifyRunStates` (pure fix-3 derivation, v0.164.0) | controller/cmd/controller/main.go | `([]stacks.Stack, quiesced, failedRestart map[string]bool, now time.Time)` → `(dead []web.DeadApp, states []notify.AppRunState)` | classify_runstates_test.go. **THE single fix-3 rule: down = `(IsDownState(st.State) || st.CrashLooping(now)) && !userStopped && !quiesced`.** C9-F2 (v0.183.0) added the crash-loop term: `restarting` is NOT in `IsDownState` and must not be — adding it alarms on every deploy and update fleet-wide — so a SUSTAINED restarting run (`stacks.crashLoopAfter` = 5 m, above the 120 s deploy timeout, Mealie's 60 s start_period AND R-97b's 180 s grace) becomes down instead. `now` is injected so the threshold is a testable contract. A deliberate UI stop (`compose down` → zero containers → StateStopped, I1) must not alarm — banner OR email — while faults (Exited/Degraded) alarm byte-identically; I2 (P2 census: all catalog services `unless-stopped`) is why a crash never rests at stopped. **Do NOT touch `IsDownState`** (other callers rely on stopped=down) and do NOT filter in `buildDeadAppAlerts`/`NotifyAppStartFailures` — one derivation point. If I1 or I2 changes, revisit the suppression | +| `classifyRunStates` (pure fix-3 derivation, v0.164.0) | controller/cmd/controller/main.go | `([]stacks.Stack, quiesced, failedRestart map[string]bool, now time.Time)` → `(dead []web.DeadApp, states []notify.AppRunState)` | classify_runstates_test.go. **THE single fix-3 rule: down = `(IsDownState(st.State) || st.CrashLooping(now)) && !userStopped && !quiesced`.** **`quiesced` is a UNION of TWO suppression sets** (R-330, v0.224.0): `quiesce.Loop.SuppressedStacks()` (whole-guest vzdump/PBS) and `backup.AppStopGuard.SuppressedStacks()` (per-app volume dump / offbox reconstitute / `.fab` export), merged by `unionSuppressed` in `scanDeployedAppRunStates`. **Adding a third way to stop an app means adding its set here** — R-330 was 61 false customer e-mails caused by exactly that omission, with a working suppressor sitting three lines away. C9-F2 (v0.183.0) added the crash-loop term: `restarting` is NOT in `IsDownState` and must not be — adding it alarms on every deploy and update fleet-wide — so a SUSTAINED restarting run (`stacks.crashLoopAfter` = 5 m, above the 120 s deploy timeout, Mealie's 60 s start_period AND R-97b's 180 s grace) becomes down instead. `now` is injected so the threshold is a testable contract. A deliberate UI stop (`compose down` → zero containers → StateStopped, I1) must not alarm — banner OR email — while faults (Exited/Degraded) alarm byte-identically; I2 (P2 census: all catalog services `unless-stopped`) is why a crash never rests at stopped. **Do NOT touch `IsDownState`** (other callers rely on stopped=down) and do NOT filter in `buildDeadAppAlerts`/`NotifyAppStartFailures` — one derivation point. If I1 or I2 changes, revisit the suppression | | `report.SetPendingControllerLog` / `SetControllerLogSource` | controller/internal/report/selftail.go | ACK-armed consume-once self-log pull (the logtail.go shape) | selftail_test.go; source = `logBuffer.Lines`, wired once in main.go | | `util.ParseVersion` / `util.Version.Compare` | controller/internal/util/version.go | THE one semver comparator (house rule: never a second) — selfupdate aliases it; agentapi's MinAgent comparison uses it | rejects pre-release/dev/latest (callers fall back, never trust); numeric compare (0.100 > 0.81) | | `agentapi.AgentVersionReporter` + `featureMinAgent` | controller/internal/agentapi/features.go | version-first Supports (v0.82.0 header channel); probe = fallback for header-less agents | a coupled feature adds BOTH a featureProbes row AND a featureMinAgent row; v0.116.0: `SupportsWithSource` also reports HOW the verdict was reached (version/probe-cache/probe) for the gate log line | diff --git a/controller/README.md b/controller/README.md index 7a24d99..8a4aa89 100644 --- a/controller/README.md +++ b/controller/README.md @@ -2076,6 +2076,27 @@ invariant changes, revisit the suppression. callers rely on stopped counting as down). An out-of-band `docker compose stop` leaves the containers present → `StateExited` → still alerts, which is correct (out-of-band tampering is reportable). +> **R-330 (v0.224.0) — the alarm must be told by EVERY mechanism that stops an app, and until now it +> was told by one.** The controller stops a customer's app on purpose in two quite separate places: +> the **quiesce loop**, for the whole-guest (vzdump/PBS) backup, and the **`AppStopGuard`** paths — +> the nightly volume dump, an off-site reconstitution and a `.fab` export. R-97b built the +> suppression window for the first and it works. The second registered with nothing, so +> `classifyRunStates` never knew, and the nightly backup e-mailed the customer +> „Telepített alkalmazás nem fut" about apps it was holding down itself. +> +> Measured on `demo-hp` 2026-08-30 (controller 0.223.0): `DumpAppVolumesSafe` holds each stack down +> **~13 s** while `deadapp-check` scans every **30 s**, so the scan caught whichever stack was +> mid-cycle — 3 events at the 02:30 CEST `db-dump` leg, 2 more at the 04:15 `offbox-backup` leg, +> every night, **61 e-mails**, while every other scan that day logged `0 currently down`. +> +> `classifyRunStates`'s `quiesced` argument is now the **union of both sets** (`unionSuppressed` in +> `scanDeployedAppRunStates`). **A third way to stop an app means a third set here** — that omission +> is the whole of this defect. The window cannot latch: a restart that was attempted and broke calls +> `ReleaseFailed` and alarms on the **next** scan, `Begin` replaces the previous operation's set, and +> a 6 h backstop covers a hold nothing released. Suppression is **not persisted** — after a crash the +> guard holds nothing, `Recover()` either brings the app back or leaves it genuinely down, and a down +> app must alarm. + **Boot desired-state reconciliation (R-52, v0.156.0, `internal/bootrecon`; rebuilt on recorded intent in R-166, v0.189.0).** A `deployed: true` app that missed its boot start used to stay down until a human noticed — the same shutdown that produced F4 left immich and calibre-web `Exited` while ten diff --git a/controller/cmd/controller/main.go b/controller/cmd/controller/main.go index 288217d..324af7f 100644 --- a/controller/cmd/controller/main.go +++ b/controller/cmd/controller/main.go @@ -727,7 +727,7 @@ func main() { if time.Since(startTime) < deadAppBootGrace { return nil // still inside the startup settle window } - dead, states := scanDeployedAppRunStates(stackMgr, quiesceLoop) + dead, states := scanDeployedAppRunStates(stackMgr, quiesceLoop, appStopGuard) alertMgr.SetDeadAppAlerts(dead) notifier.NotifyAppStartFailures(states) deadAppScans++ @@ -2141,10 +2141,35 @@ func recordLateRecovery(logger *log.Logger, started time.Time, res bootrecon.Res // state-based dashboard banner) and EVERY deployed app's run state (for the notifier's one-event-per- // transition tracking). Deploying apps are skipped (mid-deploy is not a fault). Pure over GetStacks() // — the derivation itself lives in classifyRunStates so it is testable without a live Manager. -func scanDeployedAppRunStates(mgr *stacks.Manager, q *quiesce.Loop) ([]web.DeadApp, []notify.AppRunState) { +func scanDeployedAppRunStates(mgr *stacks.Manager, q *quiesce.Loop, g *backup.AppStopGuard) ([]web.DeadApp, []notify.AppRunState) { // R-97b: a stack THIS controller stopped for a backup is not a fault. q may be nil (unprovisioned // guest) — SuppressedStacks is nil-safe and returns nothing, i.e. suppress nothing. - return classifyRunStates(mgr.GetStacks(), q.SuppressedStacks(), q.FailedRestarts(), time.Now()) + // + // R-330: there are TWO mechanisms in this product that stop a customer's app on purpose, and until + // v0.224.0 only one of them told the alarm. `q` covers the WHOLE-GUEST quiesce loop (vzdump/PBS); + // `g` covers the per-app operations — the nightly volume dump, an off-site reconstitution and a + // .fab export. Both are nil-safe, and the union is taken here rather than inside classifyRunStates + // so that pure function keeps its single `quiesced` parameter and its existing tests. + return classifyRunStates(mgr.GetStacks(), unionSuppressed(q.SuppressedStacks(), g.SuppressedStacks()), q.FailedRestarts(), time.Now()) +} + +// unionSuppressed merges the suppression sets of the two mechanisms that stop apps on purpose. +// Returns nil when both are empty so the common case allocates nothing. +func unionSuppressed(a, b map[string]bool) map[string]bool { + if len(a) == 0 { + return b + } + if len(b) == 0 { + return a + } + out := make(map[string]bool, len(a)+len(b)) + for n := range a { + out[n] = true + } + for n := range b { + out[n] = true + } + return out } // classifyRunStates is the pure fix-3 derivation over a plain stack slice. It splits the deployed @@ -2707,6 +2732,8 @@ func (a exportStopGuard) Begin(opID string, stacks []string) error { func (a exportStopGuard) End() { a.g.End() } +func (a exportStopGuard) ReleaseFailed(stacks ...string) { a.g.ReleaseFailed(stacks...) } + func (a *exportAdapter) SaveEncryptedAppConfig(stackDir string, env map[string]string) error { meta := stacks.LoadMetadata(stackDir) sensitiveVars := stacks.SensitiveEnvVars(&meta) diff --git a/controller/cmd/controller/r330_backup_suppression_test.go b/controller/cmd/controller/r330_backup_suppression_test.go new file mode 100644 index 0000000..c5212d6 --- /dev/null +++ b/controller/cmd/controller/r330_backup_suppression_test.go @@ -0,0 +1,115 @@ +package main + +import ( + "go/ast" + "io" + "log" + "testing" + "time" + + "gitea.dooplex.hu/admin/felhom-controller/internal/backup" + "gitea.dooplex.hu/admin/felhom-controller/internal/stacks" +) + +// ── R-330 — the per-app backup's suppression must actually REACH the alarm ─────────────────────── +// +// Measured on demo-hp 2026-08-30 (controller 0.223.0): the nightly `db-dump` and `offbox-backup` legs +// stop each stack for ~13 s to tar its volumes, the `deadapp-check` job scans every 30 s, and the +// customer got `app_start_failed — "Telepített alkalmazás nem fut: "` for apps that were never +// broken. Sixty-one e-mails. +// +// THE SHAPE OF THE ORIGINAL DEFECT IS WHY THESE TESTS EXIST. `quiesce/suppress.go` already solved +// this problem, correctly, in v0.179.0 — and the alarm still fired, because `classifyRunStates` read +// only the QUIESCE loop's set while a SECOND mechanism (the AppStopGuard's per-app operations) was +// stopping apps with nothing telling the alarm. A component that works and is not consulted is this +// project's "seam built but never wired" class, hit five times now. So one test asserts the +// CONSEQUENCE (a held app is not reported down) and one asserts the WIRING (main.go passes the +// guard), because in this defect the component was never the broken part. + +// TestHeldAppIsNotReportedDown is the consequence: whatever produces the suppression set, an app the +// backup is holding must not reach the notifier's Down-set or the dashboard banner. +func TestHeldAppIsNotReportedDown(t *testing.T) { + g := backup.NewAppStopGuard(t.TempDir()+"/appstop.json", log.New(io.Discard, "", 0)) + if err := g.Begin("volume-dump:bookstack", backup.ReasonVolumeDump, []string{"bookstack"}); err != nil { + t.Fatalf("Begin: %v", err) + } + + sts := []stacks.Stack{ + stack("bookstack", stacks.StateStopped, true, false), // held by the volume dump + stack("romm", stacks.StateExited, true, false), // genuinely broken, must still alarm + } + // The union is exactly what scanDeployedAppRunStates builds. The nil first argument is the normal + // state on a box with no whole-guest backup running — quiesce suppresses nothing, and the app-stop + // guard's set has to carry the whole answer on its own. + dead, states := classifyRunStates(sts, unionSuppressed(nil, g.SuppressedStacks()), nil, time.Now()) + + down := downByName(states) + if down["bookstack"] { + t.Fatal("the app the backup is holding stopped was reported DOWN — this is the false " + + "`app_start_failed` e-mail the customer received every night") + } + if !down["romm"] { + t.Fatal("a genuinely exited app stopped alarming — the fix silenced a real fault, which is " + + "the over-correction (F-CRIT-1 / R-88 Scenario D) it must never make") + } + if deadNames(dead)["bookstack"] { + t.Fatal("the held app still reached the dashboard dead-app banner") + } + if !deadNames(dead)["romm"] { + t.Fatal("the genuinely exited app vanished from the dead-app banner") + } +} + +func TestUnionSuppressed_KeepsBothMechanisms(t *testing.T) { + // Two independent mechanisms stop apps on purpose. Dropping either set re-opens one of the two + // false-alarm paths, and the bug shipped because only one was being read. + got := unionSuppressed(map[string]bool{"quiesced-app": true}, map[string]bool{"dumped-app": true}) + if !got["quiesced-app"] || !got["dumped-app"] { + t.Fatalf("union = %v, want both the quiesce loop's and the app-stop guard's stacks", got) + } + if got := unionSuppressed(nil, nil); len(got) != 0 { + t.Fatalf("union of two empty sets = %v, want empty", got) + } + // Neither input may be mutated: both callers hold live maps that other code reads. + a := map[string]bool{"a": true} + b := map[string]bool{"b": true} + unionSuppressed(a, b) + if len(a) != 1 || len(b) != 1 { + t.Fatalf("unionSuppressed mutated an input: a=%v b=%v", a, b) + } +} + +// TestScanDeployedAppRunStatesIsGivenTheAppStopGuard walks main.go's AST. A substring search is not +// enough — the sibling wiring tests in this package record why at first hand: a commented-out call +// still satisfies strings.Contains, so the text version passed the very red-proof it existed to fail. +func TestScanDeployedAppRunStatesIsGivenTheAppStopGuard(t *testing.T) { + body := mainBody(t) + + var found, withGuard bool + ast.Inspect(body, func(n ast.Node) bool { + call, ok := n.(*ast.CallExpr) + if !ok { + return true + } + id, ok := call.Fun.(*ast.Ident) + if !ok || id.Name != "scanDeployedAppRunStates" { + return true + } + found = true + for _, arg := range call.Args { + if a, ok := arg.(*ast.Ident); ok && a.Name == "appStopGuard" { + withGuard = true + } + } + return true + }) + + if !found { + t.Fatal("func main() never calls scanDeployedAppRunStates — the dead-app scan is not wired at all") + } + if !withGuard { + t.Fatal("scanDeployedAppRunStates is called WITHOUT appStopGuard: the suppression set exists " + + "but the alarm never reads it, which is precisely how R-330 shipped while R-97b's " + + "identical mechanism sat working three lines away") + } +} diff --git a/controller/internal/appexport/export.go b/controller/internal/appexport/export.go index 878faa6..b2783c1 100644 --- a/controller/internal/appexport/export.go +++ b/controller/internal/appexport/export.go @@ -114,6 +114,11 @@ type Exporter struct { type appStopGuard interface { Begin(opID string, stacks []string) error End() + // ReleaseFailed (R-330) drops the app-down alarm suppression for a stack this export stopped and + // then could not restart. Part of the seam rather than the exporter's own bookkeeping for the + // same reason Begin is: the guard owns the "we are holding this app" fact, and a second owner + // would drift from it. + ReleaseFailed(stacks ...string) } // NewExporter creates a new export/import engine. @@ -280,6 +285,12 @@ func (e *Exporter) executeExport(req ExportRequest, job *Job) { e.debugf("restarting stack %s after export", req.StackName) if err := e.provider.StartStack(req.StackName); err != nil { e.logger.Printf("[WARN] Export: could not restart %s: %v", req.StackName, err) + // R-330: the app is genuinely down now, so the app-down alarm must see it on the very + // next scan. The marker is still KEPT (above) so the next startup retries — the two + // are independent: the marker is durable recovery, this is live alarm suppression. + if e.stopGuard != nil { + e.stopGuard.ReleaseFailed(req.StackName) + } } else { e.debugf("stack %s restarted successfully", req.StackName) // Cleared only on a restart that succeeded — a failed one keeps the marker so the diff --git a/controller/internal/backup/appstop_marker.go b/controller/internal/backup/appstop_marker.go index e5406ef..dbb9c42 100644 --- a/controller/internal/backup/appstop_marker.go +++ b/controller/internal/backup/appstop_marker.go @@ -8,6 +8,7 @@ import ( "os" "path/filepath" "sort" + "sync" "time" ) @@ -103,6 +104,14 @@ type AppStopGuard struct { now func() time.Time // starter is only needed by Recover; Begin/End work without one. starter AppStopStarter + + // suppressed (R-330) is the in-memory "the alarm must not fire for these, we are holding them" + // set. It is deliberately NOT persisted: after a restart the guard no longer holds anything — + // Recover() either brings the apps back or leaves them genuinely down, and a down app must alarm. + // Reviving a suppression across a crash would silence exactly the case the alarm exists for. + // See appstop_suppress.go for the whole design. + suppressMu sync.Mutex + suppressed map[string]appStopHold } // AppStopRecovery is what Recover found and did. Returned rather than pushed through a notifier @@ -202,13 +211,20 @@ func (g *AppStopGuard) Begin(opID string, reason AppStopReason, stackNames []str if len(stackNames) == 0 { return nil } - return g.write(AppStopMarker{ + if err := g.write(AppStopMarker{ Active: true, OpID: opID, Reason: reason, Stacks: append([]string(nil), stackNames...), StartedAt: g.now(), - }) + }); err != nil { + return err + } + // R-330: the marker is on disk, so the caller is now cleared to stop these apps — which is + // exactly the moment the app-down alarm must stop counting them. Marked AFTER the write, so a + // Begin that failed (and therefore stopped nothing) suppresses nothing either. + g.markStopped(stackNames) + return nil } // End clears the marker after a successful restart. Best-effort by contract: a failure to clear is @@ -216,7 +232,15 @@ func (g *AppStopGuard) Begin(opID string, reason AppStopReason, stackNames []str // on the next boot, which is exactly D-b's "worst acceptable outcome" and far cheaper than failing // a backup that actually succeeded. func (g *AppStopGuard) End() { - if g == nil || g.path == "" { + if g == nil { + return + } + // R-330: start the post-restart grace BEFORE the early return below, and unconditionally. End() + // is the one "we gave the app back" signal on all three paths, and a guard with no marker path + // still owes its suppressed stacks a release — otherwise an unwired-path guard would hold them + // until appStopMaxHold. + g.releaseStarted() + if g.path == "" { return } if err := os.Remove(g.path); err != nil && !os.IsNotExist(err) { diff --git a/controller/internal/backup/appstop_suppress.go b/controller/internal/backup/appstop_suppress.go new file mode 100644 index 0000000..2b2038b --- /dev/null +++ b/controller/internal/backup/appstop_suppress.go @@ -0,0 +1,160 @@ +package backup + +import "time" + +// ── R-330: the app-down alarm must not fire for an app the BACKUP ITSELF is holding down ───────── +// +// THE BUG, MEASURED LIVE ON demo-hp 2026-08-30 (controller 0.223.0). Every night both demo boxes +// e-mailed the customer `app_start_failed — "Telepített alkalmazás nem fut: "` about apps that +// were never broken. `DumpAppVolumesSafe` stops a stack (`docker compose down`), tars its volumes and +// starts it again — ~13 s per stack — and the `deadapp-check` scheduler job runs every 30 s. It +// caught whichever stack was mid-cycle. Observed that night, UTC: the `db-dump` leg at 00:30 produced +// three events (Docmost, Paperless-ngx, RomM) and the `offbox-backup` leg at 02:15 produced two, while +// every dead-app scan of the other 23 hours logged `0 currently down`. 61 e-mails had accumulated. +// +// WHY R-97b's WINDOW DID NOT COVER IT. quiesce/suppress.go solves exactly this problem and solves it +// correctly — but it belongs to the QUIESCE LOOP, which stops stacks for the WHOLE-GUEST (vzdump/PBS) +// backup. `classifyRunStates` consults only `Loop.SuppressedStacks()`. The nightly per-app legs stop +// stacks through a different path (`Manager.DumpAppVolumesSafe`), which registered nothing with any +// suppressor. Two mechanisms stop apps; only one told the alarm. +// +// WHY THIS LIVES ON AppStopGuard, and not in a fourth place. The guard already brackets EVERY +// "we stopped this app on purpose" window in the product — `Begin` before the stop, `End` after a +// successful restart — at all three call sites (volume dump, off-site reconstitute, .fab export), and +// main.go hands the SAME guard object to the backup manager and the exporter. The fact the alarm needs +// ("we stopped it, and we have not given it back yet") is already here and has exactly one writer. +// Putting a fourth registry beside it would be the drift this codebase has paid for before. +// +// ── THE TENSION, WHICH IS THE WHOLE DESIGN (inherited from R-97b, and it still binds) ──────────── +// +// Suppress while we hold the app and for a grace period after we let go — but an app that GENUINELY +// fails to come back MUST still alarm. Permanent suppression trades a loud false alarm for a silent +// real one, which is F-CRIT-1 and R-88 Scenario D over again. Three independent things stop this +// window from latching: +// +// 1. `ReleaseFailed` — a restart that was ATTEMPTED AND BROKE drops the entry immediately, so the +// app alarms on the very next scan rather than after any delay at all. This is the primary +// mechanism and every failure path calls it. +// 2. `Begin` REPLACES the set. The marker file holds one operation, so a new Begin proves the +// previous one is over; a set stranded by an earlier op cannot survive into a later one. +// 3. `appStopMaxHold` — a backstop for a hold nothing ever released. See its comment. +const ( + // appStopAlarmGrace is how long after a successful restart a stack stays exempt. + // + // Deliberately the SAME 180 s as quiesce.quiesceAlarmGrace, and for the same derivation: the + // deploy flow allows 120 s for a stack to come up healthy, and the slowest catalog healthcheck + // start_period is Mealie's 60 s, after which a couple of check intervals must still elapse. Two + // suppression windows over the same alarm that disagreed on how long a restart takes would be a + // bug waiting to be found on whichever path used the shorter one. + // + // It is NOT longer than it needs to be: the dead-app scan runs on its own 30 s cadence, so an app + // that is genuinely dead alarms on the first scan after the window closes. The cost of this + // suppression is a BOUNDED DELAY in reporting a real failure, never its loss. + appStopAlarmGrace = 180 * time.Second + + // appStopMaxHold caps an open-ended hold, and exists because of a hazard the quiesce loop does + // not have. `Loop` always calls markUnquiesced; `AppStopGuard.End()` is called only on a restart + // that SUCCEEDED, so a failure path that forgets to call `ReleaseFailed` would leave an entry + // open-ended forever — a silently dead app, which is the exact defect this file must not create + // while fixing a false alarm. + // + // Six hours is chosen to be longer than any real hold and far shorter than "forever": a volume + // dump holds a stack ~13 s (measured), a .fab export minutes, and even a multi-gigabyte off-site + // reconstitution is hours at the outside. Exceeding it means something is wrong, and the correct + // behaviour when something is wrong is to let the alarm through. + appStopMaxHold = 6 * time.Hour +) + +// markStopped records `names` as exempt from app-down alarms for the duration of the current +// operation. The expiry is set at release; until then the entry is open-ended (bounded only by +// appStopMaxHold), because an operation may legitimately run for a long time and an app we are +// holding down that whole time must not alarm halfway through. +// +// It REPLACES the previous set rather than adding to it — see design note 2 above. +func (g *AppStopGuard) markStopped(names []string) { + if g == nil || len(names) == 0 { + return + } + g.suppressMu.Lock() + defer g.suppressMu.Unlock() + g.suppressed = make(map[string]appStopHold, len(names)) + now := g.now() + for _, n := range names { + g.suppressed[n] = appStopHold{since: now} // zero `until` = still held + } +} + +// releaseStarted starts the grace clock on every stack still held. Called from End(), which is the +// single "we gave the app back and it started" signal on all three paths. +func (g *AppStopGuard) releaseStarted() { + if g == nil { + return + } + until := g.now().Add(appStopAlarmGrace) + g.suppressMu.Lock() + defer g.suppressMu.Unlock() + for n, h := range g.suppressed { + if h.until.IsZero() { + h.until = until + g.suppressed[n] = h + } + } +} + +// ReleaseFailed drops the suppression for stacks whose restart was ATTEMPTED AND BROKE, so they +// alarm on the next dead-app scan instead of being silenced by a window that was only ever meant to +// cover a restart in progress. +// +// Call it on EVERY path that stops an app and then fails to bring it back. It is the counterpart of +// quiesce's noteRestartOutcome, and the same rule applies: the distinguishing fact is not in the +// stack's state — a stack we stopped and could not restart is byte-identical on the Docker side to +// one the customer stopped — it is that WE tried and could not, and only the caller knows that. +// +// Nil-safe and idempotent: releasing a stack that is not suppressed is a no-op, so a caller may call +// it without first checking whether Begin ever ran. +func (g *AppStopGuard) ReleaseFailed(names ...string) { + if g == nil || len(names) == 0 { + return + } + g.suppressMu.Lock() + defer g.suppressMu.Unlock() + for _, n := range names { + delete(g.suppressed, n) + } +} + +// SuppressedStacks returns the set of stack names currently exempt from app-down alarms: those an +// operation is holding stopped right now, plus those still inside the post-restart grace window. +// +// Nil-safe on a nil *AppStopGuard so the caller needs no branch — a controller with no guard +// suppresses nothing, which is the correct default. +func (g *AppStopGuard) SuppressedStacks() map[string]bool { + if g == nil { + return nil + } + now := g.now() + g.suppressMu.Lock() + defer g.suppressMu.Unlock() + out := make(map[string]bool, len(g.suppressed)) + for n, h := range g.suppressed { + switch { + case !h.until.IsZero() && !now.Before(h.until): + delete(g.suppressed, n) // grace expired — reap so the map cannot grow without bound + case h.until.IsZero() && now.Sub(h.since) >= appStopMaxHold: + // Held open-ended past the backstop. Say so: an alarm that appears because a hold was + // never released must be explainable, and standing rule 3 wants a positive observable. + g.logger.Printf("[WARN] [appstop] %s has been held stopped for over %s with no release — dropping the alarm suppression so a genuine outage is not hidden", n, appStopMaxHold) + delete(g.suppressed, n) + default: + out[n] = true + } + } + return out +} + +// appStopHold is one suppressed stack: when the hold started (for appStopMaxHold) and when it +// expires (zero while the app is still held). +type appStopHold struct { + since time.Time + until time.Time +} diff --git a/controller/internal/backup/appstop_suppress_test.go b/controller/internal/backup/appstop_suppress_test.go new file mode 100644 index 0000000..34fee4d --- /dev/null +++ b/controller/internal/backup/appstop_suppress_test.go @@ -0,0 +1,214 @@ +package backup + +import ( + "errors" + "io" + "log" + "testing" + "time" +) + +// ── R-330 — the nightly volume dump must not alarm about the app it is holding down ────────────── +// +// The defect these pin, measured on demo-hp 2026-08-30 with controller 0.223.0: `DumpAppVolumesSafe` +// stopped a stack for ~13 s to tar its volumes while the `deadapp-check` job ran every 30 s, so the +// scan caught the stack mid-cycle and pushed `app_start_failed` to the customer. 61 e-mails. +// +// The tests are split by what they must not lose: +// - the SUPPRESSION exists and covers the whole window (the fix), and +// - it can NEVER latch (the thing the fix must not break) — a restart that failed, a hold nothing +// released, and a stranded set from an earlier operation each let the alarm through. +// +// RED-PROOF (run 2026-08-30, recorded in REPORT.md): removing the `g.markStopped(stackNames)` call +// from `AppStopGuard.Begin` fails TestVolumeDump_SuppressesTheAlarmForTheAppItIsHolding with +// `suppressed at stop = map[]` — the exact pre-fix shape that produced the e-mails. + +// suppressWatchProvider drives the REAL DumpAppVolumesSafe and records the alarm-suppression set at +// the two moments that matter: while the app is stopped, and at the restart call. Asserting on the +// suppression set (what the dead-app scanner actually reads) rather than on a log line is the +// standing-rule-3 positive observable — and it is the CONSEQUENCE, not the mechanism. +type suppressWatchProvider struct { + StackDataProvider + guard *AppStopGuard + + suppressedAtStop map[string]bool + suppressedAtStart map[string]bool + startErr error +} + +func (p *suppressWatchProvider) GetDockerVolumes(string) []string { return nil } + +func (p *suppressWatchProvider) StopStack(string) error { + p.suppressedAtStop = p.guard.SuppressedStacks() + return nil +} + +func (p *suppressWatchProvider) StartStack(string) error { + p.suppressedAtStart = p.guard.SuppressedStacks() + return p.startErr +} + +// newSuppressManager builds a Manager over a real guard and returns both. +func newSuppressManager(t *testing.T, p *suppressWatchProvider) *Manager { + t.Helper() + dir := t.TempDir() + lg := log.New(io.Discard, "", 0) + m := &Manager{logger: lg, stackProvider: p, systemDataPath: dir} + m.appStop = NewAppStopGuard(markerPath(dir), lg) + p.guard = m.appStop + return m +} + +func TestVolumeDump_SuppressesTheAlarmForTheAppItIsHolding(t *testing.T) { + // THE FIX. Through the production path, not by calling Begin from the test: an earlier sibling + // test in this package was rewritten for exactly that reason — proving the guard works is not + // proving DumpAppVolumesSafe uses it. + p := &suppressWatchProvider{} + m := newSuppressManager(t, p) + + if err := m.DumpAppVolumesSafe("bookstack"); err != nil { + t.Fatalf("DumpAppVolumesSafe: %v", err) + } + + if !p.suppressedAtStop["bookstack"] { + t.Fatalf("suppressed at stop = %v, want bookstack — the dead-app scan runs every 30s and the "+ + "stack is down for ~13s, so an unsuppressed window is the false `app_start_failed` e-mail "+ + "the customer received nightly", p.suppressedAtStop) + } + if !p.suppressedAtStart["bookstack"] { + t.Fatalf("suppressed at restart = %v, want bookstack — the app is STILL down at this point", + p.suppressedAtStart) + } + // And it is still suppressed after the restart returns: R-97b's BookStack alarmed while `starting` + // / `unhealthy`, which is neither stopped nor healthy, so a window that ends at the restart CALL + // closes too early to fix anything. + if !m.appStop.SuppressedStacks()["bookstack"] { + t.Fatal("the suppression ended the instant the restart returned — an app that is up but not " + + "yet healthy still reads as down, which is the exact shape R-97b was filed for") + } +} + +func TestVolumeDump_SuppressionExpiresSoARealOutageStillAlarms(t *testing.T) { + // The window is a BOUNDED DELAY in reporting a real failure, never its loss. Without this the fix + // would trade a loud false alarm for a silent real one — F-CRIT-1 and R-88 Scenario D. + p := &suppressWatchProvider{} + m := newSuppressManager(t, p) + + base := time.Now() + m.appStop.now = func() time.Time { return base } + + if err := m.DumpAppVolumesSafe("bookstack"); err != nil { + t.Fatalf("DumpAppVolumesSafe: %v", err) + } + if !m.appStop.SuppressedStacks()["bookstack"] { + t.Fatal("not suppressed immediately after the restart") + } + + // One second before the grace closes: still suppressed. + m.appStop.now = func() time.Time { return base.Add(appStopAlarmGrace - time.Second) } + if !m.appStop.SuppressedStacks()["bookstack"] { + t.Fatalf("the grace closed early — a stack restarted %s ago must still be exempt", appStopAlarmGrace-time.Second) + } + + // At the grace boundary: the alarm owns it again. + m.appStop.now = func() time.Time { return base.Add(appStopAlarmGrace) } + if m.appStop.SuppressedStacks()["bookstack"] { + t.Fatalf("still suppressed %s after the restart — an app that genuinely failed to come back "+ + "would never be reported", appStopAlarmGrace) + } +} + +func TestVolumeDump_FailedRestartAlarmsImmediately(t *testing.T) { + // The primary anti-latch mechanism. We stopped it, we could not give it back: it is genuinely + // down, and it must alarm on the NEXT scan — not after any grace at all. + p := &suppressWatchProvider{startErr: errors.New("compose up failed")} + m := newSuppressManager(t, p) + + if err := m.DumpAppVolumesSafe("bookstack"); err == nil { + t.Fatal("a failed restart must surface as an error") + } + + if got := m.appStop.SuppressedStacks(); got["bookstack"] { + t.Fatalf("suppressed = %v after a restart that FAILED — the app is down and the alarm is the "+ + "only thing that would tell anyone, which is F-CRIT-1 exactly", got) + } + // The durable marker is a SEPARATE concern and must be untouched by the release: it is what the + // next startup retries from. Losing it here would trade a false alarm for a lost recovery. + if !markerExists(t, m.systemDataPath) { + t.Fatal("ReleaseFailed also cleared the crash marker — the next startup would not retry the restart") + } +} + +func TestSuppression_CannotOutliveTheBackstop(t *testing.T) { + // The belt-and-braces for a hold nothing ever released. `End()` runs only on a restart that + // SUCCEEDED, so a future failure path that forgets ReleaseFailed would otherwise silence an app + // forever. Exceeding the backstop means something is wrong, and the right answer when something + // is wrong is to let the alarm through. + base := time.Now() + g := NewAppStopGuard(markerPath(t.TempDir()), log.New(io.Discard, "", 0)) + g.now = func() time.Time { return base } + + if err := g.Begin("volume-dump:romm", ReasonVolumeDump, []string{"romm"}); err != nil { + t.Fatalf("Begin: %v", err) + } + if !g.SuppressedStacks()["romm"] { + t.Fatal("not suppressed while held") + } + + g.now = func() time.Time { return base.Add(appStopMaxHold - time.Minute) } + if !g.SuppressedStacks()["romm"] { + t.Fatalf("the backstop fired early — a legitimate long operation would start alarming mid-run") + } + + g.now = func() time.Time { return base.Add(appStopMaxHold) } + if g.SuppressedStacks()["romm"] { + t.Fatalf("a hold open-ended for %s is still suppressing the alarm — nothing released it and "+ + "nothing ever will", appStopMaxHold) + } +} + +func TestBeginReplacesThePreviousOperationsSet(t *testing.T) { + // The marker file holds ONE operation, so a new Begin proves the previous one is over. Without + // this, a set stranded by an operation that died between Begin and End would suppress its stacks + // for the whole appStopMaxHold, even though a later operation has since taken over. + g := NewAppStopGuard(markerPath(t.TempDir()), log.New(io.Discard, "", 0)) + + if err := g.Begin("volume-dump:romm", ReasonVolumeDump, []string{"romm"}); err != nil { + t.Fatalf("Begin romm: %v", err) + } + if err := g.Begin("volume-dump:kimai", ReasonVolumeDump, []string{"kimai"}); err != nil { + t.Fatalf("Begin kimai: %v", err) + } + + got := g.SuppressedStacks() + if got["romm"] { + t.Fatalf("suppressed = %v — romm's hold survived into a later operation that is not holding it", got) + } + if !got["kimai"] { + t.Fatalf("suppressed = %v, want kimai — the current operation's own stack is not exempt", got) + } +} + +func TestSuppression_FailedBeginSuppressesNothing(t *testing.T) { + // A Begin whose write failed means the caller REFUSES to stop the app (DumpAppVolumesSafe returns + // early). Nothing is stopped, so nothing may be exempt — suppressing here would hide a genuinely + // dead app that this operation never touched. + g := NewAppStopGuard("/proc/felhom-nonexistent-dir/appstop.json", log.New(io.Discard, "", 0)) + + if err := g.Begin("volume-dump:romm", ReasonVolumeDump, []string{"romm"}); err == nil { + t.Skip("the unwritable path became writable — this environment cannot exercise the failure") + } + if got := g.SuppressedStacks(); got["romm"] { + t.Fatalf("suppressed = %v after a Begin that FAILED — the app was never stopped", got) + } +} + +func TestNilGuardSuppressesNothing(t *testing.T) { + // An unprovisioned guest has no guard. Suppressing nothing is the correct default, and nil-safety + // is what lets the caller in main.go stay branch-free. + var g *AppStopGuard + if got := g.SuppressedStacks(); len(got) != 0 { + t.Fatalf("a nil guard suppressed %v", got) + } + g.ReleaseFailed("romm") // must not panic +} diff --git a/controller/internal/backup/backup.go b/controller/internal/backup/backup.go index fbdcdfe..05ee8e9 100644 --- a/controller/internal/backup/backup.go +++ b/controller/internal/backup/backup.go @@ -879,6 +879,10 @@ func (m *Manager) DumpAppVolumesSafe(stackName string) error { startErr := m.stackProvider.StartStack(stackName) if startErr != nil { m.logger.Printf("[ERROR] [backup] Failed to restart %s after volume dump: %v", stackName, startErr) + // R-330: we stopped it and could not give it back, so it is genuinely down and the app-down + // alarm must own it from the very next scan. Dropping the suppression here is what keeps this + // window from turning R-330's false alarm into F-CRIT-1's silent one. + m.appStop.ReleaseFailed(stackName) } else { // Cleared ONLY on a restart that succeeded. A failed restart keeps the marker so the next // startup retries — the app really is still owed one. diff --git a/controller/internal/backup/offbox_reconstitute.go b/controller/internal/backup/offbox_reconstitute.go index 251c1bc..ac3cc27 100644 --- a/controller/internal/backup/offbox_reconstitute.go +++ b/controller/internal/backup/offbox_reconstitute.go @@ -654,6 +654,10 @@ func (m *Manager) ReconstituteFromOffsite(ctx context.Context, stack string, ack err := m.stackProvider.StartStack(stack) if err == nil { m.appStop.End() + } else { + // R-330: same rule as the volume-dump path — a restart that was attempted and broke + // leaves the app genuinely down, so the alarm suppression must go immediately. + m.appStop.ReleaseFailed(stack) } return err }