Files
felhom.eu/REPORT.md
T
admin c60cd4234c docs(report): §11 post-session live state — offsite PBS down, R-88 loop left running
Recorded after the session report was written. The offsite PBS service stopped
listening on 8007 five minutes after this session's 14.46 GB restore-test read
from it; the box is up and the tunnel is healthy, but no SSH key to it exists so
the cause is unestablished — the restore load is a plausible mechanism on a cx23
and is recorded as correlation, not cause.

The agent restart then exposed R-88: an unreachable target reads as 'no backup
exists', so the offsite tier is perpetually due and the controller runs a full
quiesce cycle every ~5 min. Operator ruling: leave it running, it self-heals when
PBS returns and masking it would hide the fault.
2026-07-27 10:53:38 +02:00

16 KiB
Raw Blame History

REPORT — R-80 → R-85: from a false alarm to an audible DR tier (2026-07-26 → 27)

One long session. It began as a diagnostic into a nightly alarm and ended with the offsite DR tier being restore-proven unattended, with its failure audible. Five roadmap items, four artifacts.

Repo From → To
felhom-agent v0.96.0 → v0.104.0
felhom-controller v0.173.0 → v0.175.0
felhom.eu hub v0.74.0 → v0.77.0
host-install 1.19.0 → 1.20.0

All live on demo-felhom and demo-hp.


1. The arc, in one line each

Item What it was
R-80 Diagnose expected_backup_missed firing on three boxes. The premise was wrong on both counts — it fired ONCE, not nightly, and no real external customer was notified
R-81 Fix the CLASS behind it: absence of a signal treated as evidence of failure. Third instance
R-82 The backup target split — "local daily + PBS weekly" was not expressible at all, which is why the DR tier was applied and empty
R-84 An agent restart no longer triggers a redundant backup
R-85 The DR tier is restore-tested unattended, and its failure is heard

2. R-80 — the diagnosis, and what it actually found

The alarm fired at 2026-07-26 03:00 UTC on demo-felhom, demo-hp and drill-r50. The brief described it as nightly, on three customers, one reaching a customer channel with a 7.3-day staleness claim.

It fired exactly once. The check ran and was correctly silent on every prior night. The one customer-channel mail went to the operator's own mailbox; peti-felhom — the only real external customer — did not fire at all. And the 7.3 days was the age of the PBS snapshot, reached only as a fallback: the local tier had run on 07-24, 07-25 and 07-26.

Root cause: the agent's backup store is in-memory ("lost on restart; the cadence re-populates"). The R-50 fleet restart at 12:44 UTC emptied backups[]; the next backup landed at 07:03 the following morning; the 03:00 check fell in that ~18 h blind window and read empty as no backup exists.

One real finding stood: the PBS/offsite tier had no schedule at all. demo-felhom held one snapshot from a healing artifact; demo-hp held zero, ever, while reporting applied since 07-21.


3. R-81 — fixing the class, not the instance

assessBackupFreshness collapsed absence of records into failure. It now returns OK / UNKNOWN / MISSED: absence is UNKNOWN until it outlives a window anchored at first contact.

The anchor was free — a Phase-0 probe found the hub already retains 90 days of host-reports, so GetHostReportsSince + newestBackupEvidence answer "when did I last SEE evidence of a backup?" rather than "what does the latest report say?". No agent change, no new state.

Not silence. A genuinely dead box must still alarm — that is the half the naive fix breaks, and TestBackupFreshness_NoEvidenceBeyondAnchor_Alarms is what makes the suppression safe.

The invariant is now written at the head of the function naming all three instances (v0.12.0, v0.73.0, R-81), pinned by a boundary test whose name says what it protects.


4. R-82 — the target split

BackupTarget() returned ONE string and BackupCadence() ONE 24 h window.

