v0.121.1: 'nothing is due' must be AUDIBLE (R-86 + standing rule 3)
gates / gates (push) Successful in 6s

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.
This commit is contained in:
2026-08-03 15:26:54 +02:00
parent 4d82591052
commit 53d0c6bfc4
4 changed files with 119 additions and 11 deletions
+26
View File
@@ -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
}
+59 -10
View File
@@ -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)
}
}
+9 -1
View File
@@ -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
}