felhom-controller/controller/internal/backup/offbox_progress_test.go

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)
	}
}

// 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)
	}
}