From 92cebb8c958c7a056292a24157b28e5e5a3cf0b7 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Sun, 30 Aug 2026 17:58:15 +0200 Subject: [PATCH] R-330: stop the backup alarming about the apps it is holding down (v0.224.0) Measured live on demo-hp 2026-08-30 (controller 0.223.0): the nightly db-dump and offbox-backup legs stop each stack ~13s to tar its volumes while the deadapp-check job scans every 30s, so the scan caught whichever stack was mid-cycle and pushed app_start_failed to the customer. 61 e-mails about apps that were never broken. The defect is not a missing mechanism. quiesce/suppress.go solved exactly this in v0.179.0 and works -- but classifyRunStates read only the quiesce loop's set, and that loop covers the WHOLE-GUEST backup. The per-app legs stop stacks through Manager.DumpAppVolumesSafe, which registered with nothing. Two mechanisms stop apps on purpose; only one told the alarm. Fifth instance of the "seam built but never wired" class, and the first where the unwired half was a consumer. The suppression now rides AppStopGuard, which already brackets every deliberate stop in the product (Begin before the stop, End after a successful restart) at all three call sites, and which main.go hands as ONE object to the backup manager and the exporter. scanDeployedAppRunStates takes the union of both sets. All three per-app stop paths are covered, not only the reported nightly one. It cannot latch -- End() runs only on a restart that SUCCEEDED, so unlike the quiesce loop an open-ended hold is a real hazard here: 1. ReleaseFailed drops the entry IMMEDIATELY on a restart that broke, wired at every failure path, so the app alarms on the next scan; 2. Begin REPLACES the set (one marker file = one operation); 3. appStopMaxHold (6h) caps a hold nothing released, logged at WARN. Grace is 180s, deliberately quiesce's own constant and derivation. Suppression is NOT persisted: after a crash the guard holds nothing and a down app must alarm. ReleaseFailed keeps the durable crash marker; a test pins that. Three companion red-proofs, each printing the pre-fix value (REPORT.md section 5): - drop markStopped from Begin -> "suppressed at stop = map[]" - drop ReleaseFailed from the dump -> "map[bookstack:true] after a restart that FAILED" - pass nil instead of appStopGuard -> the AST wiring test fails The third is load-bearing: the component was never the broken part, so a suite that only injected it would have been green against the shipped defect. Green gate clean: go build + go vet + go test ./... -- 28 packages, rc 0. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01LB8FmJaGd2cyjvy6dbEjpM --- CHANGELOG.md | 83 ++++ REPORT.md | 377 +++++++----------- REUSE.md | 5 +- controller/README.md | 21 + controller/cmd/controller/main.go | 33 +- .../r330_backup_suppression_test.go | 115 ++++++ controller/internal/appexport/export.go | 11 + controller/internal/backup/appstop_marker.go | 30 +- .../internal/backup/appstop_suppress.go | 160 ++++++++ .../internal/backup/appstop_suppress_test.go | 214 ++++++++++ controller/internal/backup/backup.go | 4 + .../internal/backup/offbox_reconstitute.go | 4 + 12 files changed, 811 insertions(+), 246 deletions(-) create mode 100644 controller/cmd/controller/r330_backup_suppression_test.go create mode 100644 controller/internal/backup/appstop_suppress.go create mode 100644 controller/internal/backup/appstop_suppress_test.go 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 }