From a667c269c7349724734a2d79ca9e9bdf21582d64 Mon Sep 17 00:00:00 2001 From: Claude Code Date: Sun, 26 Jul 2026 14:53:24 +0200 Subject: [PATCH] =?UTF-8?q?v0.98.0=20=E2=80=94=20R-82=20Slice=20A=20fix:?= =?UTF-8?q?=20per-tier=20vzdump=20wait=20bound=20(the=2030-minute=20false?= =?UTF-8?q?=20failure)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Found by live validation on demo-felhom, not by review. The first real PBS-targeted backup ran past the runner's hard-coded 30-minute WaitTask bound. The agent stopped waiting and recorded success=false WHILE THE VZDUMP KEPT RUNNING (still running 72 min later, 2.4 GB uploaded). Consequences: the tier stays permanently due, the next attempt collides with the guest lock the live vzdump holds, and the hub sees a DR tier that never succeeds — R-82's 'applied and empty' fault re-created by a timeout. Measured: ~33 MB/min over wg to Hetzner, so a first FULL ~10 GB snapshot projects to ~5h. - BackupTargetConfig.WaitTimeoutSeconds: per-tier bound. Primary 30m UNCHANGED (a local vzdump hanging 30m IS a real fault); additional tier 6h, sized from the measurement. - backup.NewBackupRunnerWithWait: per-instance (per-tier) bound. NewBackupRunner keeps its signature, so restore-test/selftest are untouched. - localapi.BackupTier.WaitTimeout: the fire-and-forget context is sized from the tier, not a fixed 2h. BOTH bounds had to move — a 6h runner bound under a 2h outer context reproduces the same false failure four hours later. Same direction as restore_test_pbs_restore_timeout_seconds: when in doubt wait LONGER. A slow backup is a slow backup; a false timeout is a corrupt status plus lock contention. Red-proof observed and restored; full suite green. --- CHANGELOG.md | 39 ++++++++++++++++++++++ cmd/felhom-agent/main.go | 13 ++++---- internal/backup/runner.go | 21 +++++++++--- internal/config/backup_tiers_test.go | 32 ++++++++++++++++++ internal/config/config.go | 50 ++++++++++++++++++++++++---- internal/localapi/backup_tiers.go | 5 ++- internal/localapi/server.go | 16 +++++++-- 7 files changed, 155 insertions(+), 21 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index dbe0f89..615c076 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,42 @@ +## v0.98.0 — R-82 Slice A fix: per-tier vzdump wait bound (the 30-minute false failure) (2026-07-26) + +**Found by live validation on demo-felhom, not by review.** The first real PBS-targeted backup ran +past the runner's hard-coded 30-minute `WaitTask` bound. The agent stopped waiting, recorded +`success:false` — **while the vzdump kept running** (still running 72 minutes later, 2.4 GB +uploaded). That is not "the backup didn't happen"; it is worse: + +- the tier stays permanently **due** (a failed backup never satisfies a cadence), +- the next attempt collides with the **guest lock** the live vzdump still holds, +- the hub sees a DR tier that never succeeds — R-82's "applied and empty" fault, re-created by a + timeout, +- the recorded `Backup` says `success:false, size_bytes:0` for a backup that may yet complete. + +30 minutes is right for a LOCAL vzdump (minutes) and simply wrong for an offsite upload. Measured on +demo-felhom: ~33 MB/min over the wg link to Hetzner ⇒ a first FULL ~10 GB snapshot projects to ≈5 h. + +### Changed +- **`BackupTargetConfig.WaitTimeoutSeconds`** — per-tier vzdump wait bound. Defaults: + **primary 30 m (UNCHANGED)**, additional tier **6 h**. The asymmetry is the point: the primary is + the local tier where a 30-minute hang IS a genuine fault worth surfacing; an additional tier is by + construction the offsite one, where the binding constraint is uplink speed, not health. 6 h is + sized from the measurement above, not guessed. +- **`backup.NewBackupRunnerWithWait`** — the runner's wait bound is per-instance (i.e. per tier). + `NewBackupRunner` keeps its signature and delegates with 0 ⇒ 30 m, so every other caller + (restore-test, selftest) is untouched. +- **`localapi.BackupTier.WaitTimeout`** — the fire-and-forget backup context is now sized from the + tier instead of a fixed 2 h. **Both bounds had to move**: a 6 h runner bound under a 2 h outer + context would have reproduced the same false failure four hours later. + +Same reasoning, and the same direction, as `restore_test_pbs_restore_timeout_seconds` on the restore +side: **when in doubt wait LONGER.** A slow backup is a slow backup; a false timeout is a corrupt +status plus lock contention. + +### Tests +`TestBackupTiers_WaitTimeoutIsPerTier` pins the asymmetric defaults, the override, and that the two +tiers do NOT share one bound. Red-proof observed: setting the extra tier's default back to 30 m +fails with `an offsite tier must default to a GENEROUS wait — a false timeout is worse than a slow +pass; got 30m0s`. Restored; full suite green. + ## v0.97.0 — R-82 Slice A: per-target backup tiers (local daily + PBS weekly) (2026-07-26) Additive; **MinAgent floor rises** for the multi-tier contract (a controller that wants per-tier diff --git a/cmd/felhom-agent/main.go b/cmd/felhom-agent/main.go index 3612a66..c584b87 100644 --- a/cmd/felhom-agent/main.go +++ b/cmd/felhom-agent/main.go @@ -1286,18 +1286,19 @@ func buildLocalAPIServer(cfg config.Config, px *proxmox.Client, store *backup.St if t.KeepLast > 0 { prune = fmt.Sprintf("keep-last=%d", t.KeepLast) } - r := backup.NewBackupRunner(px, t.TargetID, "", "felhom local-api", prune, logger) + r := backup.NewBackupRunnerWithWait(px, t.TargetID, "", "felhom local-api", prune, t.WaitTimeout, logger) if t.Primary { runner = r } apiTiers = append(apiTiers, localapi.BackupTier{ - TargetID: t.TargetID, - Cadence: t.Cadence, - Primary: t.Primary, - Service: r, + TargetID: t.TargetID, + Cadence: t.Cadence, + WaitTimeout: t.WaitTimeout, + Primary: t.Primary, + Service: r, }) logger.Info("backup tier armed", "target", t.TargetID, "cadence", t.Cadence.String(), - "keep_last", t.KeepLast, "primary", t.Primary) + "keep_last", t.KeepLast, "wait_timeout", t.WaitTimeout.String(), "primary", t.Primary) } // Guest data-drive passthrough (slice 10 P2): a root-CLI runner for the `pct set` bind + chown // (same fenced ExecRunner the host-storage + provision back-half use). diff --git a/internal/backup/runner.go b/internal/backup/runner.go index c69190a..4d5c4a9 100644 --- a/internal/backup/runner.go +++ b/internal/backup/runner.go @@ -38,21 +38,34 @@ type BackupRunner struct { // each successful backup, so the agent's own backups can't pile up and refill root. Empty → no prune // (the legacy behaviour; restore-test/selftest runners pass ""). NEVER applied to a PBS target. retention string - logger *slog.Logger - now func() time.Time + // waitTimeout bounds the WaitTask poll on this runner's vzdump. Per-TIER since R-82: 30m is + // right for a local vzdump and badly wrong for an offsite PBS upload (see the 2026-07-26 live + // failure recorded on config.BackupTargetConfig.WaitTimeoutSeconds). 0 → 30m (legacy). + waitTimeout time.Duration + logger *slog.Logger + now func() time.Time } // NewBackupRunner builds a runner. mode defaults to snapshot (works for a stopped guest and // for lvm-thin); the caller may pass ModeStop for storages without snapshot support. retention is the // per-run prune spec ("keep-last=N", or "" to never prune) — only the periodic local backup sets it. func NewBackupRunner(api BackupAPI, target string, mode proxmox.BackupMode, notes, retention string, logger *slog.Logger) *BackupRunner { + return NewBackupRunnerWithWait(api, target, mode, notes, retention, 0, logger) +} + +// NewBackupRunnerWithWait is NewBackupRunner plus an explicit vzdump wait bound (0 → 30m). +func NewBackupRunnerWithWait(api BackupAPI, target string, mode proxmox.BackupMode, notes, retention string, waitTimeout time.Duration, logger *slog.Logger) *BackupRunner { if mode == "" { mode = proxmox.ModeSnapshot } if logger == nil { logger = slog.Default() } - return &BackupRunner{api: api, target: target, mode: mode, notes: notes, retention: retention, logger: logger, now: func() time.Time { return time.Now().UTC() }} + if waitTimeout <= 0 { + waitTimeout = 30 * time.Minute + } + return &BackupRunner{api: api, target: target, mode: mode, notes: notes, retention: retention, + waitTimeout: waitTimeout, logger: logger, now: func() time.Time { return time.Now().UTC() }} } // localPruneSpec returns the `--prune-backups` spec to apply to THIS backup, or "" to skip pruning. It @@ -147,7 +160,7 @@ func (r *BackupRunner) backup(ctx context.Context, vmid int, onSnapshot func()) defer stopWatch() go r.watchForSnapshot(watchCtx, upid, onSnapshot) } - if _, err := r.api.WaitTask(ctx, upid, proxmox.WaitOptions{Timeout: 30 * time.Minute}); err != nil { + if _, err := r.api.WaitTask(ctx, upid, proxmox.WaitOptions{Timeout: r.waitTimeout}); err != nil { rec.Error = err.Error() rec.DurationSeconds = time.Since(start).Seconds() return rec, fmt.Errorf("backup: vzdump task vmid %d: %w", vmid, err) diff --git a/internal/config/backup_tiers_test.go b/internal/config/backup_tiers_test.go index 0876ff8..163a197 100644 --- a/internal/config/backup_tiers_test.go +++ b/internal/config/backup_tiers_test.go @@ -148,3 +148,35 @@ func TestBackupTiers_PrimaryRetentionClampUnchanged(t *testing.T) { } } } + +// R-82 live-failure regression (2026-07-26): the runner hard-coded a 30-minute vzdump wait, which +// is right for a local vzdump and wrong for an offsite PBS upload. The first full ~10 GB PBS +// snapshot on demo-felhom ran past 30 min; the agent gave up waiting and recorded success=false +// WHILE THE BACKUP WAS STILL RUNNING — a false failure that leaves the tier permanently "due" and +// makes the next attempt collide with the guest lock vzdump still holds. +func TestBackupTiers_WaitTimeoutIsPerTier(t *testing.T) { + b := BackupConfig{ + LocalBackupTarget: "local", + ExtraTargets: []BackupTargetConfig{{TargetID: "felhom-pbs", CadenceSeconds: 604800}}, + } + tiers, _ := b.BackupTiers() + if len(tiers) != 2 { + t.Fatalf("got %+v", tiers) + } + if tiers[0].WaitTimeout != 30*time.Minute { + t.Fatalf("the PRIMARY must keep the historical 30m wait (unchanged behaviour); got %s", tiers[0].WaitTimeout) + } + if tiers[1].WaitTimeout != 6*time.Hour { + t.Fatalf("an offsite tier must default to a GENEROUS wait — a false timeout is worse than a slow pass; got %s", tiers[1].WaitTimeout) + } + // And it must be overridable per tier. + b.ExtraTargets[0].WaitTimeoutSeconds = 3600 + tiers, _ = b.BackupTiers() + if tiers[1].WaitTimeout != time.Hour { + t.Fatalf("wait_timeout_seconds must override; got %s", tiers[1].WaitTimeout) + } + // The two tiers must NOT share one bound. + if tiers[0].WaitTimeout == tiers[1].WaitTimeout { + t.Fatalf("wait bounds are shared between tiers — the whole point is that they differ: %+v", tiers) + } +} diff --git a/internal/config/config.go b/internal/config/config.go index 34fd9fc..12ee139 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -391,13 +391,43 @@ type BackupTargetConfig struct { // (the fail-safe default, and the current behaviour for every PBS target). A PBS tier is never // pruned by the per-run flag regardless — see BackupRunner.localPruneSpec. KeepLast int `json:"keep_last"` + // WaitTimeoutSeconds bounds how long the agent WAITS for this tier's vzdump task. 0/unset → + // defaultExtraTierWaitTimeout. + // + // THIS FIELD EXISTS BECAUSE OF A LIVE FAILURE (2026-07-26, R-82 Slice A validation). The runner + // hard-coded a 30-minute wait, which is right for a local vzdump (minutes) and badly wrong for + // an offsite PBS backup over a home uplink: the first full ~10 GB snapshot ran past 30 min, the + // agent gave up waiting and recorded success=false — WHILE THE BACKUP WAS STILL RUNNING. That + // false failure is worse than a slow pass: the tier stays "due", a retry collides with the + // guest lock vzdump still holds, and the hub sees a DR tier that never succeeds. + // + // Same reasoning as RestoreTestPBSRestoreTimeoutSeconds on the restore side, and the same + // direction: when in doubt wait LONGER. A slow backup is a slow backup; a false timeout is a + // corrupt status plus lock contention. + WaitTimeoutSeconds int `json:"wait_timeout_seconds"` } +// Per-tier vzdump wait bounds. +// +// The PRIMARY keeps the historical 30 minutes: it is the local tier, a local vzdump takes minutes, +// and one hanging 30 minutes is a genuine fault worth surfacing. Unchanged behaviour. +// +// An ADDITIONAL tier is by construction the offsite/WAN one in this design, where the binding +// constraint is uplink speed, not health. 6h covers a first FULL snapshot of a ~10 GB guest at the +// ~30 Mbit/s measured on demo-felhom (that first backup alone projects to ~5.5h); later +// incrementals are far quicker. Sized from the measurement, not guessed. +const ( + defaultPrimaryTierWaitTimeout = 30 * time.Minute + defaultExtraTierWaitTimeout = 6 * time.Hour +) + // BackupTier is a RESOLVED backup tier: one target, its own cadence, its own retention. The agent // builds one runner per tier from these. type BackupTier struct { TargetID string Cadence time.Duration + // WaitTimeout bounds the wait on this tier's vzdump task (see WaitTimeoutSeconds). + WaitTimeout time.Duration // KeepLast is the per-run prune keep-last; 0 means DO NOT PRUNE this tier. KeepLast int // Primary marks the tier that the UNTARGETED local-API endpoints act on — the pre-R-82 tier. @@ -421,10 +451,11 @@ type BackupTier struct { // - Duplicate extras are rejected after the first. func (b BackupConfig) BackupTiers() ([]BackupTier, []string) { primary := BackupTier{ - TargetID: b.BackupTarget(), - Cadence: b.BackupCadence(), - KeepLast: b.KeepLast(), - Primary: true, + TargetID: b.BackupTarget(), + Cadence: b.BackupCadence(), + KeepLast: b.KeepLast(), + WaitTimeout: defaultPrimaryTierWaitTimeout, + Primary: true, } tiers := []BackupTier{primary} var warnings []string @@ -448,10 +479,15 @@ func (b BackupConfig) BackupTiers() ([]BackupTier, []string) { if keep < 0 { keep = 0 } + wait := defaultExtraTierWaitTimeout + if t.WaitTimeoutSeconds > 0 { + wait = time.Duration(t.WaitTimeoutSeconds) * time.Second + } tiers = append(tiers, BackupTier{ - TargetID: id, - Cadence: time.Duration(t.CadenceSeconds) * time.Second, - KeepLast: keep, + TargetID: id, + Cadence: time.Duration(t.CadenceSeconds) * time.Second, + KeepLast: keep, + WaitTimeout: wait, }) } return tiers, warnings diff --git a/internal/localapi/backup_tiers.go b/internal/localapi/backup_tiers.go index 69e0c5e..8285f5f 100644 --- a/internal/localapi/backup_tiers.go +++ b/internal/localapi/backup_tiers.go @@ -24,13 +24,16 @@ func normalizeBackupTiers(tiers []BackupTier, legacy BackupService, cadence time if t.Cadence <= 0 { t.Cadence = cadence } + if t.WaitTimeout <= 0 { + t.WaitTimeout = 2 * time.Hour + } usable = append(usable, t) } if len(usable) == 0 { if legacy == nil { return nil } - return []BackupTier{{TargetID: "", Cadence: cadence, Primary: true, Service: legacy}} + return []BackupTier{{TargetID: "", Cadence: cadence, WaitTimeout: 2 * time.Hour, Primary: true, Service: legacy}} } primary := -1 for i, t := range usable { diff --git a/internal/localapi/server.go b/internal/localapi/server.go index 6e03bf8..7b5d753 100644 --- a/internal/localapi/server.go +++ b/internal/localapi/server.go @@ -51,8 +51,12 @@ type BackupService interface { type BackupTier struct { TargetID string Cadence time.Duration - Primary bool - Service BackupService + // WaitTimeout bounds the fire-and-forget backup context. It MUST be >= the runner's own wait + // bound, or the outer context cancels first and the tier reports a false failure while the + // vzdump keeps running (observed live 2026-07-26 with a fixed 2h outer bound). + WaitTimeout time.Duration + Primary bool + Service BackupService } // BackupStore records + reads the latest backup/restore-test state. Satisfied by *backup.Store. @@ -734,7 +738,13 @@ func (s *Server) handleBackup(w http.ResponseWriter, r *http.Request, vmid int) base = context.Background() } go func() { - bctx, cancel := context.WithTimeout(base, 2*time.Hour) + // Outer bound = the tier's own wait bound + headroom for the pre/post work around WaitTask. + // A fixed 2h here would silently cap a 6h offsite tier. + outer := tier.WaitTimeout + if outer <= 0 { + outer = 2 * time.Hour + } + bctx, cancel := context.WithTimeout(base, outer+15*time.Minute) defer cancel() // 8B.2: flip the job to `snapshotted` when the storage snapshot is taken, so the // controller resumes its app early (snapshot mode only; in stop mode this never fires).