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 shows its progress, rate, elapsed time and
ETA. On a terminal hash, update and the content reads keep the
library's bar, which fills what the rest of the line leaves; load,
the walk and the content checks are a spinner whose text is cut to
the terminal's width. load counts the records first. The content
phase adds up the sizes of the matching groups, without the join and
sort, and says it is searching until the first record returns. The
walk's total is estimated from the records under the operands. Each
display is drawn from its own goroutine: several times a second on a
terminal, every 5 seconds in plain mode.

Judgement call: load and the content checks stay spinners once their totals are known.

Model: opus-5-5

progress_test.go

@@ -6,11 +6,16 @@ import (
 	"strings"
 	"testing"
 	"time"
+	"unicode/utf8"
 )
 
-// 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 +59,277 @@ 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.
-//
-//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
-func TestNewProgressPrintsBeforeFirstItem(t *testing.T) {
-	stderr := captureStderr(t)
+func TestPhaseLabel(t *testing.T) {
+	t.Parallel()
 
-	newProgress("walk", -1).increment()
-	newProgress("hash", 10).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)
+	phases := []string{"load", "walk", "hash"}
+	if got := phaseLabel(phases, "walk"); got != "[2/3] walk" {
+		t.Errorf("phaseLabel = %q, want %q", got, "[2/3] walk")
 	}
 }
 
-// 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 {
+// 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 setTotal starts a phase's rate,
+// and so its ETA, from when the total becomes known, not from when the
+// phase started waiting for it.
+func TestSetTotalStartsRate(t *testing.T) {
+	t.Parallel()
+
+	waited := time.Now().Add(-20 * time.Second)
+	p := &progress{
+		label: scanPhase("load"), total: -1, start: waited, rateStart: waited,
+	}
+
+	p.setTotal(100)
+
+	// Ten seconds after the total came, without waiting ten seconds,
+	// 20 records are read.
+	p.start = p.start.Add(-10 * time.Second)
+	p.rateStart = p.rateStart.Add(-10 * time.Second)
+	p.count = 20
+
+	want := "[1/5] load: [20/100] 20%, 2 files/s, elapsed 30s, eta 40s"
+	if got := p.line(); got != want {
+		t.Errorf("line = %q, want %q", got, want)
+	}
+}
+
+// awaitOutput waits until stderr holds want at least times times, and
+// fails the test if it never does.
+func awaitOutput(t *testing.T, stderr func() string, want string,
+	times int,
+) {
 	t.Helper()
 
-	p := &progress{
-		label: "walk", total: -1, start: time.Now(),
-		bar: newBar("walk", -1),
-	}
-	t.Cleanup(p.finish)
+	deadline := time.Now().Add(testDeadline)
+	for strings.Count(stderr(), want) < times {
+		if time.Now().After(deadline) {
+			t.Fatalf("stderr = %q, want %q at least %d times",
+				stderr(), want, times)
+		}
 
-	return p
+		time.Sleep(testRedraw)
+	}
 }
 
