felhom-controller/REPORT.md

REPORT — R-330: the nightly backup alarmed about the apps it was holding down

Controller v0.224.0 · 2026-08-30 · implemented on DooPlex, diagnosed live on demo-hp

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.

---

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)
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

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):

leg	fired (UTC)	= CEST	events pushed
db-dump	00:30	02:30	Docmost, Paperless-ngx, RomM
tier2-backup	01:30	03:30	—
offbox-backup	02:15	04:15	Docmost, Paperless-ngx

Evidence, from the guest's own controller log (all copied off the box before any change):

00:30:01 backup.go:868  [INFO] [backup] Stopping bookstack for safe volume dump
00:30:06 manager.go:1129 [INFO] [stacks] Stack bookstack stopped successfully (took 4.4s)
00:30:14 manager.go:1054 [INFO] [stacks] Stack bookstack started successfully (took 6.2s)
00:30:26 notifier.go:234 [INFO] Event pushed: app_start_failed (warning) — Telepített alkalmazás nem fut: Docmost

DumpAppVolumesSafe stops a stack (docker compose down), tars its volumes and starts it again — ~13 s per stack, measured — while the deadapp-check scheduler job runs every 30 s. The scan caught whichever stack was mid-cycle.

The positive observable that proves the boxes were fine (standing rule 3 — an absent alarm is not evidence): every dead-app scan across the other 23 hours logged 8 deployed app(s) evaluated, 0 currently down, and the same night's off-site run logged [offbox] backup OK: 8 app(s) backed up, 67 snapshot(s), 2m14s.

3. Root cause

A mechanism that exists, works, and was never consulted. quiesce/suppress.go solved exactly this problem in v0.179.0 (R-97b). But classifyRunStates read only quiesce.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 no suppressor at all.

Two mechanisms in this product stop a customer's app on purpose. Only one told the alarm.

This is the "seam built but never wired" class, fifth instance — and the first where the unwired half was a consumer rather than a producer. That distinction is why the tests below include an AST wiring check: a test that injected the suppressor directly would have passed against the shipped bug.

4. The fix

internal/backup/appstop_suppress.go (new) puts the suppression on AppStopGuard, which 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 which main.go hands as ONE object to both the backup manager and the exporter. The fact the alarm needs already lived there with exactly one writer; a fourth registry beside it would have been drift.

scanDeployedAppRunStates now passes unionSuppressed(q.SuppressedStacks(), g.SuppressedStacks()). All three per-app stop paths are fixed by the one change, not only the nightly leg that was reported — a .fab export and an off-site restore stop an app the same way and would alarm the same way.

It must never latch — the harder half

Permanent suppression trades a loud false alarm for a silent real one (F-CRIT-1, R-88 Scenario D). End() runs only on a restart that succeeded, so an open-ended hold is a genuine hazard here in a way it is not for the quiesce loop, which always releases. Three independent guards:

1. ReleaseFailed — a restart attempted and broken drops the entry immediately; the app alarms on the very next scan, with no delay at all. Wired at every failure path (volume dump, restartStack in the off-site reconstitution, the exporter's restart defer — the exporter's seam interface grew the method rather than the exporter keeping separate bookkeeping).
2. Begin replaces the set — one marker file is one operation, so 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 released, logged at WARN when it fires.

The post-restart grace is 180 s, the same constant and derivation as quiesce.quiesceAlarmGrace. Two 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. ReleaseFailed drops the suppression and keeps the durable crash marker — the two are independent, and a test pins that.

5. Tests, and the red-proofs

internal/backup/appstop_suppress_test.go drives the real DumpAppVolumesSafe (not Begin directly) and asserts the suppression set the dead-app scanner actually reads — the consequence, not a log line.

test	pins
TestVolumeDump_SuppressesTheAlarmForTheAppItIsHolding	the fix, through the production path
TestVolumeDump_SuppressionExpiresSoARealOutageStillAlarms	the window is a bounded delay, never a lost alarm
TestVolumeDump_FailedRestartAlarmsImmediately	anti-latch #1, and that the crash marker survives
TestSuppression_CannotOutliveTheBackstop	anti-latch #3
TestBeginReplacesThePreviousOperationsSet	anti-latch #2
TestSuppression_FailedBeginSuppressesNothing	a refused stop suppresses nothing
TestHeldAppIsNotReportedDown	the consequence: held app silent, genuinely exited app still alarms
TestScanDeployedAppRunStatesIsGivenTheAppStopGuard	the wiring, by AST walk

Three companion red-proofs were run, and each printed the pre-fix value:

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.

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.

Green gate: go build ./... && go vet ./... && go test ./... in felhom-controller/controller/ — clean, no failures.

6. Live validation — v0.224.0 deployed and PROVEN on demo-hp

Built, pushed and deployed to both boxes; both report 0.224.0 … (healthy).

Method: POST /api/backup/run — the exact endpoint the "Mentés indítása" button invokes — driven headlessly from inside guest 9201 (no browser on DooPlex; the residual is client-side rendering only). No state was hand-set: the real RunDBDumps ran and really stopped and started all eight stacks.

The first run is discarded and the reason is recorded rather than quietly dropped. The controller had restarted at 16:00:25 UTC and the trigger landed at 16:01:17 — inside deadAppBootGrace (90 s), during which the scan returns early. Half that window could not have alarmed whatever the code did, so it proves nothing. A second run was taken at 16:08:56, 8.5 minutes past the grace.

Run 2 — the numbers (demo-hp, UTC):

stacks stopped and restarted	8 (bookstack, calibre-web, docmost, kimai, opengist, paperless-ngx, privatebin, romm)
window	16:08:59 → 16:10:26 (87 s)
dead-app scans that ran INSIDE the window	3 — 16:09:26, 16:09:56, 16:10:26
Event pushed: app_start_failed	0 (0 across the whole uptime)

The positive control is the point (standing rule 3 — an absent alarm is equally consistent with "suppressed correctly" and "the scanner stopped"). The scanner was demonstrably alive and evaluating throughout, and each of the three scans landed on an app that was actually down or mid-restart:

scan	app in its stop/start window at that moment	alarmed on 0.223.0 last night?
16:09:26	docmost (down 16:09:16 → 16:09:31)	yes
16:09:56	paperless-ngx (down 16:09:48 → 16:10:08)	yes
16:10:26	romm (restarting, back at 16:10:26)	yes

That is a true A/B on the same box, the same job and the same three apps that produced last night's e-mails: 0.223.0 → 3 events, 0.224.0 → 0 events, with the scanner proven running in both.

demo-felhom is deployed but NOT independently proven, and this is stated rather than implied. Its single app (opengist) cycles in ~1 s (16:11:07 → 16:11:08), so no 30 s scan could land inside the window — the run produced zero events, but zero events was the expected result either way. Its scanner is confirmed alive ([deadapp] check alive: 20 scans since boot, 1 deployed app(s) evaluated, 0 currently down). The code path is identical to the one proven on demo-hp; the narrower race is also why that box sent 2 mails a night rather than 5.

The real acceptance test is tonight's unattended 02:30 and 04:15 CEST runs. Zero app_start_failed mails from either box tomorrow morning closes this; any mail is a regression.

7. Not done, and why

• 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.

8. Found while diagnosing — a second, still-open defect (Option B)

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).

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.

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.

9. Also observed (not changed)

• 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.