scan: show each phase as N of M, with progress, elapsed time and ETA, also while it waits (closes #112)

Every scan display now starts with its phase and its place among the
five, as "[2/5] walk", and always shows the rate, elapsed time and
ETA. load counts the records before reading them, and the content
phase counts what its search finds before checking it, so both have
totals; until then the line says what the phase waits for. The walk's
total is estimated from the records under the operands, with the ETA
unknown past the estimate or without one. Each display draws from its
own goroutine under one mutex: several times a second on a terminal,
every 5 seconds in plain mode. scanPhase holds the phase list.

Judgement call: on a terminal the line is the plain line behind the library's spinner; the bar graphic is gone.
Judgement call: the content phase runs its search query twice, once to count its rows.

Model: opus-5-5

progress_test.go

@@ -8,9 +8,13 @@ import (
 	"time"
 )
 
-// spinnerIdle comfortably outlasts the 100ms interval at which the
-// progressbar library redraws a spinner from its own goroutine.
-const spinnerIdle = 500 * time.Millisecond
+// testRedraw is the redraw interval the tests give a display, so that
+// many redraws fit in a few milliseconds.
+const testRedraw = time.Millisecond
+
+// testDeadline bounds how long a test waits for a display to draw what
+// it expects.
+const testDeadline = 5 * time.Second
 
 //nolint:paralleltest // replaces the process-wide os.Stderr
 func TestStderrIsTTYFalseForNonTerminals(t *testing.T) {
@@ -54,59 +58,217 @@ func TestStderrIsTTYFalseForNonTerminals(t *testing.T) {
 	}
 }
 
-// TestNewProgressPrintsBeforeFirstItem checks that each pass shows its
-// zero state the moment it starts when stderr is not a terminal, and
-// that the next line still waits for plainInterval.
+func TestPhaseLabel(t *testing.T) {
+	t.Parallel()
+
+	phases := []string{"load", "walk", "hash"}
+	if got := phaseLabel(phases, "walk"); got != "[2/3] walk" {
+		t.Errorf("phaseLabel = %q, want %q", got, "[2/3] walk")
+	}
+}
+
+// TestProgressLine checks the line a display shows in each state, ten
+// seconds into the phase.
+func TestProgressLine(t *testing.T) {
+	t.Parallel()
+
+	ago := time.Now().Add(-10 * time.Second)
+
+	cases := []struct {
+		p    *progress
+		want string
+	}{{
+		p: &progress{
+			label: scanPhase("load"), total: -1,
+			waitingFor: "counting the records",
+		},
+		want: "[1/5] load: counting the records, elapsed 10s, eta unknown",
+	}, {
+		p:    &progress{label: scanPhase("hash"), total: 100, count: 20},
+		want: "[3/5] hash: [20/100] 20%, 2 files/s, elapsed 10s, eta 40s",
+	}, {
+		p:    &progress{label: scanPhase("hash"), total: 100},
+		want: "[3/5] hash: [0/100] 0%, 0 files/s, elapsed 10s, eta unknown",
+	}, {
+		p:    &progress{label: scanPhase("update"), total: 0},
+		want: "[4/5] update: [0/0] 100%, 0 files/s, elapsed 10s, eta 0s",
+	}, {
+		p: &progress{
+			label: scanPhase("walk"), total: 100, estimate: true, count: 20,
+		},
+		want: "[2/5] walk: [20/~100] 20%, 2 files/s, elapsed 10s, eta 40s",
+	}, {
+		// Past the estimate the walk cannot tell how long it has left.
+		p: &progress{
+			label: scanPhase("walk"), total: 100, estimate: true, count: 120,
+		},
+		want: "[2/5] walk: [120/~100] 120%, 12 files/s, elapsed 10s, " +
+			"eta unknown",
+	}, {
+		// A first scan's walk has no estimate.
+		p:    &progress{label: scanPhase("walk"), total: -1, count: 20},
+		want: "[2/5] walk: 20 files, 2 files/s, elapsed 10s, eta unknown",
+	}}
+
+	for _, tc := range cases {
+		tc.p.start, tc.p.rateStart = ago, ago
+
+		if got := tc.p.line(); got != tc.want {
+			t.Errorf("line = %q, want %q", got, tc.want)
+		}
+	}
+}
+
+// TestSetTotalStartsRate checks that a phase's rate, and so its ETA,
+// count from when its total became known, not from when it started
+// waiting for it.
+func TestSetTotalStartsRate(t *testing.T) {
+	t.Parallel()
+
+	p := progress{
+		label: scanPhase("load"), total: 100, count: 20,
+		start:     time.Now().Add(-20 * time.Second),
+		rateStart: time.Now().Add(-10 * time.Second),
+	}
+
+	want := "[1/5] load: [20/100] 20%, 2 files/s, elapsed 20s, eta 40s"
+	if got := p.line(); got != want {
+		t.Errorf("line = %q, want %q", got, want)
+	}
+}
+
+// TestPlainProgressPrintsAtStartAndEnd checks that when stderr is not a
+// terminal a phase prints its line the moment it starts, before its
+// first item, nothing for the items it completes before plainInterval
+// has passed, and its line again as it ends.
 //
 //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
-func TestNewProgressPrintsBeforeFirstItem(t *testing.T) {
+func TestPlainProgressPrintsAtStartAndEnd(t *testing.T) {
 	stderr := captureStderr(t)
+	p := newProgress(progressParams{label: scanPhase("hash"), total: 1000})
 
-	newProgress("walk", -1).increment()
-	newProgress("hash", 10).increment()
+	for range 1000 {
+		p.increment()
+	}
 
-	want := "walk: 0 files, elapsed 0s\n" +
-		"hash: [0/10] 0% 0 files/s elapsed 0s eta ?\n"
-	if got := stderr(); got != want {
-		t.Errorf("stderr = %q, want %q", got, want)
+	p.finish()
+
+	lines := strings.Split(strings.TrimSuffix(stderr(), "\n"), "\n")
+
+	want := "[3/5] hash: [0/1000] 0%, 0 files/s, elapsed 0s, eta unknown"
+	if len(lines) != 2 || lines[0] != want ||
+		!strings.HasPrefix(lines[1], "[3/5] hash: [1000/1000] 100%, ") {
+		t.Errorf("stderr lines = %q, want %q, then the line at 1000",
+			lines, want)
 	}
 }
 
-// newWalkSpinner returns the walk pass's terminal display, writing to
-// os.Stderr whether or not it is a terminal, and stops the library's
-// redraws when the test ends.
-func newWalkSpinner(t *testing.T) *progress {
+// TestPlainProgressPrintsWhileWaiting checks that a phase waiting with
+// no completed items still prints a line every interval.
+//
+//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
+func TestPlainProgressPrintsWhileWaiting(t *testing.T) {
+	stderr := captureStderr(t)
+	p := startProgress(progressParams{
+		label: scanPhase("load"), total: -1,
+		waitingFor: "counting the records",
+	}, nil, testRedraw)
+
+	want := "[1/5] load: counting the records, elapsed 0s, eta unknown\n"
+	for deadline := time.Now().Add(testDeadline); strings.Count(stderr(),
+		want) < 3 && time.Now().Before(deadline); {
+		time.Sleep(testRedraw)
+	}
+
+	p.finish()
+
+	if got := stderr(); strings.Count(got, want) < 3 {
+		t.Errorf("stderr = %q, want %q at least three times", got, want)
+	}
+}
+
+// lastFrame returns what a terminal shows of the frames a display drew:
+// the last one. The library starts each frame with a carriage return
+// and erases the previous one with spaces first.
+func lastFrame(out string) string {
+	var shown string
+
+	for frame := range strings.SplitSeq(out, "\r") {
+		if strings.TrimSpace(frame) != "" {
+			shown = frame
+		}
+	}
+
+	return shown
+}
+
+// awaitFrame waits until the last frame a terminal display drew to
+// stderr shows want, and fails the test if it never does.
+func awaitFrame(t *testing.T, stderr func() string, want string) {
 	t.Helper()
 
-	p := &progress{
-		label: "walk", total: -1, start: time.Now(),
-		bar: newBar("walk", -1),
+	for deadline := time.Now().Add(testDeadline); !strings.Contains(
+		lastFrame(stderr()), want); time.Sleep(testRedraw) {
+		if time.Now().After(deadline) {
+			t.Fatalf("terminal shows %q, want %q", lastFrame(stderr()), want)
+		}
 	}
-	t.Cleanup(p.finish)
-
-	return p
 }
 
-// TestProgressWarningsOnOwnLines drives the terminal display of the walk
-// pass through a run of warnings with no items between them, as when the
-// walk meets many unreadable paths, for several of the spinner's
-// redraws: every warning must land on a line of its own, never inside a
-// redraw.
+// TestTerminalRedrawsWhileWaiting checks that the terminal display of a
+// phase, with a total or without, keeps showing the elapsed time while
+// the phase waits for its next item, and shows every item completed
+// before the wait.
+//
+//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
+func TestTerminalRedrawsWhileWaiting(t *testing.T) {
+	stderr := captureStderr(t)
+
+	counts := map[int64]string{-1: "50 files", 100: "[50/100]"}
+
+	for total, count := range counts {
+		p := startProgress(progressParams{
+			label: scanPhase("hash"), total: total,
+		}, newSpinner(), testRedraw)
+
+		for range 50 {
+			p.increment()
+		}
+
+		// An hour into the phase, without waiting an hour.
+		p.mu.Lock()
+		p.start = p.start.Add(-time.Hour)
+		p.mu.Unlock()
+
+		awaitFrame(t, stderr, "elapsed 1h0m0s")
+
+		if shown := lastFrame(stderr()); !strings.Contains(shown, count) {
+			t.Errorf("terminal shows %q, want %q", shown, count)
+		}
+
+		p.finish()
+	}
+}
+
+// TestProgressWarningsOnOwnLines drives the terminal display through a
+// run of warnings with no items between them, as when the walk meets
+// many unreadable paths, for many redraws: every warning must land on a
+// line of its own, never inside a redraw.
 //
 //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
 func TestProgressWarningsOnOwnLines(t *testing.T) {
 	stderr := captureStderr(t)
-	p := newWalkSpinner(t)
+	p := startProgress(progressParams{label: scanPhase("walk"), total: -1},
+		newSpinner(), testRedraw)
 
 	// No pause between warnings: one written straight to stderr is
 	// garbled only if a redraw lands while it is being written.
 	issued := 0
-	for start := time.Now(); time.Since(start) < spinnerIdle; issued++ {
+	for start := time.Now(); time.Since(start) < 50*testRedraw; issued++ {
 		p.warnf("warning")
 	}
 
-	// The spinner prints the warnings at its next redraw.
-	time.Sleep(spinnerIdle)
+	p.finish()
 
 	// A terminal shows each line as the text after its last carriage
 	// return.
@@ -129,83 +291,41 @@ func TestProgressWarningsOnOwnLines(t *testing.T) {
 	}
 }
 
-// TestSpinnerShowsCountAfterBurst checks that once a burst of items
-// faster than the redraw limit is over, the walk display shows every
-// item completed while it waits for the next one.
+// TestTerminalStoppedShortKeepsCount checks that the terminal display
+// of a phase that stops before its total, as an interrupted one does,
+// is left showing the count it stopped at.
 //
 //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
-func TestSpinnerShowsCountAfterBurst(t *testing.T) {
+func TestTerminalStoppedShortKeepsCount(t *testing.T) {
 	stderr := captureStderr(t)
-	p := newWalkSpinner(t)
-
-	for range 50 {
-		p.increment()
-	}
-
-	time.Sleep(spinnerIdle)
-
-	if shown := lastFrame(stderr()); !strings.Contains(shown, "(50/-,") {
-		t.Errorf("terminal shows %q, want a count of 50", shown)
-	}
-}
-
-// lastFrame returns what a terminal shows of the frames a bar drew: the
-// last one. The library starts each frame with a carriage return and
-// erases the previous one with spaces first.
-func lastFrame(out string) string {
-	var shown string
-
-	for frame := range strings.SplitSeq(out, "\r") {
-		if strings.TrimSpace(frame) != "" {
-			shown = frame
-		}
-	}
-
-	return shown
-}
-
-// TestBarStoppedShortKeepsCount checks that the terminal display of a
-// pass that stops before its total, as an interrupted one does, is left
-// as last drawn instead of being filled up.
-//
-//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
-func TestBarStoppedShortKeepsCount(t *testing.T) {
-	stderr := captureStderr(t)
-	p := &progress{
-		label: "hash", total: 10, start: time.Now(),
-		bar: newBar("hash", 10),
-	}
+	p := startProgress(progressParams{label: scanPhase("hash"), total: 10},
+		newSpinner(), redrawInterval)
 
 	p.increment()
-
-	// Past the redraw limit, so the bar draws the next count.
-	time.Sleep(2 * barThrottle)
 	p.increment()
 	p.finish()
 
-	if shown := lastFrame(stderr()); !strings.Contains(shown, "(2/10,") {
+	if shown := lastFrame(stderr()); !strings.Contains(shown, "[2/10]") {
 		t.Errorf("terminal shows %q, want a count of 2 of 10", shown)
 	}
 }
 
-// TestWarningAfterLastItemKeepsBar checks that a warning printed after
-// a pass's last item, as for a failed read of the last file, leaves the
-// pass's finished bar on the terminal below the warning.
+// TestWarningAfterLastItemKeepsLine checks that a warning printed after
+// a phase's last item, as for a failed read of the last file, leaves
+// the phase's last line on the terminal below the warning.
 //
 //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
-func TestWarningAfterLastItemKeepsBar(t *testing.T) {
+func TestWarningAfterLastItemKeepsLine(t *testing.T) {
 	stderr := captureStderr(t)
-	p := &progress{
-		label: "hash", total: 2, start: time.Now(),
-		bar: newBar("hash", 2),
-	}
+	p := startProgress(progressParams{label: scanPhase("hash"), total: 2},
+		newSpinner(), redrawInterval)
 
 	p.increment()
 	p.increment()
 	p.warnf("warning")
 	p.finish()
 
-	if shown := lastFrame(stderr()); !strings.Contains(shown, "(2/2,") {
+	if shown := lastFrame(stderr()); !strings.Contains(shown, "[2/2]") {
 		t.Errorf("terminal shows %q, want a count of 2 of 2", shown)
 	}
 }