From 53d0c6bfc426e723d86515018e254c36c7a37abe Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Mon, 3 Aug 2026 15:26:54 +0200 Subject: [PATCH] v0.121.1: 'nothing is due' must be AUDIBLE (R-86 + standing rule 3) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Before R-86 every tick ran a heavy restore-test, so the scheduler was audible by construction. After it, 'nothing is due' is the NORMAL outcome — and it was logged at DEBUG, which journald drops. An empty journal would then be equally consistent with a healthy loop and a dead goroutine: the shape the R-88 watcher was retired for, re-created by making the quiet path the common one. A not-due evaluation now logs one INFO line naming every tier's verdict (four lines a day at the 6h default), and an unlistable tier reads UNKNOWN with its error in that same line, so a lookup failure can never present as 'nothing due'. Red-proved through the scheduler's own tick, not the helper. --- CHANGELOG.md | 25 +++++++++ internal/backup/restoretest_due.go | 26 ++++++++++ internal/backup/restoretest_due_test.go | 69 +++++++++++++++++++++---- internal/backup/schedule.go | 10 +++- 4 files changed, 119 insertions(+), 11 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e1d1600..e4a49ae 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,28 @@ +## v0.121.1 — "nothing is due" must be AUDIBLE (2026-08-03, R-86 + standing rule 3) + +**Found while live-validating v0.121.0, and it is this project's own rule pointed at the change that +had just shipped.** Before R-86 every tick ran a heavy restore-test, so the scheduler was audible by +construction. After it, *"nothing is due"* is the NORMAL outcome — and it was logged at **DEBUG**, +which journald drops. An empty journal would then have been equally consistent with a healthy loop +and with a dead goroutine: the exact shape the R-88 watcher was retired for, re-created in a new +place by making the quiet path the common one. + +A not-due evaluation now logs one **INFO** line naming every tier's verdict: + +``` +backup: restore-test evaluated — nothing due + verdicts="felhom-pbs: newest settled archive (landed 2026-07-28T04:49:43Z) is already proven; + felhom-backup: no settled archive yet — nothing to prove (newborn or still settling)" +``` + +Four lines a day at the 6 h default, and the answer to *"why did nothing run last night?"* is in the +log instead of being re-derived. A tier whose storage cannot be listed reads `UNKNOWN` with its error +in the same line, so a lookup failure can never present as "nothing due". + +Red-proved by reverting to the bare `Debug` line: the test asserts what the SCHEDULER emits on a real +`tick`, not what the helper returns — a helper-level test would have passed against a tick that never +called it. + ## v0.121.0 — a restore-test proves each BACKUP, not the clock (2026-08-03, R-86) **The trigger changed; the restore-test did not.** `Scheduler.Run` still has a ticker, but it is now diff --git a/internal/backup/restoretest_due.go b/internal/backup/restoretest_due.go index d4e1eeb..611880c 100644 --- a/internal/backup/restoretest_due.go +++ b/internal/backup/restoretest_due.go @@ -140,3 +140,29 @@ func (s *Scheduler) evaluateTier(ctx context.Context, target string, cutoff time func (s *Scheduler) EvaluateDueTier(ctx context.Context, target string) DueVerdict { return s.evaluateTier(ctx, target, s.settleCutoff()) } + +// verdictSummary renders one compact line of per-tier verdicts for the "nothing due" log. +// +// It re-evaluates rather than threading the verdicts out of pickForThisRun, and that is a +// deliberate trade: this runs only on the path where NOTHING is due, so the cost is one extra +// storage listing per tier on an otherwise idle evaluation (measured 18 ms local / 392 ms offsite, +// R-86 Part 1.4), and in exchange the logging path cannot drift from the deciding path by holding a +// stale copy of it. If that cost ever matters, pass the verdicts in — do not let the two diverge. +func (s *Scheduler) verdictSummary(ctx context.Context) string { + out := "" + for _, v := range s.EvaluateDue(ctx) { + if out != "" { + out += "; " + } + switch { + case v.Err != nil: + out += v.Target + ": UNKNOWN (" + v.Err.Error() + ")" + default: + out += v.Target + ": " + v.Reason + } + } + if out == "" { + return "no tiers configured" + } + return out +} diff --git a/internal/backup/restoretest_due_test.go b/internal/backup/restoretest_due_test.go index 30738b5..201e3c4 100644 --- a/internal/backup/restoretest_due_test.go +++ b/internal/backup/restoretest_due_test.go @@ -4,8 +4,10 @@ import ( "context" "errors" "fmt" + "log/slog" "os" "path/filepath" + "strings" "testing" "time" @@ -124,8 +126,8 @@ func dailyArchives(tier string, n int) []archiveStub { // COMPANION RED-PROOF (observed 2026-08-03). In Scheduler.evaluateTier, the per-archive comparison // was replaced by the naive age rule: // -// - if ok && proven == archive { … not due … } -// + if s.now().Sub(landed) < s.settle { … not due … } // and the proven-archive check deleted +// - if ok && proven == archive { … not due … } +// - if s.now().Sub(landed) < s.settle { … not due … } // and the proven-archive check deleted // // and the picker cutoff was removed (`cutoff := time.Time{}`), i.e. exactly "is the newest archive // old enough". Result: @@ -194,12 +196,13 @@ func TestDue_WeeklyTierIsProvedOncePerArchive(t *testing.T) { // COMPANION RED-PROOF (observed 2026-08-03): revert the state to per-tier TIME by making // ProvenArchive ignore the stored archive — // -// - if !ok || p.Archive == "" { return "", false } -// + return "", false // per-tier time only, the pre-R-86 state +// - if !ok || p.Archive == "" { return "", false } +// - return "", false // per-tier time only, the pre-R-86 state // // → --- FAIL: TestDue_RestartRunsNothing -// restoretest_due_test.go:226: an agent restart must not trigger a restore-test; 2 restart(s) -// produced 4 run(s) +// +// restoretest_due_test.go:226: an agent restart must not trigger a restore-test; 2 restart(s) +// produced 4 run(s) // // Four: the same already-proven archive re-tested on EVERY evaluation after EVERY restart, which is // today's behaviour with the ticker's phase reset by the deploy. Restored. @@ -256,12 +259,13 @@ func TestDue_NewSettledArchiveMakesAProvedTierDueAgain(t *testing.T) { // // COMPANION RED-PROOF (observed 2026-08-03): give credit on failure in Scheduler.tick — // -// - if rt.Pass && s.rtState != nil && target != "" { -// + if s.rtState != nil && target != "" { +// - if rt.Pass && s.rtState != nil && target != "" { +// - if s.rtState != nil && target != "" { // // → --- FAIL: TestDue_FailingTierIsRetriedAndNeverProven -// restoretest_due_test.go: a failing tier must keep being retried; got 1 run(s) over 3 -// evaluations +// +// restoretest_due_test.go: a failing tier must keep being retried; got 1 run(s) over 3 +// evaluations // // A single failure would have retired the archive as proven — a permanently broken DR tier looking // freshly verified, which is the loudest signal this system produces going silent. Restored. @@ -456,3 +460,48 @@ func TestRestoreTestState_ArchiveRoundTrips(t *testing.T) { func writeFileForTest(path, content string) error { return os.WriteFile(path, []byte(content), 0o600) } + +// Standing rule 3: an absent log line is not evidence. "Nothing is due" is now the NORMAL outcome of +// an evaluation, so it must produce a POSITIVE observable naming each tier's verdict — otherwise a +// quiet journal is equally consistent with a healthy loop and a dead goroutine. +// +// COMPANION RED-PROOF (observed 2026-08-03): drop the summary back to a bare +// `s.logger.Debug("backup: restore-test not due this evaluation")` and this fails with +// "a not-due evaluation must name each tier's verdict; got \"\"" — i.e. nothing at INFO at all. +func TestDue_NothingDueStillNamesEveryTiersVerdict(t *testing.T) { + ts := &tierStorage{archives: map[string][]archiveStub{ + "local": {{volid: "local:backup/a.tar.zst", landed: day0}}, + "felhom-pbs": nil, // no archive at all + }} + h := newDueHarness(t, day0.AddDate(0, 0, 1), 24*time.Hour, true, []string{"local", "felhom-pbs"}, ts) + // Prove the local tier so NOTHING is due. + if err := h.st.RecordSuccess("local", "local:backup/a.tar.zst", h.clock); err != nil { + t.Fatal(err) + } + + // Assert what the SCHEDULER emits on a real evaluation, not what a helper returns — a helper + // test would pass against a tick that never calls it. + var logbuf strings.Builder + h.s.logger = slog.New(slog.NewTextHandler(&logbuf, &slog.HandlerOptions{Level: slog.LevelInfo})) + h.s.tick(context.Background()) + got := logbuf.String() + for _, want := range []string{"local", "felhom-pbs", "already proven", "no settled archive"} { + if !strings.Contains(got, want) { + t.Fatalf("a not-due evaluation must name each tier's verdict; got %q (missing %q)", got, want) + } + } +} + +// A tier whose storage cannot be listed must say UNKNOWN in that same line — a lookup failure that +// reads as "nothing due" is the silence this rule exists to prevent. +func TestDue_VerdictSummaryNamesAnUnknownTier(t *testing.T) { + ts := &tierStorage{ + archives: map[string][]archiveStub{"local": nil}, + err: map[string]error{"felhom-pbs": errors.New("storage unreachable")}, + } + h := newDueHarness(t, day0, 24*time.Hour, true, []string{"local", "felhom-pbs"}, ts) + got := h.s.verdictSummary(context.Background()) + if !strings.Contains(got, "UNKNOWN") || !strings.Contains(got, "storage unreachable") { + t.Fatalf("an unlistable tier must read as UNKNOWN with its error; got %q", got) + } +} diff --git a/internal/backup/schedule.go b/internal/backup/schedule.go index e8f163e..2feec29 100644 --- a/internal/backup/schedule.go +++ b/internal/backup/schedule.go @@ -180,7 +180,15 @@ func (s *Scheduler) tick(ctx context.Context) { return } if archive == "" { - s.logger.Debug("backup: restore-test not due this evaluation") + // A POSITIVE OBSERVABLE, at INFO, and this is not noise — it is standing rule 3. + // + // Before R-86 every tick ran a heavy restore-test, so the scheduler was audible by + // construction. Now "nothing is due" is the NORMAL outcome, and at DEBUG it is silent: an + // empty journal would be equally consistent with a healthy loop and with a dead goroutine, + // which is the exact shape the R-88 watcher was retired for. One line per evaluation is four + // lines a day at the 6h default, and it names each tier's verdict so the answer to "why did + // nothing run last night?" is in the log rather than in a re-derivation. + s.logger.Info("backup: restore-test evaluated — nothing due", "verdicts", s.verdictSummary(ctx)) return }