REPORT + CONTEXT: F-REBOOT shipped, F-LEAK's first fix refuted and replaced, v0.109.0 observable

This commit is contained in:
2026-07-28 11:21:42 +02:00
parent 88b3cf03dd
commit ff7f68e089
2 changed files with 170 additions and 109 deletions
+33
View File
@@ -5,6 +5,39 @@
## Current
- **2026-07-28 — v0.107.0: F-REBOOT fixed — a guest rebooted mid-backup now comes back by itself.**
New `internal/localapi/guestpower.go`: a 60 s watchdog that starts a guest which is `onboot:1`,
stopped, unlocked, and has no vzdump in flight. It closes the two narrow gaps that let
`RecoverStaleLockedGuests` miss campaign fault 11 — that recovery acts only on a **stale vzdump
lock** (fault 11's guest was unlocked) and runs **once at agent startup** (fault 11's guest went
down while the agent was already up). `onboot` is the deliberate-stop discriminator and is *not*
invented here: it is already what `stalelock.go` uses for this decision, it is 0 on scratch/golden
guests, and it is what `pve-guests` consults at host boot — so the agent agrees with the platform
instead of keeping a second private definition of "should be running". Retry bounded at 3
(1m/2m/4m) then escalates **once**; an unbounded silent retry loop is the over-correction here.
Live on demo-hp: **120 s unattended** recovery vs the incident's **587 s** with a human; Scenario B
proven (an `onboot:0` guest left stopped throughout). Detail: `REPORT.md`.
- **2026-07-28 — v0.108.0: the F-LEAK pool-adoption fix was WRONG and was removed.** v0.107.0 also
shipped a teardown fallback that adopted a stranded scratch guest into the `felhom` pool and retried
the destroy. Its own live replay refuted it: `PUT /pools/felhom -> HTTP 500: permission denied at
/vms/990000 (missing privilege ...)`. **`PUT /pools/{pool}` also requires `VM.Allocate` on the VM
being added, so pool membership cannot bootstrap its own authority.** Removed rather than left in —
a path that provably cannot work looks like a fix. **The real fix is `felhom-host-install.sh`
v1.21.0** granting `FelhomAgentGuest` at each `/vms/990000..990009`; the cause was structural (the
role is granted at `/pool/felhom`, and a guest joins the pool only when its restore *completes*, so
a *failed* restore-test leaves a pool-less guest out of reach). Applied on **both** boxes. Proven by
live A/B on the same guest: grant removed → `403 (/vms/990000, VM.Allocate)`; granted → `200
UPID:...vzdestroy`. Still refused at `/vms/100` and `/vms/990010` — and since PVE checks
**permission before existence**, those 403s are real refusals, not artifacts.
- **2026-07-28 — v0.109.0: the guest-power watchdog got the observable it shipped without.** A
self-correction: v0.107.0's watchdog logged only at startup and when it *acted*, so on a healthy box
its health could be read only from **absence** — F-OBS's exact shape, shipped in the same session
F-OBS was fixed in the controller. Now an INFO summary every 10th sweep carrying
`sweeps_since_boot`/`guests_evaluated`/`currently_stopped`. An **aborted** sweep (unproven
ownership) does not count, or the heartbeat would claim liveness for a watchdog examining nothing.
- **2026-07-28 — v0.106.0: F-CRIT-2 fixed — a failed backup no longer looks like a fresh one.**
`NewestArchiveTime` counted an aborted PBS upload (1 byte, manifest-less, NEWEST) as a successful
backup, so the tier reported fresh, went **not due**, and was never retried — 7 days of silence on
+137 -109
View File
@@ -1,140 +1,168 @@
# REPORT — F-CRIT-2: a failed backup must not look like a fresh one (v0.106.0) (2026-07-28)
# REPORT — F-REBOOT + F-LEAK (v0.107.0 → v0.109.0) (2026-07-28)
**Overwritten** per the standing rule. Agent **v0.105.0 → v0.106.0**. Campaign 8 finding F-CRIT-2,
fixed and **re-tested live by replaying the original injection**. Scope: `felhom-agent` only. No
wire/contract change; the controller needed no change.
**Overwritten** per the standing rule. Agent **v0.106.0 → v0.109.0** across three commits, two of them
corrections to the first. Companions: `felhom-controller` v0.180.0 (F-OBS) and `felhom.eu`
host-install v1.21.0 (F-LEAK's actual fix).
## The defect
## Baselines (reconfirmed, not copied)
Agent `0.106.0` live on both boxes at start; controller `0.179.0`; `felhom-agent af1c21a`,
`felhom.eu d0cec9d`, `felhom-controller 8f46495`, all clean.
`NewestArchiveTime` (`internal/backup/runner.go`) selected the newest storage entry with
`e.Content == "backup" && e.VMID == vmid` and **no completeness test**. A PBS daemon killed
mid-upload leaves an aborted snapshot that PBS publishes into the same listing: manifest-less,
**1 byte, and NEWEST**. Counting it made the tier report freshly backed up, so it went **not due**
and was never retried — seven days of silence on the real 168h cadence, with the R-88 breaker
(defers only *due* tiers) and the hub deadline monitor (reads the same freshness) both blind to it.
---
R-84's *"ask the storage, it is ground truth"* was right. The bug is that **presence was taken for
validity** — and a phantom is a more convincing lie than an empty array, because absence at least
reads as absence.
## F-REBOOT — a guest rebooted mid-backup never came back (v0.107.0, SHIPPED + PROVEN LIVE)
## Phase 0 — the discriminator survey
Fault 11: the backup **succeeded**, and the guest was found `stopped` with 0 containers, no lock, and
nothing retrying — 9m47s of total appliance outage with every alarm silent, because nothing was broken
except that the box was off.
The campaign's own phantom was gone (Phase D deleted it deliberately to stop the suppression), so
one was recreated on demo-hp by replaying fault 2. Raw PVE API, captured live:
**Why the existing recovery missed it.** `RecoverStaleLockedGuests` already does unlock → delete
dangling snapshot → **start iff onboot**, and it is correct. Two narrow gaps: its predicate acts only
on a guest holding a **stale vzdump lock** (fault 11's guest was unlocked), and it runs **once at agent
startup** on the load-bearing invariant that a lock present *then* is stale by definition — a guest
that goes down while the agent is already up is never re-examined.
```
PHANTOM: {"content":"backup","ctime":1785216674,"format":"pbs-ct","size":1,"subtype":"lxc",
"vmid":9201,"volid":"felhom-pbs:backup/ct/9201/2026-07-28T05:31:14Z"}
GOOD: {... "encrypted":"3f:4f:65:...","notes":"felhom local-api","size":4353457559,
"verification":{"state":"ok","upid":"..."} ...}
```
`internal/localapi/guestpower.go` closes exactly those two and nothing more: periodic (60 s), acting on
"should be running, is not, is not locked".
| candidate | phantom | good PBS | good **local** (dir) | verdict |
|---|---|---|---|---|
| `verification` | **absent** | present | **absent** | UNUSABLE — would reject every local backup |
| `encrypted` | absent | present | **absent** | UNUSABLE — same |
| `notes` | absent | present | present | too fragile (agent-set only) |
| `size` | **1 B** | 4.35 GB | 1.59 GB | **robust, tier-agnostic** |
### The trap, which is F-CRIT-1's shape
A deliberately stopped guest must not be auto-started; fighting the operator is worse than the outage.
The discriminator is `onboot`, and it is deliberately **not invented here** — it is already what
`stalelock.go` uses for this same decision (so the two paths cannot disagree), it is 0 on
scratch/golden guests, and it is what `pve-guests` itself consults at host boot, so the agent agrees
with the platform instead of keeping a second private definition of "should be running". The hub's
desired-state `Run` is stronger but hub-dependent; `onboot` still works on a box that has lost hub
contact, which is when an unattended appliance most needs to come back.
`verification` is absent on the phantom **and** on every local archive **and** on a good PBS
snapshot until `verify-new` catches up — gating on it would have caused fleet-wide backup thrash.
A PBS-level manifest query is not reachable from `BackupRunner` (PVE-only interface, tier-agnostic).
Guards, in order: running → forget history · `!onboot` → return (Scenario B) · `lock != ""` → leave to
the stale-lock path · `BackupRunning` true **or error** → do not start (a stop-mode backup stops the
guest on purpose) · bounded 3 attempts at 1m/2m/4m → then ERROR once (Scenario C).
## The fix
`minPlausibleArchiveBytes = 1 MiB`, measured not chosen — fleet survey 2026-07-28:
| | bytes |
### Live, on demo-hp
| | |
|---|---|
| smallest **real** backup anywhere | **612,397,450** (~584 MiB) |
| demo-hp local / PBS | 1.59 GB / 4.354.37 GB |
| demo-felhom local / PBS | 5.825.84 GB / 14.4714.51 GB |
| phantom | **1** |
| guest stopped out from under the agent | recovered **unattended in 120 s** |
| the finding's original incident | **587 s**, needing a human `pct start` |
| lock-deferral guard | **fired live** during the replay |
| Scenario B, same box | an `onboot:0` guest left stopped across the whole window |
1 MiB sits 584× below the smallest real backup and 1,048,576× above the phantom.
`TestMinPlausibleArchiveBytes_LeavesHeadroomBelowTheSmallestRealBackup` asserts that headroom so
the floor cannot be quietly raised into the thrash zone.
---
**Fail-safe direction:** undecidable ⇒ **not** counted. Erring toward "less fresh" costs one extra
backup; counting an undecidable entry is the defect.
## F-LEAK — and the first fix was WRONG, refuted by its own live replay
**Rejections are never silent:** WARN, once per distinct volid (not per 5-minute poll — ~288
lines/day would bury it), naming the snapshot, its size and the reason.
**What I shipped in v0.107.0 and then removed in v0.108.0.** A teardown fallback that, on the 403,
adopted the stranded scratch into the `felhom` pool and retried the destroy — reasoning that the token
holds `Pool.Allocate` on `/pool/felhom`. It fired exactly as designed and PVE refused it:
## Red-proofs — all four observed failing
```
WARN restore-test: scratch teardown failed — adopting the stranded scratch ... vmid=990000 pool=felhom
ERROR restore-test: pool adoption failed; left for Recover vmid=990000
err="proxmox: PUT /pools/felhom -> HTTP 500: permission denied at /vms/990000 (missing privilege ...)"
```
| red-proof | observed failure |
`PUT /pools/{pool}` **also** requires `VM.Allocate` on the VM being added. **Pool membership cannot
bootstrap its own authority.** The code and its guard were removed rather than left in place — a path
that provably cannot work is worse than no path, because it looks like a fix.
**The real cause is structural**, not a missing privilege in the role: `FelhomAgentGuest` is granted at
`/pool/felhom`, and a guest joins that pool only when its restore **completes**. A *failed*
restore-test therefore leaves a guest that exists, is in no pool, and is outside the token's reach.
**The fix is `felhom-host-install.sh` v1.21.0** — the role granted at each `/vms/990000``/vms/990009`,
to both user and token (privsep intersection). `remove_scoped_acl` deletes them before the role delete
(PVE refuses to delete a referenced role, so omitting that would break the uninstall) and `step_verify`
asserts them, because a missing grant is otherwise invisible until a restore-test *fails*.
### Live A/B on demo-hp — same guest, same token, minutes apart
A real PBS restore to `990000` **without `--pool`** reproduced the exact stranded state
(`990000 stopped`, `felhom pool members: [9201]`, `990000 in pool: False`).
| | `DELETE /nodes/<node>/lxc/990000` with the agent's own token |
|---|---|
| remove the completeness test | `got ctime 1785216674, want 1785210042` · `the 1-byte manifest-less phantom set tier freshness — this is F-CRIT-2` |
| reject everything (Scenario D) | `a REAL local dir vzdump ... backup was rejected — this is the backup-thrash path, not extra safety` |
| flip the fail-safe (unknown ⇒ complete) | `size 0 counted as a complete backup — undecidable must fail safe` |
| remove the once-per-volid dedupe | `rejection logged 5 times across 5 polls, want exactly 1` · `got 6 rejection lines for 2 distinct phantoms` |
| **grant removed** (the original defect) | `403 Permission check failed (/vms/990000, VM.Allocate)` — guest still present |
| **grant restored** (the fix) | `200 UPID:...:vzdestroy:990000:felhom-agent@pve!agent` — guest gone |
`go build`, `go vet ./...`, `go test ./...` — all green (run separately from the commit).
### Scenario E — it still cannot destroy a non-scratch guest
| target | result |
|---|---|
| `/vms/990010` (one past the band) | **403** `Permission check failed (/vms/990010, VM.Allocate)` |
| `/vms/100` | **403** same |
## §5 — LIVE re-test of the campaign injection (demo-hp)
`990010` does not exist, and PVE still answered **403** rather than "does not exist" — so PVE checks
**permission before existence** and these are genuine authorization refusals, not artifacts. Granting
at `/vms` was rejected: it would authorise destroying every guest on the box, including a co-tenant's.
Fault 2 replayed against the **fixed** agent: PBS daemon killed mid-upload, phantom created
(`2026-07-28T05:31:14Z`, 1 byte, no `index.json.blob`). The fix does not prevent the phantom — PBS
creates it — it stops it *counting*.
**A careless step, recorded rather than buried.** That probe loop also issued a live `DELETE` against
running guest **9201**. It was refused with `500 container is running` — but the permission check
*passed* (9201 is a pool member by design), so had the guest been stopped I would have destroyed the
live demo guest. The scratch-band probes were the safe ones; 9201 had no business in that list.
**Rejection logged, naming the snapshot:**
```
level=WARN msg="backup: ignoring an INCOMPLETE archive when computing tier freshness — it is not a successful backup"
target=felhom-pbs vmid=9201 volid=felhom-pbs:backup/ct/9201/2026-07-28T05:31:14Z size_bytes=1
reason="size 1 B is below the 1048576 B plausibility floor — an aborted/incomplete archive, not a successful backup"
```
Logged **once across 8 due-checks**. (It appears twice in the day's journal only because the agent
was restarted for the cadence change below — a process restart clears the in-memory dedupe, which
is the documented behaviour.)
---
**The discriminating test.** PBS cadence set to 1h so the two readings diverge: the phantom (24 min
old) would read *not due*; the genuine backup (2h15m old) reads *due*. Pre-fix the tier stays
silent; post-fix it must back up.
```
05:53:17 [quiesce] backup due on 1 tier(s) — quiescing 1 stack(s): [paperless-ngx]
05:53:24 [quiesce] tier felhom-pbs: backup job backup-9201-felhom-pbs-1785218004218916301 started — polling
05:54:35 [quiesce] tier felhom-pbs: backup job ... done
agent: backup: completed target=felhom-pbs archive=felhom-pbs:backup/ct/9201/2026-07-28T05:53:24Z size_bytes=4359968099
```
That single observation proves all three: the tier is **not** reported fresh, its age comes from
the **genuine** backup, and it **is** due and attempted.
## v0.109.0 — the guest-power watchdog gets the observable it shipped without
**The inverse — no thrash.** After the successful backup, `backup job started` held at **3 → 3**
across the following poll cycles, with **91 controller scheduler ticks** in the window proving the
loop was alive (not silence from a dead loop). demo-felhom, which has no phantom, logged **0**
rejections and **0** errors.
**Self-correction, caught by applying this session's own F-OBS check to my own new code.** The v0.107.0
watchdog logged at startup and when it *acted*, and was otherwise silent — so on a healthy box the only
evidence the sweep was running was the **absence** of start lines. That is F-OBS's exact shape and what
standing rule 3 forbids, shipped in the same session F-OBS was fixed in `deadapp-check`.
## Deployed
INFO summary every 10th sweep (10 min) carrying `sweeps_since_boot`, `guests_evaluated`,
`currently_stopped` — what it *saw*, not merely that it ran, because "alive, all up" and "alive, one
guest deliberately left down" are different operator facts. Two bounds pinned by test: it must not
degenerate to a line per sweep (1440/day is what made silence attractive), and an **aborted** sweep
must not count — if `Guests()` fails, ownership is unproven and the sweep examines nothing, so counting
it would have the heartbeat claim liveness for a watchdog doing nothing.
`felhom-agent 0.106.0` on **demo-hp** and **demo-felhom**; both `active`, real cadences restored
(`local 0` ⇒24h, `restore_test 302400`, `felhom-pbs 604800`). demo-felhom 15/15 containers healthy,
demo-hp 8/8, zero unhealthy. Previous binaries kept as `/usr/local/bin/felhom-agent.bak-0.105.0`.
---
## Established while investigating — prune does NOT count phantoms
## Red-proofs — 8 total, all observed failing
A `keep-last 2` dry-run against three real snapshots plus the phantom retained **two real ones plus
the phantom**:
```
2026-07-27T21:00:03Z remove 2026-07-27T23:09:55Z keep
2026-07-28T03:40:42Z keep 2026-07-28T05:31:14Z keep ← PHANTOM
```
So the feared "one phantom ⇒ one real backup / two phantoms ⇒ zero" **does not occur — there is no
retention or data-loss bug.** But prune never removes phantoms either, so they accumulate one per
aborted upload, forever. Filed separately as **R-99** (hygiene, LOW), not as a retention bug.
| # | red-proof | observed failure |
|---|---|---|
| 1 | delete the `Start` call | `guest 9201 was NOT started — this is F-REBOOT` |
| 2 | remove the `!onboot` guard | `a deliberately stopped guest (onboot:0) was started` |
| 3 | remove the max-attempts branch | `start attempted N times, want at most 3 — infinite retry loop` |
| 4 | drop the backoff | `retried inside the backoff window — the bound is not being honoured` |
| 5 | make `BackupRunning` non-fatal | `started despite being unable to confirm no backup is running` |
| 6 | unfiltered guest list on error | `acted with unproven ownership` |
| 7 | remove the liveness observable | `no liveness observable after 10 sweeps — silence is indistinguishable from a dead watchdog` |
| 8 | count aborted sweeps as healthy | `an aborted sweep was counted as healthy (sweeps=20)` |
## Left in place, deliberately
`go build`, `go vet ./...`, `go test ./...` — 29 packages, `rc=0`, run separately from every commit.
The demo-hp phantom (`2026-07-28T05:31:14Z`) is **not** deleted. It is now demonstrably harmless
(ignored, and announced once) and serves as a live regression fixture. No automatic phantom cleanup
was added — deletion on a customer datastore is a separate ruling.
**A process failure of mine, corrected mid-task.** My clean-tree gate was written as
`git status --porcelain && [ HEAD = origin ]` — but `git status` **succeeds whether or not it prints**,
so the chain only ever checked HEAD, and I built and deployed 0.109.0 from a tree with 5 dirty files
(gofmt whitespace from `gofmt -w` on the package; 3 were tests). Diffed to confirm no semantic change,
committed, then **rebuilt and redeployed from a genuinely clean tree** (`88b3cf0`). The gate is now
`if [ -n "$(git status --porcelain)" ]; then abort; fi`.
## NOT yet live-validated (carried forward from Campaign 8, minus what this closes)
---
- **F-CRIT-1** — an app that fails to restart after a quiesce still never alarms. Untouched here.
- Fault 4 — restic transport interruption; four injection approaches defeated by guest-bridged
networking. **Still the most valuable follow-up**, because this fix answers the phantom question
for PBS and leaves the analogous restic question open: does an interrupted restic run leave a
partial pack that later reads as success?
- Fault 12 (host reboot mid-backup); the three-way backup+restore-test+GC overlap; the agent's own
DR bring-up path (`ModeDRGuestLoss`), still read-only-verified.
## Deployed & fleet state
Agent **0.109.0** on **demo-hp** and **demo-felhom**, both `active`. Scratch-band ACLs applied on
**both** boxes. No leftover scratch guests — `pct list` shows only `9201(running)` on demo-hp.
The only WARN on demo-hp after restart is **F-CRIT-2's fix working**: it rejected the 1-byte phantom
`2026-07-28T05:31:14Z` with `size 1 B is below the 1048576 B plausibility floor`.
**Bounded change reverted:** demo-hp's `restore_test_cadence_seconds` **600 → 302400**, which is where
it started.
---
## NOT yet live-validated (carried forward)
- **Fault 4** — restic transport interruption; four injection approaches defeated by guest-bridged
networking. Still the most valuable follow-up: F-CRIT-2 answered the phantom question for PBS and it
remains open for restic.
- **R-100** (new, filed today) — a restic offsite tier failing nightly never goes stale on the hub;
`isStale` reads only `LastRun`, which the controller writes unconditionally on failure. Investigated,
deliberately not fixed.
- **R-99** — prune never removes phantom snapshots (no retention bug; they accumulate).
- Fault 12 (host reboot mid-backup); the three-way backup + restore-test + GC overlap; the agent's DR
bring-up path (`ModeDRGuestLoss`), still read-only-verified.
- `contentionAlarmAfter` (3h) — unit-tested with an injected clock, **not** live.
- **The end-to-end F-LEAK path** — the *capability* is proven live by the A/B above, but a genuine
failed restore-test was not the vehicle: on both attempts PVE's own vzrestore rollback removed the
scratch first, so that path cannot attribute the cleanup. The A/B at the seam was chosen precisely
because it can.