diff --git a/CHANGELOG.md b/CHANGELOG.md index 630c3c8..21ebf48 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,22 @@ ## Changelog +### v0.191.2 — a quiet fill check now says so (2026-08-02, R-167) — MinAgent: none + +**Earned during v0.191.1's own live validation, which is the strongest evidence it was needed.** After +the customer had been warned about `/mnt/sys_drive`, the controller was restarted and produced **zero +`fillwatch` log lines** — and that was read, correctly, as unusable: an absent line is equally +consistent with *"the check ran and chose silence"* and *"the check never ran"*. Proving the checker +was alive required deliberately crossing into the critical band. + +That ambiguity is **permanent, not rare, for this check specifically**: it is edge-triggered, so the +HEALTHY STEADY STATE IS A QUIET RUN. Standing rule 3 aimed at the one place it costs most. + +`Check` now logs a per-RUN summary — `checked N filesystem(s), M unreadable/skipped, K +notification(s); bands: …` — on every run, healthy or not. **Unreadable is counted separately from +healthy**, so a drive that has quietly gone unreadable for weeks cannot read as "all fine". Two tests +pin it, including that a second, equally quiet run logs again (the observable is per run, not per +change). + ### v0.191.1 — the fill check also runs at startup (2026-08-02, R-167) — MinAgent: none **Found while live-validating v0.191.0 on guest 9201: the fill check was reachable only on its daily diff --git a/controller/internal/fillwatch/fillwatch.go b/controller/internal/fillwatch/fillwatch.go index 04230e2..a677beb 100644 --- a/controller/internal/fillwatch/fillwatch.go +++ b/controller/internal/fillwatch/fillwatch.go @@ -195,6 +195,7 @@ func (w *Watcher) Check() error { targets := w.targets() seen := make(map[string]bool, len(targets)) changed := false + var checked, skipped, emitted int for _, t := range targets { if t.Path == "" { @@ -208,8 +209,10 @@ func (w *Watcher) Check() error { // backup_target_absent). Reporting it as "full" would be a false alarm with a misleading // cause, and would tell the customer to delete files that are not the problem. w.logger.Printf("[DEBUG] [fillwatch] %s: usage unreadable — skipped (an unreadable filesystem is not a full one)", t.Path) + skipped++ continue } + checked++ prev := w.bands[t.Path] next := classify(*u, prev) if next == prev { @@ -230,6 +233,7 @@ func (w *Watcher) Check() error { msg := Message(t, *u, next) w.logger.Printf("[WARN] [fillwatch] %s (%q): %s → %s — %.0f%% used, %.1f GB free of %.1f GB; notifying the customer", t.Path, t.Label, prev, next, u.UsedPercent, u.AvailGB, u.TotalGB) + emitted++ if w.notify != nil { w.notify(Event{Target: t, Band: next, Usage: *u, Message: msg}) } @@ -244,12 +248,38 @@ func (w *Watcher) Check() error { } } + // A POSITIVE OBSERVABLE, every run, healthy or not (standing rule 3). Without it a quiet run is + // indistinguishable from a checker that never ran — and because this check is edge-triggered, the + // HEALTHY steady state IS a quiet run, so the ambiguity is permanent rather than rare. It was hit + // for real while live-validating v0.191.1 on 9201: an unchanged band produced zero log lines, and + // proving the checker was alive needed a deliberate threshold crossing. + w.logger.Printf("[INFO] [fillwatch] checked %d filesystem(s), %d unreadable/skipped, %d notification(s); bands: %s", + checked, skipped, emitted, w.bandSummaryLocked()) + if !changed { return nil } return w.saveLocked() } +// bandSummaryLocked renders the current per-path bands for the run summary, deterministically. Caller +// holds w.mu. +func (w *Watcher) bandSummaryLocked() string { + if len(w.bands) == 0 { + return "all ok" + } + paths := make([]string, 0, len(w.bands)) + for p := range w.bands { + paths = append(paths, p) + } + sort.Strings(paths) + parts := make([]string, 0, len(paths)) + for _, p := range paths { + parts = append(parts, p+"="+w.bands[p].String()) + } + return strings.Join(parts, " ") +} + // Bands returns a copy of the current per-path state (diagnostics + tests). func (w *Watcher) Bands() map[string]Band { w.mu.Lock() diff --git a/controller/internal/fillwatch/fillwatch_test.go b/controller/internal/fillwatch/fillwatch_test.go index a5ba9c5..2b02a30 100644 --- a/controller/internal/fillwatch/fillwatch_test.go +++ b/controller/internal/fillwatch/fillwatch_test.go @@ -318,3 +318,56 @@ func TestVanishedTargetIsForgotten(t *testing.T) { "re-added drive would resume from a stale band instead of warning afresh") } } + +// --- The run summary is the POSITIVE OBSERVABLE --------------------------------------------------- + +// Standing rule 3, aimed at the one place it bites hardest here: this check is edge-triggered, so the +// HEALTHY STEADY STATE IS A QUIET RUN. Without a per-run summary line, "the checker ran and correctly +// said nothing" and "the checker is dead" produce byte-identical logs, permanently. +// +// This was hit for real while live-validating v0.191.1 on guest 9201: an unchanged band produced zero +// log lines, and proving the checker was alive required a deliberate threshold crossing. +func TestEveryRunLogsAPositiveObservable(t *testing.T) { + var buf strings.Builder + usage := map[string]*Usage{photos.Path: {UsedPercent: 40, AvailGB: 60, TotalGB: 100}} + w := New(filepath.Join(t.TempDir(), "s.json"), log.New(&buf, "", 0), + func() []Target { return []Target{photos} }, + func(p string) *Usage { return usage[p] }) + + if err := w.Check(); err != nil { + t.Fatal(err) + } + out := buf.String() + if !strings.Contains(out, "[fillwatch] checked 1 filesystem(s)") { + t.Fatalf("a HEALTHY run logged no summary — a quiet run is then indistinguishable from a "+ + "checker that never ran, and for an edge-triggered check that is the normal state. Got:\n%s", out) + } + if !strings.Contains(out, "all ok") { + t.Fatalf("the summary does not report the bands. Got:\n%s", out) + } + + // And a second, equally quiet run must log again — the observable is per RUN, not per change. + buf.Reset() + if err := w.Check(); err != nil { + t.Fatal(err) + } + if !strings.Contains(buf.String(), "checked 1 filesystem(s)") { + t.Fatalf("the second unchanged run logged nothing. Got:\n%s", buf.String()) + } +} + +// The summary must distinguish an unreadable filesystem from a healthy one — otherwise a drive that +// has silently gone unreadable for weeks reads as "all fine". +func TestSummaryCountsUnreadableSeparately(t *testing.T) { + var buf strings.Builder + w := New(filepath.Join(t.TempDir(), "s.json"), log.New(&buf, "", 0), + func() []Target { return []Target{photos} }, + func(string) *Usage { return nil }) + if err := w.Check(); err != nil { + t.Fatal(err) + } + if !strings.Contains(buf.String(), "checked 0 filesystem(s), 1 unreadable/skipped") { + t.Fatalf("an unreadable filesystem is not distinguished in the summary — it would read as a "+ + "healthy check. Got:\n%s", buf.String()) + } +}