From 2a2af2018d6fa33f5773a53b4d3f7f3645c76931 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Sat, 3 Oct 2026 17:15:10 +0200 Subject: [PATCH] v0.289.1: strip the provider rclone notice; an unreadable snapshot count is never a measured zero (found live on demo-felhom) Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_0159rPz1ZhFKsS53msqPYxtS --- CHANGELOG.md | 14 +++++ controller/internal/backup/offbox.go | 54 +++++++++++++++---- controller/internal/backup/offbox_3a_test.go | 2 +- .../internal/backup/offbox_window_test.go | 31 +++++++++++ 4 files changed, 89 insertions(+), 12 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index d0f5882..8456b96 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,17 @@ +## v0.289.1 — the provider's rclone notice no longer reads as "0 snapshots" (found live on demo-felhom) (2026-10-03) + +**MinAgent: 0.131.0** (unchanged). Needs hub v0.127.0 (unchanged). + +- **Found live in the first run through the pinned key:** the provider's rclone prints + `NOTICE: Config file … not found - using defaults` on every connection, restic forwards it into the combined output, + every `--json` parse failed, and the box recorded **0 snapshots as MEASURED** (`stats_known`) over a store holding 12 — + the shape the hub's R-431 detector reads as a mass deletion — and the clean-up step could not list snapshots. + `Manager.runner()` now strips exactly that notice line (`stripRcloneNotice`; an rclone ERROR line stays). +- **An unreadable snapshot count is no longer a measured zero (R-331 class):** `offboxRecordStats` returns + `(count, ok)`; on a failed or unparseable listing the box keeps the last measured count and reports `stats_known=false`. +- Tests: `TestStripRcloneNotice`, `TestRunOffbox_UnreadableCountIsNotZero` (red-proved). **Second release this session, + against the one-release rule, because v0.289.0 was live on a box and reporting a false zero.** + ## v0.289.0 — the off-site key cannot delete: append-only transport, no password on the box, retention only inside a hub window (decisions 68–69, R-820, R-822) (2026-10-03) **MinAgent: 0.131.0** (unchanged). **Needs hub v0.127.0** (the key registrar and the window endpoints; an older hub diff --git a/controller/internal/backup/offbox.go b/controller/internal/backup/offbox.go index b8ab8c4..72b32a0 100644 --- a/controller/internal/backup/offbox.go +++ b/controller/internal/backup/offbox.go @@ -1,6 +1,7 @@ package backup import ( + "bytes" "context" "crypto/rand" "crypto/sha256" @@ -425,10 +426,32 @@ func (m *Manager) offboxSize() func(string) int64 { } func (m *Manager) runner() offboxRunner { + r := defaultOffboxRunner if m.offboxRunner != nil { - return m.offboxRunner + r = m.offboxRunner } - return defaultOffboxRunner + return func(ctx context.Context, env []string, args ...string) ([]byte, error) { + out, err := r(ctx, env, args...) + return stripRcloneNotice(out), err + } +} + +// rcloneNoticeRe is the ONE line the provider's rclone prints on every connection of the pinned +// transport (v0.289.0) — restic forwards it with an "rclone: " prefix into the combined output: +// +// rclone: 2026/10/03 15:05:42 NOTICE: Config file "/home/.config/rclone/rclone.conf" not found - using defaults +// +// MEASURED LIVE on demo-felhom 2026-10-03: left in, every `--json` parse failed ("invalid character +// 'r'"), so the box recorded 0 snapshots AS MEASURED (StatsKnown) over a store holding 12 — the exact +// shape R-431's detector reads as a mass deletion. Only this exact notice is removed; any other rclone +// line (an error) stays in the output. Pinned by TestStripRcloneNotice. +var rcloneNoticeRe = regexp.MustCompile(`(?m)^rclone: \d{4}/\d\d/\d\d \d\d:\d\d:\d\d NOTICE: Config file "[^"]*rclone\.conf" not found - using defaults\r?\n?`) + +func stripRcloneNotice(out []byte) []byte { + if len(out) == 0 || !bytes.Contains(out, []byte("rclone: ")) { + return out + } + return rcloneNoticeRe.ReplaceAll(out, nil) } func (m *Manager) offboxDir() string { return filepath.Join(m.cfg.Paths.DataDir, "offbox") } @@ -1034,9 +1057,9 @@ func (m *Manager) runOffboxBackup(ctx context.Context, withProgress bool) error } dur := time.Since(start) - snapshots := 0 + snapshots, countKnown := 0, false if runErr == nil { - snapshots = m.offboxRecordStats(ctx, base, env) + snapshots, countKnown = m.offboxRecordStats(ctx, base, env) } // THE LANGUAGE IS RESOLVED HERE, OUTSIDE THE CALLBACK, AND IT IS NOT A STYLE CHOICE. // @@ -1114,8 +1137,15 @@ func (m *Manager) runOffboxBackup(ctx context.Context, withProgress bool) error o.LastStatus = "ok" } o.LastError = "" - o.SnapshotCount = snapshots - o.StatsKnown = true // R-225: measured, even if the answer is zero + if countKnown { + o.SnapshotCount = snapshots + o.StatsKnown = true // R-225: measured, even if the answer is zero + } else { + // v0.289.0: the listing FAILED — that is not a measurement of zero (R-331). Keep the + // last measured count and say it is not known now; a reported 0 here reads as a mass + // deletion to the hub (R-431). Pinned by TestRunOffbox_UnreadableCountIsNotZero. + o.StatsKnown = false + } o.EnlargedBlocked = blockedNames // replace each run (sorted); empty slice clears it var warns []string warnKind := "" @@ -1832,18 +1862,20 @@ func (m *Manager) offboxPruneOnly(ctx context.Context, base, env []string) { } // offboxRecordStats reads the snapshot count (best-effort) for the UI; also fills repo size when stats works. -func (m *Manager) offboxRecordStats(ctx context.Context, base, env []string) int { +func (m *Manager) offboxRecordStats(ctx context.Context, base, env []string) (int, bool) { sctx, cancel := context.WithTimeout(ctx, offboxProbeTimeout) defer cancel() out, err := m.runner()(sctx, env, append(append([]string{}, base...), "snapshots", "--json")...) if err != nil { - return 0 + m.logger.Printf("[WARN] [offbox] snapshot count unreadable (kept the last measured value): %v", err) + return 0, false } var snaps []struct { ID string `json:"id"` } - if json.Unmarshal(out, &snaps) != nil { - return 0 + if jerr := json.Unmarshal(out, &snaps); jerr != nil { + m.logger.Printf("[WARN] [offbox] snapshot count unparseable (kept the last measured value): %v", jerr) + return 0, false } // Repo size (best-effort, RAW-DATA mode). SP-1: `--mode raw-data` reports the actual // deduplicated+compressed repo bytes (what the Storage Box really fills), not the modeless @@ -1863,7 +1895,7 @@ func (m *Manager) offboxRecordStats(ctx context.Context, base, env []string) int }) } } - return len(snaps) + return len(snaps), true } // RestoreOffbox restores an app's latest off-box snapshot to destDir (a scratch/verify location — it does diff --git a/controller/internal/backup/offbox_3a_test.go b/controller/internal/backup/offbox_3a_test.go index 9f4b0f7..35ff7ec 100644 --- a/controller/internal/backup/offbox_3a_test.go +++ b/controller/internal/backup/offbox_3a_test.go @@ -367,7 +367,7 @@ func TestOffbox3a_StatsRawDataMode(t *testing.T) { return nil, nil }) base, env := m.offboxBaseArgs(sett.GetOffboxTarget()) - m.offboxRecordStats(context.Background(), base, env) + _, _ = m.offboxRecordStats(context.Background(), base, env) if !contains(statsArgs, "--mode") || valAfter(statsArgs, "--mode") != "raw-data" { t.Fatalf("stats must run in raw-data mode, got %v", statsArgs) } diff --git a/controller/internal/backup/offbox_window_test.go b/controller/internal/backup/offbox_window_test.go index 0827498..7a08e08 100644 --- a/controller/internal/backup/offbox_window_test.go +++ b/controller/internal/backup/offbox_window_test.go @@ -235,3 +235,34 @@ func TestAbandon_PinnedDefersToOperator(t *testing.T) { t.Fatal("second sweep deleted") } } + +// The provider's rclone notice must not reach a JSON parser — measured live on demo-felhom (v0.289.0). +func TestStripRcloneNotice(t *testing.T) { + in := "rclone: 2026/10/03 15:05:42 NOTICE: Config file \"/home/.config/rclone/rclone.conf\" not found - using defaults\n[{\"id\":\"s1\"}]\n" + if got := string(stripRcloneNotice([]byte(in))); got != "[{\"id\":\"s1\"}]\n" { + t.Fatalf("got %q", got) + } + keep := "rclone: 2026/10/03 15:05:42 ERROR : something real\n" + if got := string(stripRcloneNotice([]byte(keep))); got != keep { + t.Fatalf("an rclone ERROR line was stripped: %q", got) + } +} + +// THE CONSEQUENCE (R-331/R-431): a run whose snapshot listing cannot be read must NOT record 0 as a +// measurement. Before the fix the box reported 0 snapshots with stats_known over a store holding 12. +func TestRunOffbox_UnreadableCountIsNotZero(t *testing.T) { + m, sett := newOffboxManager(t) + sett.UpdateOffboxStatus(func(o *settings.OffboxTarget) { o.SnapshotCount, o.StatsKnown = 11, true }) + m.SetOffboxRunner(func(ctx context.Context, env []string, args ...string) ([]byte, error) { + if contains(args, "snapshots") { + return []byte("rclone: 2026/10/03 15:05:42 ERROR : boom\nnot json"), nil + } + rr := &recordingOffboxRunner{} + return rr.run(ctx, env, args...) + }) + _ = m.RunOffboxBackup(context.Background()) + got := sett.GetOffboxTarget() + if got.StatsKnown && got.SnapshotCount == 0 { + t.Fatalf("an unreadable count was recorded as a measured zero: %+v", got.SnapshotCount) + } +}