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. Not done, and why

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

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

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