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.
This commit is contained in:
2026-07-27 11:03:02 +02:00
parent c60cd4234c
commit a16896af86
2 changed files with 54 additions and 27 deletions
+47 -26
View File
@@ -237,38 +237,59 @@ An estimate extrapolated from a degraded measurement is not a measurement.
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
### 11.1 The offsite PBS outage — ~15 minutes, OOM-driven, RESOLVED
`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.
**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.
**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.
**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.
### 11.2 An outage loop is RUNNING on demo-felhom, deliberately left running
**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.
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.
### 11.2 R-88 — an unreachable target takes the customer's apps down on a loop
**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.
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.
**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.
**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
File diff suppressed because one or more lines are too long