R-331 (controller half): forward stats_known so the hub can tell empty from unmeasured (v0.225.0)
gates / gates (push) Successful in 12s

The hub's operator Backup card read `Snapshots 0 / Repo Size 0 MB / Integrity
Unknown` for EVERY customer, because it rendered the report's `backup` object --
whose snapshot/size/integrity fields have had NO producer since disk-tier restic
moved to the host agent (slice 8C). buildBackupReport leaves them zero
deliberately and says so. Measured on demo-hp 2026-08-30 while that night's log
said `[offbox] backup OK: 8 app(s) backed up, 67 snapshot(s), 2m14s`.

The live numbers were always in the report's `offsite` object, which the hub
already reads for its Offsite page and its fill/staleness alarms. The hub fix is
to render that -- and that made exactly ONE field mandatory that was not being
forwarded.

snapshot_count:0 means two opposite things: "holds nothing" and "never
measured". R-225 measured that confusion inside this repo (a rebuilt box
rendered 0 pillanatkep over a store really holding snapshot f3d9cd67), and
settings.OffboxTarget.StatsKnown fixed it for the controller's own UI. It was
never put on the wire, so the hub was free to make the identical mistake one
layer up -- and did. OffboxReportStatus.StatsKnown now carries it, omitempty, so
an older controller sends no key and a reader degrades to UNKNOWN, never to
EMPTY. Absence is ignorance, not emptiness.

The four dead BackupReport fields stay on the wire (historical reports in the
hub store must keep parsing) but now carry a warning naming R-331 and pointing
at Offsite. TestBackupReport_DeadFieldsStayZero fails the moment a producer
appears for one -- the prompt to update the hub card in the SAME change rather
than ship a field nothing renders.

RED-PROOF: drop `StatsKnown: t.StatsKnown` -> "a MEASURED empty repository
reported stats_known=<nil>". Tests assert the JSON the hub sees, not the Go
struct: measured-empty and never-measured must differ ON THE WIRE, which is the
entire point of the field.

Green gate clean: 28 packages, rc 0.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01LB8FmJaGd2cyjvy6dbEjpM
This commit is contained in:
2026-08-30 18:38:10 +02:00
parent 45b52b6ed5
commit e5eee501b5
7 changed files with 324 additions and 180 deletions
+91 -180
View File
@@ -1,221 +1,132 @@
# REPORT — R-330: the nightly backup alarmed about the apps it was holding down
# REPORT — R-331: the operator Backup card said every customer had no backups
**Controller v0.224.0 · 2026-08-30 · implemented on DooPlex, diagnosed live on `demo-hp`**
**Controller v0.225.0 + hub v0.109.0 · 2026-08-30**
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.
This is Option B of a two-part request. Option A (the nightly false `app_start_failed` e-mails) shipped
earlier today as controller v0.224.0 (R-330) and is recorded in this repo's `CHANGELOG.md`.
---
## 1. What was reported
## 1. What was wrong
61 e-mails, arriving in two bursts every night from both demo boxes:
The hub customer page's **Backup** card read, for **every customer, indefinitely**:
```
[Felhom] demo-hp: app_start_failed
Severity: warning
Time: 2026-08-30 02:30 CEST
Message: Telepített alkalmazás nem fut: Docmost
Enabled Yes Snapshots 0
Repo Size 0 MB Integrity Unknown
```
## 2. What was actually happening
Measured on `demo-hp` 2026-08-30, at which moment the truth was:
**Nothing was broken.** Both boxes were healthy at every check:
| source | value |
|---|---|
| the box's own `settings.json` | `snapshot_count: 67, repo_size_bytes: 140829678, stats_known: true` |
| that night's controller log | `[offbox] backup OK: 8 app(s) backed up, 67 snapshot(s), 2m14s` |
| the hub's **Offsite** page | `0.1 GB` used of a `50 GB` quota — read from the stored report |
| | `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` |
**A card that reads "no backups" over a working backup is worse than no card.** It is the R-88
direction of failure — degrading to *no backup* rather than to *unknown* — on the one screen an
operator consults to answer "is this customer protected?".
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. Root cause
| 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 |
The card rendered the report's **`backup`** object. Its `snapshot_count`, `repo_size_mb` and
`integrity_ok` fields have had **no producer** since disk-tier restic moved to the host agent (slice
8C) — `buildBackupReport` leaves them zero *deliberately* and says so in a comment. So the zeros were
not a bug in the controller; they were correct values for dead fields, being rendered as if live.
Evidence, from the guest's own controller log (all copied off the box before any change):
**The data was never missing.** The live numbers ride in the report's **`offsite`** object
(`backup.OffboxReportStatus`), which the hub *already* reads for the Offsite page
(`offsiteUsageBytes`) and which `monitor.OffsiteChecker` *already* drives fill and staleness alarms
from. That the Offsite page rendered demo-hp's real usage from the same stored report, at the same
moment the Backup card said `0 MB`, is the proof the bytes were arriving.
```
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
```
So the fix is a **render change over an existing feed**, not a new pipeline.
`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.
## 3. Why it was not a one-line template swap
**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`.
`snapshot_count: 0` means two opposite things — *this repository holds nothing* and *nobody has ever
measured this repository*.
## 3. Root cause
**R-225 already measured that exact confusion one layer down**: a rebuilt box rendered
„Tarolo meret · 0 pillanatkep" over a store that really held snapshot `f3d9cd67`, and
`settings.OffboxTarget.StatsKnown` is what fixed it for the controller's own UI. It was never put on
the wire, so the hub was free to make the identical mistake one layer up — and rendering the count
without consulting it would have **moved R-225 to the hub instead of fixing anything**.
**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.
## 4. What changed
Two mechanisms in this product stop a customer's app on purpose. Only one told the alarm.
**Controller (v0.225.0) — one field, and the dead ones labelled.**
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.
- `OffboxReportStatus.StatsKnown` now forwards `settings.OffboxTarget.StatsKnown`. It is `omitempty`,
so a controller below this version sends no key, a reader sees `false`, and **false means "cannot
answer", never "the answer is zero"**. Absence is ignorance, not emptiness.
- The four dead `BackupReport` fields (`SnapshotCount`, `RepoSizeMB`, `LastIntegrityCheck`,
`IntegrityOK`) are **kept on the wire** so historical reports in the hub's store keep parsing, but
now carry a warning naming R-331 and pointing at `Offsite`. `TestBackupReport_DeadFieldsStayZero`
fails the moment a producer appears for any of them — the prompt to update the hub card in the
**same** change rather than shipping a field nothing renders.
## 4. The fix
**Hub (v0.109.0) — the card reads `offsite`, resolved in Go.**
`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.
`backup_card.go` builds a typed view, because the card's whole subject is a distinction a template
`{{if}}` chain over `map[string]interface{}` float64s cannot keep:
`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.
| report state | card shows |
|---|---|
| no `offsite` object at all | "No off-site data reported" — **and says explicitly this is not the same as "no backups"** |
| `enabled:false` + declared `state` | the blocker by name (`needs_credential`) — a different operator action from "not enabled" |
| enabled, `stats_known:false` | **&mdash;**, plus "never been measured". Never `0` |
| enabled, `stats_known:true` | the real count and size, **including a real `0`** — measured empty is knowledge |
### It must never latch — the harder half
**The Integrity row is deleted, not re-sourced.** Nothing produces it: the controller runs no
integrity check, and `NotifyIntegrityOK` / `NotifyIntegrityFailed` exist and are **called from
nowhere**. A row that can only ever read "Unknown" is not information, and one that could read "OK"
from an unwritten field would be a lie.
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:
`fmtBytesAuto` is new rather than reusing the Offsite page's `fmtBytesGB`: that one is fixed at GB
because it renders against GB quotas, and it turns demo-hp's real 140 829 678 bytes into `0.1 GB` —
which on a card whose entire defect was under-reporting a real backup reads as "nearly nothing".
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.
## 5. Tests and red-proofs
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.
The hub tests assert the **rendered page**, using demo-hp's real reported values, so a regression fails
against the same numbers the defect was measured against. The defect lived in the template's choice of
source object, so a test one layer below it would have been green against the shipped bug.
| 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 |
| `TestBackupCard_RendersTheRealSnapshotCount` (hub) | 67 and 134.3 MB are on the page; no `0 MB`; no Integrity row |
| `TestBackupCard_ThreeWayRuling` (hub) | unmeasured ≠ measured-empty ≠ no-object, all four branches |
| `TestBackupCard_OldControllerDegradesToUnknownNotEmpty` (hub) | upgrading the hub ahead of the fleet must not report every customer as empty |
| `TestFmtBytesAuto_...` (hub) | the real byte value renders as 134.3 MB, not 0.1 GB |
| `TestOffboxReportStatus_CarriesStatsKnown` (controller) | the field is on the wire |
| `TestOffboxReportStatus_MeasuredEmptyIsNotUnmeasured` (controller) | asserted on the **JSON**, not the struct — the hub sees bytes |
| `TestOffboxReportStatus_AbsentStatsKnownParsesAsUnknown` (controller) | the fail-safe direction |
| `TestBackupReport_DeadFieldsStayZero` (controller) | the dead fields stay dead |
**Three companion red-proofs were run, and each printed the pre-fix value:**
**Red-proofs, each printing 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.
1. Restore the pre-fix card markup → **all four hub tests fail**, reporting `67` and `134.3 MB` absent
from the rendered page and the `Integrity` row present.
2. Drop `StatsKnown: t.StatsKnown` from `OffboxReportStatus()` → `a MEASURED empty repository reported
stats_known=<nil>`.
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.
Both restored immediately; `git diff` clean afterwards.
**Green gate:** `go build ./... && go vet ./... && go test ./...` in `felhom-controller/controller/` —
clean, no failures.
**Green gates:** controller `go build && go vet && go test ./...` — 28 packages, rc 0. Hub, same
command in `hub/` — 18 packages, rc 0.
## 6. Live validation — v0.224.0 deployed and PROVEN on `demo-hp`
## 6. Deployment and live verification
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.
Recorded in the hub's own `REPORT.md`; the two halves ship together (the hub renders "unknown" for any
box still on 0.224.0, which is correct rather than wrong).
## 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.
- **No staleness verdict on the card.** `monitor.OffsiteChecker` already owns that and alarms on it.
A second verdict on the same data is two things that can disagree, which this codebase has been bitten
by before (`LastRun` vs `LastSuccess`, R-100).
- **The dead `BackupReport` fields were not removed from the wire.** Removing them would stop
historical reports already in the hub's store from parsing, for no gain — nothing renders them now,
and a test fails if anything starts producing them.