Files
felhom.eu/REPORT.md
T
admin a16896af86 docs: R-88 root cause established — no limiter, and the nil age bypasses the window gate
Corrects two wrong severity readings with evidence from the box and the code.

The PBS outage was ~15 min (07:00-07:18 UTC), caused by a global OOM at 06:58:12:
proxmox-backup-proxy peaked at 3.2G on a 3.8G box and a concurrent 1.9G rsync
tipped it over. Root SSH to that box works from DooPlex via the public IP, not
from felhom-pve via the tunnel IP — the documented path I failed to try first.

R-88: internal/quiesce has NO failure limiter, backoff or breaker; the loop
stopped after three cycles only because PBS recovered. Verified additionally that
scheduledRunAllowed (quiesce.go:476-478) returns true whenever lastAgeSecs is nil,
so the same missing value that makes every poll due also bypasses the time-of-day
gate — the cycles ran outside the [04:30,08:30) window. Fixing the due-verdict
without fixing the nil-age bypass would leave the hole open.
2026-07-27 11:03:02 +02:00

18 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 outage — ~15 minutes, OOM-driven, RESOLVED

Root cause established, on the box. felhom-hetzner (167.233.158.164) did not reboot (up 18 days). At 06:58:12 UTC a global OOM fired: proxmox-backup-proxy had grown to a 3.2 GB peak on a 3.8 GB box (systemd's own accounting at the later restart: Consumed 42.395s CPU time, 3.2G memory peak) and a concurrent root rsync at 1.9 GB RSS tipped it over. The kernel killed the rsync. PBS stopped serving from ~07:00 to 07:17:59 UTC, then recovered on its own — evidenced by the PVE API access log for the agent's ground-truth reads: 500 at 09:02/09:07/09:12 CEST, 200 from 09:17:59 CEST onward, uninterrupted since. A separate deliberate proxy restart at 07:52:52 UTC cleared unrelated `read fs info on "/srv/pbs-scratch" failed

  • ENOENT` spam; it was not the recovery.

This session's restore-test is the most likely driver of the proxy's 3.2 GB peak — it read 14.46 GB off that datastore 06:4406:58 UTC, finishing 9 seconds before the OOM. Not provable from what is on the box, but the timing and the memory figure both point at it, and the rsync was the victim rather than the cause. This bears directly on R-86: restore-testing a tier weekly means putting a multi-GB read on a 4 GB offsite box on a schedule. Either the box needs more RAM before that lands, or the restore-test needs to not run concurrently with whatever else touches that datastore. See also the existing note on rsync over a PBS chunk store.

Access correction worth carrying: root SSH to that box works from DooPlex to the public IP (root@167.233.158.164), and not from felhom-pve to the tunnel IP 10.77.0.1. I concluded "no access exists" from the second failing and stopped diagnosing — the project memory recorded the working path and I did not check it until later. The whole root cause above came from finally trying the documented route.

11.2 R-88 — an unreachable target takes the customer's apps down on a loop

The agent restart that applied the reverted 3.5-day cadence exposed R-88: an unreachable target reads as no backup exists, so the offsite tier is perpetually "due". Three full quiesce cycles ran (07:02:57, 07:07:58, 07:12:57 UTC), each stopping and restarting all four app stacks for a backup that could not succeed — ~19 s of app downtime per cycle, ~50 s per full cycle.

It stopped after three only because PBS recovered. There is no limiter: internal/quiesce has no failure counter, backoff, breaker or attempt budget, and the driver is a plain 5-minute ticker (quiesce.go:149). Had the outage lasted, the loop would have continued indefinitely.

The amplifier found while verifying that: the agent answers AgeSecs: nil, and scheduledRunAllowed (quiesce.go:466-480) returns true whenever the age is nil — "never withhold the first one". So the same missing value that makes every poll due also bypasses the time-of-day gate. The gate was [04:30, 08:30); the cycles ran 09:0209:12 Budapest, outside it. A safety valve written for a genuine first-ever backup is being tripped by a failed storage read.

Operator ruling 2026-07-27: leave it running (given while PBS was still down) — demo box, contained impact, self-heals, and leaving it keeps the fault visible rather than masked. It has since self-resolved; no action is outstanding on the box.

I got the severity wrong twice before measuring it. First as "one spurious event per restart" (it was a repeating loop), then as "three tries, so something limits it" (nothing does — the condition ended). Both readings were asserted from the mechanism I had reasoned about rather than from what the box and the code actually showed; the second was only caught by reading internal/quiesce instead of inferring a breaker from three log lines. Same shape as the ~2-hour estimate in §9.

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.