F-CRIT-2: a failed backup must not look like a fresh one (v0.106.0)
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.
This commit is contained in:
@@ -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/<node>/storage/<store>/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())
|
||||
}
|
||||
}
|
||||
@@ -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
|
||||
}
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user