Phase 0 gates: weekly CONFIRMED (the only 7-day-exposed state is the non-SMB half of settings.json; encryption.key and the offbox credentials are stable files unchanged since first boot, so a week-old copy is byte-identical). The pvesm status 0/0/0 anomaly resolved as a namespace-scoped-token reporting artifact. Capacity raised a STOP, which the operator ruled past.

Measured, not bracketed: the second weekly snapshot cost +2.7 GB against 14.46 GB logical (~81 % dedup). Weekly top-ups are cheap; first snapshots are not. Per-tenant encryption means no cross-customer dedup, so the 80 % warn arrives at roughly the first additional customer.

Shipped: per-tier cadence/retention/wait-bound (agent); one quiesce window for both tiers (controller — two cycles would mean two app outages for one night's work); per-tier thresholds (hub, host 26 h / offsite 8 d); fresh-install default (installer).

Four defects found by RUNNING it, not reviewing it

  1. v0.98.0 — a 41-minute backup recorded success:false at 30 minutes while still running, then completed TASK OK. Worse than "didn't happen": the tier stays due and the retry hits the guest lock.
  2. v0.100.0 — the restore tier read from the configured target, not the archive. A silent regression of the S4.1 fix — the mechanism was never removed; its input changed when local_backup_target was retargeted to local.
  3. v0.101.0 — a leaked scratch kept onboot: 1; a host reboot would have started a clone of the live guest.
  4. v0.102.0 — a tier fired at a storage that does not exist yet.

5. R-84 — ground truth instead of memory

Three redundant local backups ran in one afternoon of deploys, because a restart empties the store. On the offsite tier that is a wasted multi-hour upload after every agent deploy.

Fixed by asking the storage, not persisting the record: a pruned archive correctly stops counting, where a persisted record would keep claiming a backup that no longer exists. Proven live on both boxes with the store cold.


6. R-85 — unattended, and audible

Three defects, each verified at source: the scheduler only ever saw BackupTarget(); the spec was frozen at daemon start (an immediately-invoked function — also a latent staleness bug); and a failed restore-test was a [WARN] line with no event, no notification, no gauge — true for the local tier that was being tested.

Ruling (operator): oldest-first. Never-proven sorts first, which is where the offsite tier starts. Rotation credit only on success, or a permanently failing tier looks freshly proven and stops being retried. State persisted — unlike R-84 there is no ground truth, because a restore-test destroys its scratch and leaves no artifact.

backup.InFlight — a host-wide one-heavy-operation gate. Not a lock concern (the scratch VMID never touches the live guest's vzdump lock) but a LINK one: an offsite restore PULLS multi-GB over the tunnel a backup PUSHES one. Callers defer; they never cancel.

Two hub signals, never merged: restore_test_failed (broken now) and restore_test_stale (unverified, not known-broken). Anchored on R-81, operator-tier only.


7. Live evidence

The restore round-trip PASSED (demo-hp, manual):

source_tier: pbs   pass: true   verified: boot+running   mount_parity: ok   4m5s, clean teardown

mount_parity is the non-hollow half — a boot-only verify cannot see a missing data volume.

The multi-tier quiesce ran through the real UI endpoint (authed + CSRF): exactly ONE stop/start pair with BOTH backups inside it, app quiesced through the non-last tier, early resume on the last tier's snapshot. Downtime 1m27s for both tiers.

Rotation proven unattended (demo-hp):

tier selected (oldest-proven first)  target=felhom-pbs   ← never-proven sorted first
scheduled restore-test passed        duration_s=194.8
tier selected (oldest-proven first)  target=local        ← rotated

The signal fired on its first sweep — on real faults:

[ERROR] drill-r50   Restore-test FAILED on the local tier … HTTP 403 missing privilege VM.Backup
[WARN]  demo-felhom pbs tier: NEVER restore-proven in 205h (limit 168h) — unverified, not known-broken
[INFO]  demo-hp     pbs tier: watching 133h of a 168h grace — newborn, not a fault

The first two are genuine, previously-invisible failures. All notifications went to the operator channel; the DB confirms no customer routing.

demo-hp's first ever offsite backup landed — 4.25 GB into a verifiably empty namespace.


8. Mistakes I made, and what they cost

Recorded because the pattern matters more than any one of them.

  1. I claimed the restore-test would break the control plane by booting a network-conflicting clone. Wrong — it link-downs every NIC before boot, and that is unit-tested. I read a config artifact and inferred behaviour without reading the code that consumes it, then escalated before finishing the check. I also disabled a safety mechanism on that basis; it is re-enabled.
  2. I pushed one commit red — read packages ok: 28 and missed rc=1 in the same command. Five of my own tests were failing.
  3. I planted a time bomb in Slice C — a test hard-coded the incident timestamp 2026-07-18T18:31:06Z while comparing against the real clock. It passed all day and began failing at exactly 18:31 UTC, 8 days later. A test that passes at commit time and fails hours later is worse than one that fails immediately.
  4. I left REPORT.md claiming "not deployed" 26 minutes before deploying, and did not update it.
  5. Two bad observables while verifying the controller: read a UTC timestamp as host time, then checked for log lines the agent does not emit at INFO. Both produced confident wrong readings.
  6. I told the operator blocking would not silence the new alerts. Wrong — blocked customers are excluded by GetActiveCustomerIDs already.
  7. My own spec's §5.3 was wrong — it said to force a failure with --selftest, but the selftest runs in a separate process and never reaches a host-report.

The recurring shape: inferring behaviour from an artifact instead of reading the code path that consumes it, and reading a result without reading its exit code. The host=CEST / component=UTC mismatch caught me twice in one session.


9. State at close

Backups local daily + offsite weekly, both boxes
Offsite retention 2 weeks (keep_last=2)
Restore-test rotating both tiers, unattended; interim cadence 3.5 d → each tier ~weekly
Signals failure + staleness, operator-only
drill-r50 VM 300 stopped, onboot=0. Operator will block the customer

demo-felhom's offsite restore-test — PASSED, and my estimate was wrong

tier selected (oldest-proven first)  target=felhom-pbs   archive=…2026-07-26T12:21:48Z (14.46 GB)
scheduled restore-test passed        duration_s=635.07          ← 10m35s
tier selected (oldest-proven first)  target=local              ← rotated

Rotation is now proven unattended on BOTH boxes, and the persisted state confirms it: {"felhom-pbs": "2026-07-27T06:14:42Z"} — credit recorded, so the next cycle picks the other tier.

Correction worth carrying forward: I estimated ~2 hours for this restore and it took 10m35s. I derived the estimate from a download rate measured during the failed attempt, which was running under contention; the real link does ~1.4 GB/min. I then used that wrong figure to raise a design concern — that the heavy-operation gate would block backups for hours on this box. At 10 minutes that concern largely evaporates, and the same correction applies to the SPEC's closing risk note. An estimate extrapolated from a degraded measurement is not a measurement.

10. NOT done — explicitly

  1. The restic (app-data offsite) tier is NEVER restore-testedR-87. R-85 covers whole-guest vzdump tiers only. This is arguably the tier that matters most: the only one that survives losing the box and carries the customer's app data (the whole-guest snapshot excludes the bind-mounted drives). It is exactly the state PBS was in yesterday.
  2. Restore-tests are interval-scheduled, not backup-alignedR-86 (operator ruling 2026-07-27: ~1 day after that tier's own backup).
  3. Rotation observed on demo-hp only, and under a compressed cadence. It proves the rotation logic, not the production interval.
  4. The hub infers "PBS ⇒ weekly" from storage TYPE, not a reported cadence. No box is in the wrong shape today.
  5. The installer-default fleet flip awaits a full weekly cycle.
  6. 07-backup-architecture.md is NOT ratified — brought current with an honest staleness header; ratification is Viktor's review of the §10 list.
  7. The customer-facing Hungarian copy still overstates scope — unchanged since R-80 flagged it.
  8. Capacity: the datastore still needs growing before the first real customer.

11. POST-SESSION — live state at hand-off (2026-07-27 ~07:10 UTC)

Recorded after §1–§10 were written. Two facts, both still true at hand-off.

11.1 The offsite PBS service is DOWN — cause unknown, box reachable

felhom-hetzner (167.233.158.164) reports status=running via the Hetzner API; the wg-felhom tunnel is healthy (handshake seconds old, ping 0% loss, ~40 ms); SSH 22 answers but 8007 refuses, repeatedly over several minutes from felhom-pve. The box is up and proxmox-backup-proxy is not listening. No SSH key to that box exists from DooPlex or felhom-pve, so diagnosis stopped there — the box's own journal and dmesg are unread.

A cause I cannot rule out: this session's own restore-test. The unattended PBS restore-test read 14.46 GB off that datastore 06:4406:58 UTC and completed OK; PBS was refusing five minutes later. On a cx23 (2 vCPU / 4 GB) an OOM of the proxy under that read is a plausible mechanism. Correlation only — not established, and it must not be written up as though it were. First checks for whoever gets into the box: journalctl -u proxmox-backup-proxy and dmesg | grep -i oom. If it IS the restore load, it bears directly on R-86: restore-testing a tier weekly means putting that read on a small offsite box on a schedule.

11.2 An outage loop is RUNNING on demo-felhom, deliberately left running

The agent restart that applied the reverted 3.5-day cadence exposed R-88 (filed eb3f0b8, severity corrected 5aca709): an unreachable target reads as no backup exists, so the offsite tier is perpetually "due". The controller re-polls every ~5 min and runs the full quiesce cycle each time — quiescing 4 stack(s): [bookstack calibre-web docmost immich]unquiescing (backup failed) — roughly 19 s of app downtime per cycle, unbounded, until PBS answers.

Operator ruling 2026-07-27: leave it running. It is a demo box, the impact is contained, it self-heals the instant PBS returns, and leaving it keeps the fault visible rather than masked. The alternatives (disable the tier; ship the R-88 fix) were declined in favour of not masking it.

I recorded R-88 as bounded — "one spurious event per restart" — before measuring it. It is neither bounded nor event-only; it is a repeating availability fault. The roadmap entry carries the correction. The error was the same shape as the ~2-hour estimate in §9: a severity asserted from the mechanism I had reasoned about, before looking at what the mechanism actually did on the box.

11.3 Verified clean at hand-off

Agent felhom-agent 0.104.0 active on demo-felhom, restore-test scheduler starting cadence=84h0m0s, both tiers armed (local 24h / felhom-pbs 168h). The scratch guest leaked by the mid-test restart was destroyed — 990000 band empty, zero leftover LVs. onboot: 0 held on that leaked scratch, which is the v0.101.0 fix working in exactly the scenario it was written for.


11. Observations

  • drill-r50's 403 (missing privilege VM.Backup at /vms/9100) is real and was invisible. The box is being retired, so it needs a decision — fix or accept — not silence.
  • A blocked customer is hidden from the Dashboard and from every checker, and it is reversible (configs.go sets status back to active, with a UI affordance). Blocking is a blunt instrument though: it silences everything, which is why the operator is building per-alert silencing.
  • The PVE UI will permanently show felhom-pbs at 0 % (namespace-scoped token). Read fill from the hub's PBS-DR gauge.
  • demo-felhom's guest grew 9.74 → 14.46 GB logical in eight days. Probably one-off from app testing, but if it is a rate the capacity sizing changes quickly.
  • Three of the five items in this arc were the same bug class — absence of a signal read as evidence, or a correct mechanism whose input changed underneath it. Both are now written into the code as invariants rather than left as lore.