package backup import ( "context" "strings" "testing" ) // v0.147.0 slice 4c — live progress for a MANUAL offsite run. // // These tests exercise the WHOLE path a real run takes: a fake restic emits canned `--json` status // lines through the streaming seam, and the assertion is on what the poll surface // (OffboxProgressSnapshot) reports — not on the parser in isolation. A parser that works but is // never wired to the snapshot would leave the customer looking at the same silent spinner, which is // the bug being fixed. // // RED-PROOF (run manually, both confirmed to fail): // 1. break the parser — flip `s.MessageType != "status"` to `== "status"` in parseResticStatus: // TestManualRunReportsParsedProgress fails ("percent = 0, want 42"). // 2. drop the wiring — make resticBackupStep always delegate to resticStep: // the same test fails (no --json, no stream, no snapshot). // jsonStatus is one restic --json status line. func jsonStatus(pct float64, done, total int64) string { return `{"message_type":"status","percent_done":` + ftoa(pct) + `,"total_bytes":` + itoa(total) + `,"bytes_done":` + itoa(done) + `}` } func ftoa(f float64) string { // small helper — avoids strconv import noise in the canned lines switch f { case 0: return "0" case 0.42: return "0.42" case 1: return "1" } return "0.5" } func itoa(i int64) string { if i == 0 { return "0" } var b []byte neg := i < 0 if neg { i = -i } for i > 0 { b = append([]byte{byte('0' + i%10)}, b...) i /= 10 } if neg { return "-" + string(b) } return string(b) } // TestManualRunReportsParsedProgress is the headline: a manual run driven by a fake restic that emits // --json status lines must make OffboxProgressSnapshot report the parsed percentage, byte counts and // the app currently being pushed. func TestManualRunReportsParsedProgress(t *testing.T) { e := newSharesOffboxEnv(t, "immich") if err := e.sett.SetSMBEnabled(false); err != nil { // keep this test to the app leg only t.Fatal(err) } var seen []OffboxProgress var sawJSONFlag bool e.m.SetOffboxStreamRunner(func(ctx context.Context, env []string, onLine func(string), args ...string) ([]byte, error) { for _, a := range args { if a == "--json" { sawJSONFlag = true } } // Emit a scan phase (total not yet known), then real progress, sampling the published // snapshot after each line exactly as the polling page would. onLine(jsonStatus(0, 0, 0)) seen = append(seen, e.m.OffboxProgressSnapshot()) onLine(`{"message_type":"verbose_status","action":"unchanged"}`) // must be ignored, not fatal onLine(jsonStatus(0.42, 4200, 10000)) seen = append(seen, e.m.OffboxProgressSnapshot()) return []byte(`{"message_type":"summary","snapshot_id":"abc"}`), nil }) // The non-streaming seam still serves every other restic call (cat config, forget, snapshots…). e.m.SetOffboxRunner(func(ctx context.Context, env []string, args ...string) ([]byte, error) { if contains(args, "snapshots") { return []byte(`[]`), nil } return []byte(""), nil }) if err := e.m.RunOffboxBackupWithProgress(context.Background()); err != nil { t.Fatalf("manual run: %v", err) } if !sawJSONFlag { t.Fatal("the manual backup leg did not pass --json to restic — nothing could ever be parsed") } if len(seen) != 2 { t.Fatalf("expected 2 sampled snapshots, got %d", len(seen)) } // While restic is still scanning, total is unknown: report 0 rather than inventing a percentage. if seen[0].TotalBytes != 0 || seen[0].Percent != 0 { t.Errorf("scan phase: got %+v, want zeroed counters", seen[0]) } if seen[0].CurrentApp != "immich" { t.Errorf("scan phase: current_app = %q, want %q", seen[0].CurrentApp, "immich") } got := seen[1] if got.Percent != 42 { t.Errorf("percent = %v, want 42", got.Percent) } if got.BytesDone != 4200 || got.TotalBytes != 10000 { t.Errorf("bytes = %d/%d, want 4200/10000", got.BytesDone, got.TotalBytes) } if got.CurrentApp != "immich" { t.Errorf("current_app = %q, want %q", got.CurrentApp, "immich") } if got.TotalHuman == "" || got.DoneHuman == "" { t.Errorf("humanized byte strings not populated: %+v", got) } if !got.Active { t.Error("progress reported inactive during a manual run") } // After the run the sink must be torn down, or the page would keep rendering a stale bar. if after := e.m.OffboxProgressSnapshot(); after.Active || after.Percent != 0 { t.Errorf("progress still published after the run: %+v", after) } } // TestNightlyRunStaysSilent pins the scope decision: the scheduled run must neither install the sink // nor pass --json, so its output format (and everything that greps it) is untouched. func TestNightlyRunStaysSilent(t *testing.T) { e := newSharesOffboxEnv(t, "immich") if err := e.sett.SetSMBEnabled(false); err != nil { t.Fatal(err) } e.m.SetOffboxStreamRunner(func(ctx context.Context, env []string, onLine func(string), args ...string) ([]byte, error) { t.Fatal("the nightly run used the streaming runner — progress must be manual-only") return nil, nil }) var backupArgs []string e.m.SetOffboxRunner(func(ctx context.Context, env []string, args ...string) ([]byte, error) { if contains(args, "backup") { backupArgs = append([]string{}, args...) } if contains(args, "snapshots") { return []byte(`[]`), nil } return []byte(""), nil }) if err := e.m.RunOffboxBackup(context.Background()); err != nil { t.Fatalf("nightly run: %v", err) } if backupArgs == nil { t.Fatal("no backup call was made") } if contains(backupArgs, "--json") { t.Errorf("the nightly run passed --json: %v", backupArgs) } if p := e.m.OffboxProgressSnapshot(); p.Active { t.Errorf("the nightly run published progress: %+v", p) } } // TestParseResticStatusIgnoresNonStatus covers the lines restic actually interleaves with status // output. An unknown message_type must be ignored, never mistaken for progress — restic adds new // types between versions. func TestParseResticStatusIgnoresNonStatus(t *testing.T) { for _, line := range []string{ `{"message_type":"summary","total_bytes_processed":123}`, `{"message_type":"verbose_status","action":"new"}`, `{"message_type":"error","error":{"message":"boom"}}`, `not json at all`, ``, `{}`, } { if _, ok := parseResticStatus(line); ok { t.Errorf("parsed a non-status line as progress: %q", line) } } r, ok := parseResticStatus(jsonStatus(0.42, 4200, 10000)) if !ok { t.Fatal("a real status line was not parsed") } if r.Percent != 42 || r.BytesDone != 4200 || r.TotalBytes != 10000 { t.Errorf("got %v %d %d, want 42 4200 10000", r.Percent, r.BytesDone, r.TotalBytes) } } // TestParseResticStatusIncrementalRun is the case that MATTERS and the one a synthetic test suite // would never think to write. It is a real status line shape from restic 0.14 on the demo box: // an incremental push where nothing changed transfers no new bytes, so restic omits bytes_done // entirely (`omitempty`) and percent_done stays 0 — while files_done climbs steadily. // // Measured live: a 430MB immich push reported 0% for 40+ seconds and then completed. A byte-only // progress bar is therefore indistinguishable from a hang in the COMMON case, which is the exact // failure 4c exists to remove. The file counters must survive parsing so the page can fall back to // them. func TestParseResticStatusIncrementalRun(t *testing.T) { // bytes_done and files_done absent — restic's scan-start state. r, ok := parseResticStatus(`{"message_type":"status","percent_done":0,"total_files":1,"total_bytes":112}`) if !ok { t.Fatal("scan-start status line was not parsed") } if r.BytesDone != 0 || r.TotalBytes != 112 || r.TotalFiles != 1 { t.Errorf("scan-start: got %+v", r) } // The incremental steady state: no bytes moving, files moving. r, ok = parseResticStatus(`{"message_type":"status","percent_done":0,"total_files":8123,"files_done":4110,"total_bytes":451130451}`) if !ok { t.Fatal("incremental status line was not parsed") } if r.BytesDone != 0 { t.Errorf("bytes_done = %d, want 0 (absent in the JSON)", r.BytesDone) } if r.FilesDone != 4110 || r.TotalFiles != 8123 { t.Errorf("file counters lost: got %d/%d, want 4110/8123 — the page has nothing left to move", r.FilesDone, r.TotalFiles) } if r.TotalBytes != 451130451 { t.Errorf("total_bytes = %d, want 451130451", r.TotalBytes) } } // TestParseResticStatusKeepsCurrentFileAndElapsed — the case where NO counter can move: restic 0.14 // only counts a file when it completes, so an app dominated by one big archive freezes bytes_done // AND files_done. Measured on the demo box: immich at 1 of 46 files, 0 bytes, for 42 seconds while // restic worked through a single ~430MB volume tar. current_files + seconds_elapsed are then the only // honest signals of liveness left, so losing them in parsing would put the bar back to looking hung. func TestParseResticStatusKeepsCurrentFileAndElapsed(t *testing.T) { line := `{"message_type":"status","seconds_elapsed":42,"percent_done":0,"total_files":46,` + `"files_done":1,"total_bytes":451130451,"current_files":["/mnt/hdd/felhom-data/backups/primary/immich/volumes/immich_upload.tar"]}` r, ok := parseResticStatus(line) if !ok { t.Fatal("status line was not parsed") } if r.ElapsedSec != 42 { t.Errorf("elapsed = %d, want 42", r.ElapsedSec) } if r.CurrentFile == "" { t.Fatal("current_file lost — with no counter moving this is the only liveness signal left") } if want := "immich_upload.tar"; !strings.HasSuffix(r.CurrentFile, want) { t.Errorf("current_file = %q, want it to end in %q", r.CurrentFile, want) } } // TestProgressKeepsLastKnownCurrentFile — restic omits current_files on some status ticks. Blanking // the label every other second is its own kind of flicker, so the last known value must persist. func TestProgressKeepsLastKnownCurrentFile(t *testing.T) { var st offboxProgressState st.begin() st.setApp("immich") st.update(resticProgress{CurrentFile: "/data/big.tar", ElapsedSec: 5, TotalFiles: 46, FilesDone: 1}) st.update(resticProgress{CurrentFile: "", ElapsedSec: 7, TotalFiles: 46, FilesDone: 1}) // tick without current_files if got := st.snapshot().CurrentFile; got != "/data/big.tar" { t.Errorf("current_file = %q after a tick that omitted it, want the last known value", got) } if got := st.snapshot().ElapsedSec; got != 7 { t.Errorf("elapsed = %d, want it to keep advancing (7)", got) } // A new app must clear it — otherwise the previous app's file is shown against the next one. st.setApp("nextcloud") if got := st.snapshot().CurrentFile; got != "" { t.Errorf("current_file = %q after switching app, want cleared", got) } } // TestSetPhaseClearsAppScopedCounters — a run is not only the per-app loop. The shares leg and // forget --prune follow it and took 40 of a 57-second run on the demo box. Without a phase the card // kept showing the last app's finished counters ("calibre-web 8 / 8") for that whole tail, which is // the same frozen-looking silence 4c exists to remove, just relocated to the end of the run. func TestSetPhaseClearsAppScopedCounters(t *testing.T) { var st offboxProgressState st.begin() st.setApp("calibre-web") st.update(resticProgress{Percent: 100, BytesDone: 850000, TotalBytes: 850000, FilesDone: 8, TotalFiles: 8, CurrentFile: "/data/x"}) st.setPhase(OffboxPhaseRetention) got := st.snapshot() if got.Phase != OffboxPhaseRetention { t.Errorf("phase = %q, want %q", got.Phase, OffboxPhaseRetention) } if got.CurrentApp != "" || got.FilesDone != 0 || got.TotalFiles != 0 || got.BytesDone != 0 || got.CurrentFile != "" { t.Errorf("app-scoped counters survived the phase switch: %+v — the card would show the last "+ "app's finished numbers against retention work", got) } // Starting another app must clear the phase again, or the card would stay on „Karbantartás". st.setApp("immich") if p := st.snapshot(); p.Phase != "" || p.CurrentApp != "immich" { t.Errorf("after setApp: phase=%q app=%q, want phase cleared and app set", p.Phase, p.CurrentApp) } } // TestParseResticStatusClampsPercent — restic has been seen to report percent_done slightly above 1 // near completion. A bar wider than its track is a visible bug. func TestParseResticStatusClampsPercent(t *testing.T) { r, ok := parseResticStatus(`{"message_type":"status","percent_done":1.04}`) if !ok || r.Percent != 100 { t.Errorf("percent = %v (ok=%v), want clamped to 100", r.Percent, ok) } r, ok = parseResticStatus(`{"message_type":"status","percent_done":-0.2}`) if !ok || r.Percent != 0 { t.Errorf("percent = %v (ok=%v), want clamped to 0", r.Percent, ok) } } // TestLineTailKeepsOnlyTheTail — the --json stream of a large backup is megabytes of status spam, and // every caller uses this output for error diagnosis and lock-pattern matching. Buffering all of it // would be a memory leak proportional to backup size. func TestLineTailKeepsOnlyTheTail(t *testing.T) { var tl lineTail for i := 0; i < 500; i++ { tl.add("line-" + itoa(int64(i))) } out := string(tl.bytes()) if strings.Contains(out, "line-0\n") { t.Error("the oldest line survived — the tail is unbounded") } if !strings.Contains(out, "line-499") { t.Error("the newest line was dropped") } if n := strings.Count(out, "\n"); n > 64 { t.Errorf("tail kept %d lines, want a small bounded number", n) } }