trees: show its phases as N of M, with progress, elapsed time and ETA (closes #113)

trees now runs in four phases, open, read, group and write, each under
the progress display scan uses, until the summary line. open covers a
wait on a busy database. read counts the records and reads them in one
read-only transaction, so the two agree during a scan; group counts the
directories, and write the groups. The rows reach stdout through a
writer. When stdout and stderr are the same file, it clears the display
and holds its lock while writing, so no row shares a line with the
display on a shared terminal; otherwise it writes without the lock, so
a slow reader of stdout cannot stop the display. Each rate names what
its phase counts.

Judgement call: opening the database is a phase of its own, so there are four phases, not the three the issue sketches.

Model: opus-5-5

progress_test.go

@@ -1,6 +1,8 @@
 package main
 
 import (
+	"fmt"
+	"io"
 	"math"
 	"os"
 	"path/filepath"
@@ -86,30 +88,44 @@ func TestProgressLine(t *testing.T) {
 		},
 		want: "[1/5] load: counting the records, elapsed 10s, eta unknown",
 	}, {
-		p:    &progress{label: scanPhase("hash"), total: 100, count: 20},
+		p: &progress{
+			label: scanPhase("hash"), unit: scanUnit, 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},
+		p:    &progress{label: scanPhase("hash"), unit: scanUnit, total: 100},
 		want: "[3/5] hash: [0/100] 0%, 0 files/s, elapsed 10s, eta unknown",
 	}, {
-		p:    &progress{label: scanPhase("update"), total: 0},
+		p:    &progress{label: scanPhase("update"), unit: scanUnit, 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,
+			label: scanPhase("walk"), unit: scanUnit, 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,
+			label: scanPhase("walk"), unit: scanUnit, 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},
+		p: &progress{
+			label: scanPhase("walk"), unit: scanUnit, total: -1, count: 20,
+		},
 		want: "[2/5] walk: 20 files, 2 files/s, elapsed 10s, eta unknown",
+	}, {
+		// The rate is in what the phase counts.
+		p: &progress{
+			label: treesPhase("group"), unit: "directories", total: 100,
+			count: 20,
+		},
+		want: "[3/4] group: [20/100] 20%, 2 directories/s, elapsed 10s, " +
+			"eta 40s",
 	}}
 
 	for _, tc := range cases {
@@ -129,7 +145,7 @@ func TestLineFitsRoom(t *testing.T) {
 
 	ago := time.Now().Add(-10 * time.Second)
 	hash := &progress{
-		label: scanPhase("hash"), total: 100, count: 20,
+		label: scanPhase("hash"), unit: scanUnit, total: 100, count: 20,
 		start: ago, rateStart: ago,
 	}
 	content := &progress{
@@ -183,7 +199,8 @@ func TestSetTotalStartsRate(t *testing.T) {
 
 	waited := time.Now().Add(-20 * time.Second)
 	p := &progress{
-		label: scanPhase("load"), total: -1, start: waited, rateStart: waited,
+		label: scanPhase("load"), unit: scanUnit, total: -1, start: waited,
+		rateStart: waited,
 	}
 
 	p.setTotal(100)
@@ -226,7 +243,9 @@ func awaitOutput(t *testing.T, stderr func() string, want string,
 //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})
+	p := newProgress(progressParams{
+		label: scanPhase("hash"), unit: scanUnit, total: 1000,
+	})
 
 	for range 1000 {
 		p.increment()
@@ -289,8 +308,14 @@ func TestTerminalRedrawsWhileWaiting(t *testing.T) {
 		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],"},
+		{
+			progressParams{label: scanPhase("walk"), unit: scanUnit, total: -1},
+			"50 files,",
+		},
+		{
+			progressParams{label: scanPhase("hash"), unit: scanUnit, total: 100},
+			"[50/100],",
+		},
 	}
 
 	for _, tc := range cases {
@@ -341,8 +366,9 @@ func drawLate(stderr func() string, params progressParams, width int,
 }
 
 // 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.
+// 80-column terminal at a large scan's counts and times, and the line
+// of trees' read phase at the same counts: 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) {
@@ -354,18 +380,29 @@ func TestTerminalLinesKeepETA(t *testing.T) {
 	}{{
 		// Past its estimate, the walk cannot tell how long it has left.
 		params: progressParams{
-			label: scanPhase("walk"), total: 1200000, estimate: true,
+			label: scanPhase("walk"), unit: scanUnit, total: 1200000,
+			estimate: true,
 		},
 		want: "[2/5] walk: [1234567/~1200000] 103%, elapsed 2h30m0s, " +
 			"eta unknown",
 	}, {
-		params: progressParams{label: scanPhase("hash"), total: 9876543},
+		params: progressParams{
+			label: scanPhase("hash"), unit: scanUnit, total: 9876543,
+		},
 		want: "[3/5] hash: [1234567/9876543] 12%, elapsed 2h30m0s, " +
 			"eta 17h30m0s",
 	}, {
-		params: progressParams{label: scanPhase("content"), total: 9876543},
+		params: progressParams{
+			label: scanPhase("content"), unit: scanUnit, total: 9876543,
+		},
 		want: "[5/5] content: [1234567/9876543] 12%, elapsed 2h30m0s, " +
 			"eta 17h30m0s",
+	}, {
+		params: progressParams{
+			label: treesPhase("read"), unit: "records", total: 9876543,
+		},
+		want: "[2/4] read: [1234567/9876543] 12%, elapsed 2h30m0s, " +
+			"eta 17h30m0s",
 	}}
 
 	for _, tc := range cases {
@@ -389,7 +426,9 @@ func TestTerminalLinesFitWidth(t *testing.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}
+			params := progressParams{
+				label: scanPhase("content"), unit: scanUnit, total: total,
+			}
 			out := drawLate(stderr, params, width, total/8)
 
 			if width == 120 && !strings.Contains(out, "% |") {
@@ -426,8 +465,16 @@ func TestTerminalNarrowedRedrawsInPlace(t *testing.T) {
 		params progressParams
 		narrow int
 	}{
-		{progressParams{label: scanPhase("walk"), total: -1}, 60},
-		{progressParams{label: scanPhase("hash"), total: 9876543}, 90},
+		{
+			progressParams{label: scanPhase("walk"), unit: scanUnit, total: -1},
+			60,
+		},
+		{
+			progressParams{
+				label: scanPhase("hash"), unit: scanUnit, total: 9876543,
+			},
+			90,
+		},
 	}
 
 	for _, tc := range cases {
@@ -513,6 +560,125 @@ func TestProgressWarningsOnOwnLines(t *testing.T) {
 	}
 }
 
+// TestProgressWriterRowsOnOwnLines drives the terminal displays,
+// spinner and bar, through a run of rows written through the display's
+// writer to the same terminal, as stdout is in a plain "sfdupes trees",
+// each written out at once, for many redraws: the terminal must show
+// every row whole, in order, on a line of its own.
+//
+//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
+func TestProgressWriterRowsOnOwnLines(t *testing.T) {
+	stderr := captureStderr(t)
+
+	cases := []progressParams{
+		{
+			label: treesPhase("open"), total: -1,
+			waitingFor: "opening the database",
+		},
+		{label: treesPhase("write"), unit: "groups", total: 10},
+	}
+
+	var want []string
+
+	for _, params := range cases {
+		p := startProgress(params, terminalWidth, testRedraw)
+		out := p.writer(os.Stderr)
+
+		// No pause between rows: one is garbled only if a redraw lands
+		// on its line.
+		for start := time.Now(); time.Since(start) < 50*testRedraw; {
+			row := fmt.Sprintf("row %d", len(want))
+			want = append(want, row)
+
+			_, err := fmt.Fprintln(out, row)
+			if err == nil {
+				err = out.Flush()
+			}
+
+			if err != nil {
+				t.Fatal(err)
+			}
+		}
+
+		p.finish()
+	}
+
+	// A terminal shows each line as the text after its last carriage
+	// return.
+	var shown []string
+
+	for line := range strings.SplitSeq(stderr(), "\n") {
+		if strings.Contains(line, "row ") {
+			shown = append(shown, line[strings.LastIndex(line, "\r")+1:])
+		}
+	}
+
+	if len(shown) != len(want) {
+		t.Fatalf("terminal shows %d rows, want %d", len(shown), len(want))
+	}
+
+	for i := range want {
+		if shown[i] != want[i] {
+			t.Fatalf("terminal shows %q, want %q", shown[i], want[i])
+		}
+	}
+}
+
+// TestProgressWriterStalledStdoutKeepsLines writes a row larger than a
+// pipe holds through the display's writer to a pipe nobody reads yet,
+// as stdout is when its reader has stopped while stderr goes to a file:
+// while the write waits, the display must go on printing its line.
+//
+//nolint:paralleltest // captureStderr replaces the process-wide os.Stderr
+func TestProgressWriterStalledStdoutKeepsLines(t *testing.T) {
+	stderr := captureStderr(t)
+
+	r, w, err := os.Pipe()
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	t.Cleanup(func() {
+		_ = w.Close()
+		_ = r.Close()
+	})
+
+	p := startProgress(progressParams{label: treesPhase("write"), total: 1},
+		nil, testRedraw)
+	out := p.writer(w)
+	written := make(chan error, 1)
+
+	go func() {
+		_, writeErr := fmt.Fprintln(out, strings.Repeat("x", ioBufSize))
+		written <- writeErr
+	}()
+
+	// Pass or fail, the pipe is then read so that the write ends, and
+	// the display ends before stderr is put back.
+	t.Cleanup(func() {
+		go func() {
+			_, _ = io.Copy(io.Discard, r)
+		}()
+
+		writeErr := <-written
+		if writeErr != nil {
+			t.Error(writeErr)
+		}
+
+		p.finish()
+	})
+
+	// The first byte read shows that the write has started; the rest
+	// of the row waits until the pipe is read.
+	_, err = r.Read(make([]byte, 1))
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	line := "[4/4] write: "
+	awaitOutput(t, stderr, line, strings.Count(stderr(), line)+3)
+}
+
 // 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.