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

Every scan display names its phase and its place among the five, as
"[2/5] walk", with its progress, elapsed time and ETA. load counts the
records first; the walk estimates its total from the records under the
operands; the content phase adds up the sizes of the matching groups
and says it is searching until the first record returns. Each display
redraws every 100 ms on a terminal and every 5 seconds in plain mode.

On a terminal no line reaches the last column: a line too wide drops
its rate, then its bar. After the terminal is made narrower than the
widest line drawn, the display makes a new library object, whose erase
fits.

Judgement call: load and the content checks draw the bar too, once their totals are known.
Judgement call: the bar is 10 columns wide, not the width the line leaves.

Model: opus-5-5

progress_test.go

@@ -1,16 +1,22 @@
 package main
 
 import (
+	"math"
 	"os"
 	"path/filepath"
 	"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 +60,437 @@ 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(math.MaxInt, true); got != tc.want {
+			t.Errorf("line = %q, want %q", got, tc.want)
+		}
+	}
+}
+
+// TestLineFitsRoom checks how a line is fitted to the room it has, ten
+// seconds into the phase: it leaves out the rate, or what the phase
+// waits for, and is cut only when what is left is still too wide.
+func TestLineFitsRoom(t *testing.T) {
+	t.Parallel()
+
+	ago := time.Now().Add(-10 * time.Second)
+	hash := &progress{
+		label: scanPhase("hash"), total: 100, count: 20,
+		start: ago, rateStart: ago,
+	}
+	content := &progress{
+		label: scanPhase("content"), total: -1,
+		waitingFor: "searching the database", start: ago, rateStart: ago,
+	}
+
+	cases := []struct {
+		p       *progress
+		room    int
+		percent bool
+		want    string
+		fits    bool
+	}{{
+		p: hash, room: 57, percent: true,
+		want: "[3/5] hash: [20/100] 20%, 2 files/s, elapsed 10s, eta 40s",
+		fits: true,
+	}, {
+		p: hash, room: 56, percent: true,
+		want: "[3/5] hash: [20/100] 20%, elapsed 10s, eta 40s",
+		fits: true,
+	}, {
+		p: hash, room: 45, percent: true,
+		want: "[3/5] hash: [20/100] 20%, elapsed 10s, eta 40",
+		fits: false,
+	}, {
+		// Before the library's bar, which shows the percent.
+		p: hash, room: 57, percent: false,
+		want: "[3/5] hash: [20/100], 2 files/s, elapsed 10s, eta 40s",
+		fits: true,
+	}, {
+		p: content, room: 40, percent: true,
+		want: "[5/5] content: elapsed 10s, eta unknown",
+		fits: true,
+	}}
+
+	for _, tc := range cases {
+		got, fits := tc.p.line(tc.room, tc.percent)
+		if got != tc.want || fits != tc.fits {
+			t.Errorf("line(%d, %t) = %q, %t, want %q, %t",
+				tc.room, tc.percent, got, fits, tc.want, tc.fits)
+		}
+	}
+}
+
+// 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(math.MaxInt, true); 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",
+	}, nil, 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, spinner or bar, keeps being drawn while the phase waits for its
+// next item, with the elapsed time as of now, and shows every item
+// completed before the wait. 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 TestTerminalRedrawsWhileWaiting(t *testing.T) {
+	stderr := captureStderr(t)
+
+	cases := []struct {
+		params progressParams
+		want   string // how the line shows a count of 50
+	}{
+		{progressParams{label: scanPhase("walk"), total: -1}, "50 files,"},
+		{progressParams{label: scanPhase("hash"), total: 100}, "[50/100],"},
+	}
+
+	for _, tc := range cases {
+		before := len(stderr())
+		since := func() string { return stderr()[before:] }
+		p := startProgress(tc.params, terminalWidth, 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()
+
+		awaitOutput(t, since, "elapsed 1h0m0s", 1)
+		p.finish()
+
+		if shown := lastFrame(since()); !strings.Contains(shown, tc.want) {
+			t.Errorf("terminal shows %q, want %q", shown, tc.want)
+		}
+	}
+}
+
+// drawLate draws the display params describes on a terminal width
+// columns wide as it starts and once more as it ends, with count items
+// done two and a half hours into the phase, and returns what it wrote
+// to stderr.
+func drawLate(stderr func() string, params progressParams, width int,
+	count int64,
+) string {
+	before := len(stderr())
+
+	// No timed draws come between the two.
+	p := startProgress(params, func() int { return width }, time.Hour)
+
+	// Without counting the items one by one or waiting the hours.
+	p.mu.Lock()
+	p.count = count
+	p.start = p.start.Add(-150 * time.Minute)
+	p.rateStart = p.start
+	p.mu.Unlock()
+
+	p.finish()
+
+	return stderr()[before:]
+}
+
+// TestTerminalLinesKeepETA checks the line each display shows on an
+// 80-column terminal at a large scan's counts and times: the rate is
+// left out, so that the elapsed time and the ETA stay whole.
+//
+//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
+func TestTerminalLinesKeepETA(t *testing.T) {
+	stderr := captureStderr(t)
+
+	cases := []struct {
+		params progressParams
+		want   string
+	}{{
+		// Past its estimate, the walk cannot tell how long it has left.
+		params: progressParams{
+			label: scanPhase("walk"), total: 1200000, estimate: true,
+		},
+		want: "[2/5] walk: [1234567/~1200000] 103%, elapsed 2h30m0s, " +
+			"eta unknown",
+	}, {
+		params: progressParams{label: scanPhase("hash"), total: 9876543},
+		want: "[3/5] hash: [1234567/9876543] 12%, elapsed 2h30m0s, " +
+			"eta 17h30m0s",
+	}, {
+		params: progressParams{label: scanPhase("content"), total: 9876543},
+		want: "[5/5] content: [1234567/9876543] 12%, elapsed 2h30m0s, " +
+			"eta 17h30m0s",
+	}}
+
+	for _, tc := range cases {
+		out := drawLate(stderr, tc.params, 80, 1234567)
+		if shown := lastFrame(out); !strings.Contains(shown, tc.want) {
+			t.Errorf("terminal shows %q, want %q", shown, tc.want)
+		}
+	}
+}
+
+// TestTerminalLinesFitWidth draws a large scan's bar display and a small
+// scan's, two and a half hours into the phase, on terminals from 120
+// columns down to 40, and checks that every line stays clear of the
+// terminal's last column. A line that reaches it wraps, and every
+// redraw then leaves a line behind. The bar is drawn where it has room,
+// as at 120 columns, and left out where it has none.
+//
+//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
+func TestTerminalLinesFitWidth(t *testing.T) {
+	stderr := captureStderr(t)
+
+	for _, width := range []int{120, 100, 80, 72, 60, 50, 40} {
+		for _, total := range []int64{9876543, 20000} {
+			params := progressParams{label: scanPhase("content"), total: total}
+			out := drawLate(stderr, params, width, total/8)
+
+			if width == 120 && !strings.Contains(out, "% |") {
+				t.Errorf("no bar on a terminal %d wide: %q", width, out)
+			}
+
+			lines := strings.FieldsFuncSeq(out, func(r rune) bool {
+				return r == '\r' || r == '\n'
+			})
+
+			for line := range lines {
+				if n := utf8.RuneCountInString(line); n >= width {
+					t.Errorf("a line of %d columns on a terminal %d wide: %q",
+						n, width, line)
+				}
+			}
+		}
+	}
+}
+
+// TestTerminalNarrowedRedrawsInPlace draws a large scan's display, two
+// and a half hours into the phase, on a terminal 120 columns wide, then
+// makes the terminal narrower than that line and draws it again a few
+// times. Nothing written after that, the erase before each redraw
+// included, may reach the narrower terminal's last column: it would
+// wrap, and every redraw would leave a line behind. At these widths the
+// spinner stays a spinner and the bar stays a bar.
+//
+//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
+func TestTerminalNarrowedRedrawsInPlace(t *testing.T) {
+	stderr := captureStderr(t)
+
+	cases := []struct {
+		params progressParams
+		narrow int
+	}{
+		{progressParams{label: scanPhase("walk"), total: -1}, 60},
+		{progressParams{label: scanPhase("hash"), total: 9876543}, 90},
+	}
+
+	for _, tc := range cases {
+		width := 120
+
+		// No timed draws: the test draws.
+		p := startProgress(tc.params, func() int { return width }, time.Hour)
+
+		p.mu.Lock()
+		p.count = 1234567
+		p.start = p.start.Add(-150 * time.Minute)
+		p.rateStart = p.start
+		p.mu.Unlock()
+
+		p.draw()
+
+		width = tc.narrow
+		before := len(stderr())
+
+		p.draw()
+		p.draw()
+		p.finish()
+
+		lines := strings.FieldsFuncSeq(stderr()[before:], func(r rune) bool {
+			return r == '\r' || r == '\n'
+		})
+
+		for line := range lines {
+			if n := utf8.RuneCountInString(line); n >= width {
+				t.Errorf("%d columns written on a terminal made %d wide: %q",
+					n, width, 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, terminalWidth, 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,83 +513,43 @@ 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},
+		terminalWidth, 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.
+// 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},
+		terminalWidth, testRedraw)
 
 	p.increment()
 	p.increment()
+
+	awaitOutput(t, stderr, "[2/2],", 1)
 	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)
 	}
 }