-// 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.
+// 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 TestPlainProgressPrintsAtStartAndEnd(t *testing.T) {
+	stderr := captureStderr(t)
+	p := newProgress(progressParams{label: scanPhase("hash"), total: 1000})
+
+	for range 1000 {
+		p.increment()
+	}
+
+	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)
+	}
+}
+
+// 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",
+	}, false, testRedraw)
+
+	awaitOutput(t, stderr,
+		"[1/5] load: counting the records, elapsed 0s, eta unknown\n", 3)
+	p.finish()
+}
+
+// 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
+}
+
+// TestTerminalRedrawsWhileWaiting checks that the terminal display of a
+// phase keeps being drawn while the phase waits for its next item, and
+// shows every item completed before the wait: a spinner's line with
+// the elapsed time as of now, and the library's bar, which works out
+// its elapsed time at each draw.
+//
+//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
+func TestTerminalRedrawsWhileWaiting(t *testing.T) {
+	stderr := captureStderr(t)
+
+	walk := startProgress(progressParams{label: scanPhase("walk"), total: -1},
+		true, testRedraw)
+
+	for range 50 {
+		walk.increment()
+	}
+
+	// An hour into the phase, without waiting an hour.
+	walk.mu.Lock()
+	walk.start = walk.start.Add(-time.Hour)
+	walk.mu.Unlock()
+
+	awaitOutput(t, stderr, "elapsed 1h0m0s", 1)
+	walk.finish()
+
+	if shown := lastFrame(stderr()); !strings.Contains(shown, "50 files,") {
+		t.Errorf("terminal shows %q, want a count of 50", shown)
+	}
+
+	hash := startProgress(progressParams{label: scanPhase("hash"), total: 100},
+		true, testRedraw)
+
+	for range 50 {
+		hash.increment()
+	}
+
+	// Drawn with the 50 items, then twice more with none.
+	awaitOutput(t, stderr, "(50/100,", 3)
+	hash.finish()
+}
+
+// TestTerminalLinesFitWidth checks that every line a terminal display
+// draws, bar or spinner, is narrower than the terminal at the size of a
+// large scan. A line as wide as the terminal or wider would wrap, and
+// every redraw would leave a line behind. stderr is not a terminal
+// here, so the displays take it to be fallbackWidth wide.
+//
+//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
+func TestTerminalLinesFitWidth(t *testing.T) {
+	stderr := captureStderr(t)
+
+	cases := []progressParams{
+		{label: scanPhase("content"), total: 9876543},
+		{label: scanPhase("walk"), total: 9876543, estimate: true},
+	}
+
+	for _, params := range cases {
+		p := startProgress(params, true, testRedraw)
+
+		// 1234567 items two and a half hours into the phase, without
+		// counting them one by one or waiting the hours.
+		p.mu.Lock()
+		p.count = 1234567
+		p.start = p.start.Add(-150 * time.Minute)
+		p.rateStart = p.start
+		p.mu.Unlock()
+
+		awaitOutput(t, stderr, "1234567", 1)
+		p.finish()
+	}
+
+	lines := strings.FieldsFuncSeq(stderr(), func(r rune) bool {
+		return r == '\r' || r == '\n'
+	})
+
+	for line := range lines {
+		if n := utf8.RuneCountInString(line); n >= fallbackWidth {
+			t.Errorf("a line of %d columns on a terminal %d wide: %q",
+				n, fallbackWidth, line)
+		}
+	}
+}
+
+// TestProgressWarningsOnOwnLines drives the terminal displays, spinner
+// and bar, 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)
 
-	// 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++ {
-		p.warnf("warning")
+	cases := []progressParams{
+		{label: scanPhase("walk"), total: -1},
+		{label: scanPhase("hash"), total: 10},
 	}
 
-	// The spinner prints the warnings at its next redraw.
-	time.Sleep(spinnerIdle)
+	issued := 0
+
+	for _, params := range cases {
+		p := startProgress(params, true, testRedraw)
+
+		// No pause between warnings: one written straight to stderr is
+		// garbled only if a redraw lands while it is being written.
+		for start := time.Now(); time.Since(start) < 50*testRedraw; issued++ {
+			p.warnf("warning")
+		}
+
+		p.finish()
+	}
 
 	// A terminal shows each line as the text after its last carriage
 	// return.
@@ -129,57 +352,17 @@ 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 rather than a full bar.
 //
 //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},
+		true, redrawInterval)
 
 	p.increment()
-
-	// Past the redraw limit, so the bar draws the next count.
-	time.Sleep(2 * barThrottle)
 	p.increment()
 	p.finish()
 
@@ -189,19 +372,19 @@ func TestBarStoppedShortKeepsCount(t *testing.T) {
 }
 
 // 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.
+// a phase's last item, as for a failed read of the last file, leaves the
+// phase's full bar on the terminal below the warning.
 //
 //nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
 func TestWarningAfterLastItemKeepsBar(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},
+		true, testRedraw)
 
 	p.increment()
 	p.increment()
+
+	awaitOutput(t, stderr, "(2/2,", 1)
 	p.warnf("warning")
 	p.finish()