From c9a5cc664ace27e615323a6559cd02990a86813c Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Tue, 28 Jul 2026 07:47:22 +0200 Subject: [PATCH] F-CRIT-2: a failed backup must not look like a fresh one (v0.106.0) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit NewestArchiveTime counted an aborted PBS upload (1 byte, no manifest, NEWEST) as a successful backup, so the tier reported fresh, went not-due, and was never retried. On the real 168h offsite cadence that is 7 days of silence, and neither the R-88 breaker (defers only DUE tiers) nor the hub deadline monitor (reads the same freshness) can catch it. R-84's storage-as-ground-truth was right; the bug is that presence was taken for validity. Now only plausibly-complete entries count, via a measured size floor (minPlausibleArchiveBytes = 1 MiB). Undecidable => not counted. Size is the only tier-agnostic discriminator: verification and encrypted are absent on EVERY local dir archive (and on a good PBS snapshot until verify-new catches up), so gating on either would reject 100% of local backups and cause fleet-wide backup thrash. Floor measured against the fleet: smallest real backup is 612,397,450 B, so 1 MiB leaves 584x headroom — asserted by a test. Rejections are announced at WARN once per distinct volid, naming snapshot and reason; per-poll logging would emit ~288 lines/day and bury the signal. Four red-proofs, all observed failing. --- CHANGELOG.md | 48 ++++ internal/backup/archive_completeness_test.go | 243 +++++++++++++++++++ internal/backup/runner.go | 92 ++++++- 3 files changed, 380 insertions(+), 3 deletions(-) create mode 100644 internal/backup/archive_completeness_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 63d0d7e..7c3fd40 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,53 @@ # felhom-agent — Changelog +## v0.106.0 — F-CRIT-2: a failed backup must not look like a fresh one (2026-07-28) + +Campaign 8 killed the PBS daemon mid-upload. PBS published the aborted upload into the storage +listing anyway — **1 byte, no manifest, and the NEWEST entry**. `NewestArchiveTime` counted it, so +the tier reported freshly backed up, went **not due**, and was never attempted again. On the real +168h offsite cadence that is **seven days of silence**, and neither backstop helps: the R-88 breaker +only defers tiers that are *due*, and the hub's deadline monitor reads the same freshness. + +R-84 replaced remembered state with *"ask the storage, it is ground truth"*. That 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. + +**The fix.** `NewestArchiveTime` now counts only entries that are *plausibly complete*, via a +measured size floor (`minPlausibleArchiveBytes` = 1 MiB). Undecidable ⇒ **not** counted: erring +toward "less fresh" costs one extra backup, whereas counting an undecidable entry is the defect. + +**Why size and nothing else.** This runner is tier-agnostic — the same predicate runs against PBS +and against a plain `dir` storage. Verified against the live PVE API (2026-07-28): + +| candidate | phantom | good PBS | good **local** | 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 floor is measured, not chosen: the smallest real backup anywhere on the fleet is **612,397,450 B** +(~584 MiB); 1 MiB sits 584x below it and 1,048,576x above the phantom. A test asserts that headroom +so nobody can quietly raise the floor into the thrash zone. + +**The opposite risk is real and is a first-class test.** A filter that is too aggressive does not +merely lose safety — the tier reports absent every poll, backs up every cycle, and **R-88 cannot +save it because those backups succeed**. That is a continuous multi-GB write loop across the fleet. +`TestNewestArchiveTime_ValidSnapshotsAreStillCounted` is that guard, red-proofed by making the +filter reject everything. + +**A rejected archive is never silent.** WARN, once per distinct volid (not per 5-minute poll — +~288 lines/day would bury it), naming the snapshot and the reason. + +Also established while investigating, and worth recording: **server-side prune does NOT count a +phantom toward `keep-last`** — a dry-run with `keep-last 2` against three real snapshots plus a +phantom retained *two real ones plus the phantom*. So there is **no retention/data-loss bug**. But +prune never removes phantoms either, so they accumulate one per aborted upload, forever. + +Files: `internal/backup/runner.go`, `internal/backup/archive_completeness_test.go` (new). +No wire/contract change; the controller needs no change — it consumes `age_state` and now simply +receives the truth. + ## v0.105.0 — R-88 Part 2: the agent can finally say "unknown" (2026-07-27) `newestArchiveOn` promised, in its own doc comment, that *"errors and unsupported services degrade to diff --git a/internal/backup/archive_completeness_test.go b/internal/backup/archive_completeness_test.go new file mode 100644 index 0000000..563283b --- /dev/null +++ b/internal/backup/archive_completeness_test.go @@ -0,0 +1,243 @@ +package backup + +import ( + "bytes" + "context" + "log/slog" + "strings" + "testing" + + "gitea.dooplex.hu/admin/felhom-agent/internal/proxmox" +) + +// F-CRIT-2 (Campaign 8): a failed backup must not look like a fresh one. +// +// Every fixture below is a VERBATIM shape captured from the live PVE API on 2026-07-28 +// (`pvesh get /nodes//storage//content`), not a hand-invented struct. That matters: +// the `unparseable` path in this package went untested for months behind a JSON shape that did not +// match production, and the whole point of this fix is that presence != validity. + +// phantomEntry is the artefact a PBS daemon killed mid-upload leaves behind: listed as a restorable +// backup, 1 byte, NEWEST, and carrying no `verification`/`encrypted`/`notes` at all because it has +// no manifest (`index.json.blob` is absent on disk). +func phantomEntry() proxmox.StorageContent { + return proxmox.StorageContent{ + VolID: "felhom-pbs:backup/ct/9201/2026-07-28T05:31:14Z", + Content: "backup", + Format: "pbs-ct", + Size: 1, + CTime: 1785216674, + VMID: 9201, + } +} + +// goodPBSEntry is a real, complete offsite snapshot (demo-hp, 2026-07-28T03:40:42Z). +func goodPBSEntry() proxmox.StorageContent { + return proxmox.StorageContent{ + VolID: "felhom-pbs:backup/ct/9201/2026-07-28T03:40:42Z", + Content: "backup", + Format: "pbs-ct", + Size: 4353457559, + CTime: 1785210042, + VMID: 9201, + } +} + +// goodLocalEntry is a real, complete LOCAL vzdump (demo-hp). Note it legitimately has no +// `verification` and no `encrypted` on the wire — a dir storage has no such concept — which is +// exactly why those fields must never be used as completeness discriminators. +func goodLocalEntry() proxmox.StorageContent { + return proxmox.StorageContent{ + VolID: "local:backup/vzdump-lxc-9201-2026_07_28-07_29_54.tar.zst", + Content: "backup", + Format: "tar.zst", + Size: 1590431865, + CTime: 1785216594, + VMID: 9201, + } +} + +func runnerWithContent(t *testing.T, buf *bytes.Buffer, content []proxmox.StorageContent) *BackupRunner { + t.Helper() + lg := slog.New(slog.NewTextHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug})) + return NewBackupRunner(&fakeBackupAPI{content: content}, "felhom-pbs", proxmox.ModeSnapshot, "", "", lg) +} + +// Group A — the phantom must NOT set tier freshness, even though it is the newest entry. +// +// RED-PROOF: restore the old predicate in NewestArchiveTime +// (`if e.Content == "backup" && e.VMID == vmid && e.CTime > best`) → the phantom's ctime +// (1785216674) wins over the good snapshot's (1785210042) and this test fails with +// "got 1785216674, want 1785210042" — i.e. the exact F-CRIT-2 defect. +func TestNewestArchiveTime_PhantomIsNotCounted(t *testing.T) { + var buf bytes.Buffer + // phantom deliberately listed FIRST and is also the newest by ctime. + r := runnerWithContent(t, &buf, []proxmox.StorageContent{phantomEntry(), goodPBSEntry()}) + + got, found, err := r.NewestArchiveTime(context.Background(), 9201) + if err != nil { + t.Fatalf("NewestArchiveTime: %v", err) + } + if !found { + t.Fatal("found=false — the GOOD snapshot must still be counted; rejecting everything is the thrash path") + } + if got.Unix() != goodPBSEntry().CTime { + t.Errorf("freshness came from the wrong entry: got ctime %d, want %d (the good snapshot)", got.Unix(), goodPBSEntry().CTime) + } + if got.Unix() == phantomEntry().CTime { + t.Error("the 1-byte manifest-less phantom set tier freshness — this is F-CRIT-2") + } +} + +// Group A — with ONLY a phantom present the tier must report "no backup", not a fresh one. +// That is what lets the controller see age_state=absent and fire its first-backup valve. +func TestNewestArchiveTime_OnlyPhantomReportsNotFound(t *testing.T) { + var buf bytes.Buffer + r := runnerWithContent(t, &buf, []proxmox.StorageContent{phantomEntry()}) + + _, found, err := r.NewestArchiveTime(context.Background(), 9201) + if err != nil { + t.Fatalf("NewestArchiveTime: %v", err) + } + if found { + t.Error("found=true with only a phantom present — the tier would report fresh and go silent for a full cadence") + } +} + +// Group B — THE SCENARIO-D GUARD. A valid snapshot on EITHER tier must still be counted. +// +// This is what makes Group A safe. A filter that is too aggressive does not merely lose safety +// margin: the tier reports absent on every poll, backs up every cycle, and the R-88 breaker cannot +// save it because those backups SUCCEED. That is a continuous multi-GB write loop across the fleet. +// +// RED-PROOF: make archivePlausiblyComplete return `false, "reject everything"` unconditionally → +// both subtests fail with found=false. +func TestNewestArchiveTime_ValidSnapshotsAreStillCounted(t *testing.T) { + for _, tc := range []struct { + name string + entry proxmox.StorageContent + }{ + {"pbs offsite (has verification+encrypted on the wire)", goodPBSEntry()}, + {"local dir vzdump (has NEITHER verification NOR encrypted — and must still count)", goodLocalEntry()}, + } { + t.Run(tc.name, func(t *testing.T) { + var buf bytes.Buffer + r := runnerWithContent(t, &buf, []proxmox.StorageContent{tc.entry}) + + got, found, err := r.NewestArchiveTime(context.Background(), 9201) + if err != nil { + t.Fatalf("NewestArchiveTime: %v", err) + } + if !found { + t.Fatalf("a REAL %s backup was rejected — this is the backup-thrash path, not extra safety", tc.name) + } + if got.Unix() != tc.entry.CTime { + t.Errorf("got ctime %d, want %d", got.Unix(), tc.entry.CTime) + } + if strings.Contains(buf.String(), "INCOMPLETE archive") { + t.Errorf("a valid archive was announced as incomplete:\n%s", buf.String()) + } + }) + } +} + +// Group B — the smallest REAL backup measured anywhere on the fleet (612,397,450 B, a guest-9100 +// vzdump) must clear the floor with room to spare. If someone ever raises +// minPlausibleArchiveBytes past this, that is the fleet-thrash bug and this test is the tripwire. +func TestMinPlausibleArchiveBytes_LeavesHeadroomBelowTheSmallestRealBackup(t *testing.T) { + const smallestObservedRealBackup int64 = 612397450 // fleet survey 2026-07-28 + if minPlausibleArchiveBytes >= smallestObservedRealBackup { + t.Fatalf("floor %d B is not below the smallest real backup ever observed (%d B) — this WILL reject real archives", + minPlausibleArchiveBytes, smallestObservedRealBackup) + } + if ratio := smallestObservedRealBackup / minPlausibleArchiveBytes; ratio < 100 { + t.Errorf("floor %d B leaves only %dx headroom below the smallest real backup (%d B) — too tight", + minPlausibleArchiveBytes, ratio, smallestObservedRealBackup) + } +} + +// Group C — UNDECIDABLE ⇒ NOT COUNTED (the fail-safe direction). +// +// A zero/absent size is not evidence of a good backup; it is absence of evidence. Erring toward +// "not fresh" costs one extra backup. Erring the other way is F-CRIT-2. +// +// RED-PROOF: flip the comparison in archivePlausiblyComplete to `e.Size > minPlausibleArchiveBytes +// || e.Size == 0` (i.e. treat unknown as complete) → the size-0 case reports ok=true and this fails. +func TestArchivePlausiblyComplete_UndecidableIsNotCounted(t *testing.T) { + for _, tc := range []struct { + name string + size int64 + }{ + {"the observed phantom", 1}, + {"absent size field (unmarshals to 0)", 0}, + {"just under the floor", minPlausibleArchiveBytes - 1}, + } { + t.Run(tc.name, func(t *testing.T) { + e := phantomEntry() + e.Size = tc.size + ok, why := archivePlausiblyComplete(e) + if ok { + t.Errorf("size %d counted as a complete backup — undecidable must fail safe", tc.size) + } + if why == "" { + t.Error("rejection carried no reason — a silent rejection is a new quiet path") + } + }) + } + if ok, why := archivePlausiblyComplete(goodPBSEntry()); !ok { + t.Errorf("a real snapshot was rejected: %s", why) + } +} + +// Group D — the rejection is announced ONCE per snapshot, not once per due-check. +// +// The due-check runs every 5 minutes and a phantom persists indefinitely (server-side prune does +// not collect it), so per-poll logging would emit ~288 identical lines a day and bury the signal. +// +// RED-PROOF: delete the `if seen { return }` guard in warnRejectedArchiveOnce → this test reports +// "logged 5 times, want 1". +func TestNewestArchiveTime_RejectionLoggedOncePerSnapshot(t *testing.T) { + var buf bytes.Buffer + r := runnerWithContent(t, &buf, []proxmox.StorageContent{phantomEntry(), goodPBSEntry()}) + + const polls = 5 + for i := 0; i < polls; i++ { + if _, _, err := r.NewestArchiveTime(context.Background(), 9201); err != nil { + t.Fatalf("poll %d: %v", i, err) + } + } + + n := strings.Count(buf.String(), "INCOMPLETE archive") + if n != 1 { + t.Errorf("rejection logged %d times across %d polls, want exactly 1:\n%s", n, polls, buf.String()) + } + out := buf.String() + if !strings.Contains(out, phantomEntry().VolID) { + t.Errorf("the log line does not NAME the rejected snapshot:\n%s", out) + } + if !strings.Contains(out, "below the") { + t.Errorf("the log line does not say WHY it was rejected:\n%s", out) + } + if !strings.Contains(out, "level=WARN") { + t.Errorf("rejection was not logged at WARN:\n%s", out) + } +} + +// Group D — a SECOND, distinct phantom is announced separately. The dedupe must be per snapshot, +// not a one-shot latch that hides every later phantom. +func TestNewestArchiveTime_DistinctPhantomsEachAnnounced(t *testing.T) { + var buf bytes.Buffer + second := phantomEntry() + second.VolID = "felhom-pbs:backup/ct/9201/2026-07-29T05:31:14Z" + second.CTime = phantomEntry().CTime + 86400 + r := runnerWithContent(t, &buf, []proxmox.StorageContent{phantomEntry(), second, goodPBSEntry()}) + + for i := 0; i < 3; i++ { + if _, _, err := r.NewestArchiveTime(context.Background(), 9201); err != nil { + t.Fatalf("poll %d: %v", i, err) + } + } + if n := strings.Count(buf.String(), "INCOMPLETE archive"); n != 2 { + t.Errorf("got %d rejection lines for 2 distinct phantoms across 3 polls, want 2:\n%s", n, buf.String()) + } +} diff --git a/internal/backup/runner.go b/internal/backup/runner.go index 63da28d..6ca9f55 100644 --- a/internal/backup/runner.go +++ b/internal/backup/runner.go @@ -6,6 +6,7 @@ import ( "log/slog" "sort" "strings" + "sync" "time" "gitea.dooplex.hu/admin/felhom-agent/internal/hub" @@ -53,7 +54,13 @@ type BackupRunner struct { // there is a deliberate act. allowPBSPrune bool logger *slog.Logger - now func() time.Time + now func() time.Time + // rejected remembers the volids already announced by warnRejectedArchiveOnce, so an incomplete + // archive is reported ONCE rather than on every 5-minute due-check. Bounded in practice: one + // entry per aborted upload, and a process restart clears it. Guarded by rejectedMu because the + // due-check is served from the local-API handler goroutines. + rejectedMu sync.Mutex + rejected map[string]struct{} } // NewBackupRunner builds a runner. mode defaults to snapshot (works for a stopped guest and @@ -297,6 +304,75 @@ func (r *BackupRunner) latestArchive(ctx context.Context, vmid int) (string, int // reported "no successful backup recorded yet" and the controller dutifully took another one. On the // local tier that is wasted minutes; on the OFFSITE tier it is a wasted multi-hour WAN upload after // every agent deploy — and agent deploys are routine. Three redundant local backups were observed on +// minPlausibleArchiveBytes is the floor below which a storage entry cannot be a real whole-guest +// backup and is therefore treated as an INCOMPLETE artefact rather than a successful one. +// +// MEASURED, not chosen by feel — fleet survey 2026-07-28 (Campaign 8, finding F-CRIT-2): +// +// smallest REAL backup anywhere on the fleet ... 612,397,450 B (~584 MiB, a guest-9100 vzdump) +// demo-hp local / PBS ..................... 1.59 GB / 4.35-4.37 GB +// demo-felhom local / PBS ..................... 5.82-5.84 GB / 14.47-14.51 GB +// the phantom left by a PBS daemon killed mid-upload ....... 1 B +// +// 1 MiB sits 584x below the smallest real backup and 1,048,576x above the phantom. The two +// populations are nine orders of magnitude apart, so this floor cannot plausibly clip a real +// archive — which is the property that matters, because a floor set too HIGH does not merely lose +// safety margin, it causes fleet-wide backup THRASH (see archivePlausiblyComplete). +const minPlausibleArchiveBytes int64 = 1 << 20 + +// archivePlausiblyComplete reports whether a storage entry can be a COMPLETE backup, and if not, +// why. Pure, so the contract is unit-testable without a storage. +// +// WHY SIZE, AND NOTHING ELSE. The richer PBS fields look like better discriminators and are all +// traps, because this runner is TIER-AGNOSTIC — the same predicate runs against a PBS datastore and +// against a plain `dir` storage (verified against the live PVE API, 2026-07-28): +// +// - `verification` is absent on the phantom, but ALSO absent on every local (dir) archive — a dir +// storage has no verification concept — and absent on a good PBS snapshot until verify-new +// catches up. Gating on it would reject 100% of local backups and every freshly-taken offsite +// one: continuous re-backup across the fleet. +// - `encrypted` fails the same way, and for the same reason. +// - `notes` happens to be present on both good tiers today only because the agent sets it; an +// archive written by any other path lacks it. Too fragile to gate freshness on. +// +// Size is the only signal that means the same thing on every tier. +// +// THE FAIL-SAFE DIRECTION, stated explicitly: when completeness cannot be established the entry is +// NOT counted as a successful backup. That errs toward the tier looking LESS fresh, and its worst +// case is one extra backup. Counting an undecidable entry is precisely the F-CRIT-2 defect — a +// failed upload that made its tier look freshly backed up and silenced it for a full cadence. +func archivePlausiblyComplete(e proxmox.StorageContent) (bool, string) { + if e.Size < minPlausibleArchiveBytes { + return false, fmt.Sprintf("size %d B is below the %d B plausibility floor — an aborted/incomplete archive, not a successful backup", + e.Size, minPlausibleArchiveBytes) + } + return true, "" +} + +// warnRejectedArchiveOnce announces a rejected archive at WARN exactly once per distinct volid. +// +// A rejected archive must never be silent: a tier that quietly ignores the newest entry on its +// storage is a new quiet path, and quiet paths are what F-CRIT-2 was. But the due-check runs every +// 5 minutes and a phantom persists indefinitely — server-side prune does NOT collect it (verified +// by dry-run 2026-07-28: with keep-last 2 it retained two real snapshots PLUS the phantom) — so +// logging per poll would emit ~288 identical lines a day and bury the one that matters. +func (r *BackupRunner) warnRejectedArchiveOnce(e proxmox.StorageContent, why string) { + r.rejectedMu.Lock() + if r.rejected == nil { + r.rejected = map[string]struct{}{} + } + _, seen := r.rejected[e.VolID] + if !seen { + r.rejected[e.VolID] = struct{}{} + } + r.rejectedMu.Unlock() + if seen { + return + } + r.logger.Warn("backup: ignoring an INCOMPLETE archive when computing tier freshness — it is not a successful backup", + "target", r.target, "vmid", e.VMID, "volid", e.VolID, "size_bytes", e.Size, "reason", why) +} + // demo-felhom in a single afternoon of deploys (2026-07-26). // // Asking the STORAGE rather than persisting the store is deliberate: @@ -305,7 +381,10 @@ func (r *BackupRunner) latestArchive(ctx context.Context, vmid int) (string, int // - it needs no new on-disk state and no migration; // - it is the same source `latestArchive` already trusts to build the post-backup record. // -// It answers ONLY "when did a backup last land", which is exactly what the due-check needs. The +// It answers ONLY "when did a plausibly COMPLETE backup last land", which is exactly what the +// due-check needs. Completeness is not optional here: PBS publishes an aborted upload into the same +// listing (manifest-less, 1 byte, and NEWEST), and counting it made the tier report fresh and go +// silent for a whole cadence — F-CRIT-2. Presence is not validity. The // richer fields (size, duration, uncovered volumes, error) stay with the real in-memory records — a // synthesized record would put invented numbers into the host-report. func (r *BackupRunner) NewestArchiveTime(ctx context.Context, vmid int) (time.Time, bool, error) { @@ -315,7 +394,14 @@ func (r *BackupRunner) NewestArchiveTime(ctx context.Context, vmid int) (time.Ti } var best int64 = -1 for _, e := range contents { - if e.Content == "backup" && e.VMID == vmid && e.CTime > best { + if e.Content != "backup" || e.VMID != vmid { + continue + } + if ok, why := archivePlausiblyComplete(e); !ok { + r.warnRejectedArchiveOnce(e, why) + continue + } + if e.CTime > best { best = e.CTime } }