diff --git a/cmd/llmtest/progress.go b/cmd/llmtest/progress.go index 2a980b5..347a26f 100644 --- a/cmd/llmtest/progress.go +++ b/cmd/llmtest/progress.go @@ -3,22 +3,48 @@ package main import ( "fmt" "io" + "os" "sync" "github.com/lukaszraczylo/llm-testbench/internal/runner" ) -// stderrProgressReporter implements runner.ProgressReporter, writing one -// line per event to w (os.Stderr in production). Run's stdout stays -// pipeable (table/markdown/json only): all progress goes here instead. +// pipedProgressEvery is how often a non-terminal stderr gets a progress +// line. A piped log stays readable without one line per request. +const pipedProgressEvery = 25 + +// stderrProgressReporter implements runner.ProgressReporter, writing a +// self-updating "test N of M" counter to w (os.Stderr in production). +// Run's stdout stays pipeable (table/markdown/json only): all progress +// goes here instead. +// +// When w is a terminal the counter rewrites itself in place with a +// carriage return. When w is piped (a log file), rewriting would produce +// one unreadable blob, so it prints a plain line every pipedProgressEvery +// completions plus the final one. type stderrProgressReporter struct { - w io.Writer - mu sync.Mutex + w io.Writer + mu sync.Mutex + isTTY bool } // newStderrProgressReporter builds a stderrProgressReporter writing to w. func newStderrProgressReporter(w io.Writer) *stderrProgressReporter { - return &stderrProgressReporter{w: w} + return &stderrProgressReporter{w: w, isTTY: isTerminal(w)} +} + +// isTerminal reports whether w is a character device (an interactive +// terminal), using only the standard library. +func isTerminal(w io.Writer) bool { + f, ok := w.(*os.File) + if !ok { + return false + } + info, err := f.Stat() + if err != nil { + return false + } + return info.Mode()&os.ModeCharDevice != 0 } // ReportStart implements runner.ProgressReporter. @@ -34,30 +60,23 @@ func (r *stderrProgressReporter) ReportStart(totalTests, totalModels, concurrenc // ReportDone implements runner.ProgressReporter. Safe for concurrent calls // from up to Config.Concurrency goroutines at once: the mutex serializes -// each printed line so concurrent completions cannot interleave mid-line. -func (r *stderrProgressReporter) ReportDone(done, total int, result runner.Result) { - status := resultStatus(result) - truncated := "" - if result.Truncated() { - truncated = " TRUNCATED" - } - +// writes so concurrent completions cannot interleave mid-line. +func (r *stderrProgressReporter) ReportDone(done, total int, _ runner.Result) { r.mu.Lock() defer r.mu.Unlock() - // See ReportStart: a write failure here is not actionable. - _, _ = fmt.Fprintf(r.w, "[%d/%d] model=%s test=%s score=%s tokens=%d (%s)%s\n", - done, total, result.Model, result.TestID, status, result.TotalTokens(), result.Latency, truncated) -} -// resultStatus renders a Result's score for one progress line: the numeric -// score, or ERR/skip. -func resultStatus(result runner.Result) string { - switch { - case result.Err != nil: - return "ERR" - case result.Score.Skipped: - return "skip" - default: - return fmt.Sprintf("%.2f", result.Score.Value) + if r.isTTY { + // \r returns to the line start, \x1b[K clears any longer previous + // text; the final completion ends the line so later output starts + // clean. + _, _ = fmt.Fprintf(r.w, "\rtest %d of %d\x1b[K", done, total) + if done == total { + _, _ = fmt.Fprintln(r.w) + } + return + } + + if done%pipedProgressEvery == 0 || done == total { + _, _ = fmt.Fprintf(r.w, "test %d of %d\n", done, total) } } diff --git a/cmd/llmtest/progress_test.go b/cmd/llmtest/progress_test.go index 5c5279a..e1f7afe 100644 --- a/cmd/llmtest/progress_test.go +++ b/cmd/llmtest/progress_test.go @@ -2,12 +2,10 @@ package main import ( "bytes" - "errors" "regexp" "strings" "sync" "testing" - "time" "github.com/lukaszraczylo/llm-testbench/internal/eval" "github.com/lukaszraczylo/llm-testbench/internal/runner" @@ -26,55 +24,56 @@ func TestStderrProgressReporter_ReportStart(t *testing.T) { } } -func TestStderrProgressReporter_ReportDone(t *testing.T) { +// A bytes.Buffer is not a character device, so newStderrProgressReporter +// selects piped mode: a plain line every pipedProgressEvery completions +// plus the final one, nothing else. +func TestStderrProgressReporter_ReportDone_Piped(t *testing.T) { tests := []struct { - name string - wantSub []string - result runner.Result + name string + want string + done int + total int }{ - { - name: "scored result", - result: runner.Result{Model: "m1", TestID: "t1", Score: eval.Score{Value: 0.85}, Latency: 2 * time.Second}, - wantSub: []string{"model=m1", "test=t1", "score=0.85", "(2s)"}, - }, - { - name: "error result", - result: runner.Result{Model: "m1", TestID: "t1", Err: errors.New("boom")}, - wantSub: []string{"score=ERR"}, - }, - { - name: "skipped result", - result: runner.Result{Model: "m1", TestID: "t1", Score: eval.Score{Skipped: true}}, - wantSub: []string{"score=skip"}, - }, - { - name: "truncated result carries the TRUNCATED marker", - result: runner.Result{Model: "m1", TestID: "t1", Score: eval.Score{Value: 0}, FinishReason: "length"}, - wantSub: []string{"score=0.00", "TRUNCATED"}, - }, - { - name: "non-truncated result has no marker", - result: runner.Result{Model: "m1", TestID: "t1", Score: eval.Score{Value: 1}, FinishReason: "stop"}, - wantSub: []string{"score=1.00"}, - }, + {name: "intermediate completion stays silent", done: 3, total: 10, want: ""}, + {name: "final completion always prints", done: 10, total: 10, want: "test 10 of 10\n"}, + {name: "every pipedProgressEvery-th completion prints", done: pipedProgressEvery, total: 100, want: "test 25 of 100\n"}, + {name: "multiple of pipedProgressEvery prints", done: 2 * pipedProgressEvery, total: 100, want: "test 50 of 100\n"}, + {name: "off-interval completion stays silent", done: 2*pipedProgressEvery + 1, total: 100, want: ""}, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { var buf bytes.Buffer r := newStderrProgressReporter(&buf) - r.ReportDone(3, 10, tt.result) + r.ReportDone(tt.done, tt.total, runner.Result{Model: "m", TestID: "t", Score: eval.Score{Value: 1}}) - got := buf.String() - if !strings.HasPrefix(got, "[3/10] ") { - t.Errorf("ReportDone() output = %q, want prefix [3/10] ", got) + if got := buf.String(); got != tt.want { + t.Errorf("ReportDone(%d, %d) output = %q, want %q", tt.done, tt.total, got, tt.want) } - for _, want := range tt.wantSub { - if !strings.Contains(got, want) { - t.Errorf("ReportDone() output = %q, want substring %q", got, want) - } - } - if tt.name == "non-truncated result has no marker" && strings.Contains(got, "TRUNCATED") { - t.Errorf("ReportDone() output = %q, must not contain TRUNCATED", got) + }) + } +} + +// TTY mode rewrites one counter line in place; the test forces isTTY since +// a bytes.Buffer can never be a terminal. +func TestStderrProgressReporter_ReportDone_TTY(t *testing.T) { + tests := []struct { + name string + want string + done int + total int + }{ + {name: "intermediate rewrites in place without a newline", done: 3, total: 10, want: "\rtest 3 of 10\x1b[K"}, + {name: "final completion ends the line", done: 10, total: 10, want: "\rtest 10 of 10\x1b[K\n"}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + var buf bytes.Buffer + r := newStderrProgressReporter(&buf) + r.isTTY = true + r.ReportDone(tt.done, tt.total, runner.Result{Model: "m", TestID: "t", Score: eval.Score{Value: 1}}) + + if got := buf.String(); got != tt.want { + t.Errorf("ReportDone(%d, %d) output = %q, want %q", tt.done, tt.total, got, tt.want) } }) } @@ -82,13 +81,13 @@ func TestStderrProgressReporter_ReportDone(t *testing.T) { // TestStderrProgressReporter_ReportDone_ConcurrencySafe writes many // concurrent ReportDone calls (as Runner.Run's goroutines would) and -// verifies every line is well-formed and none interleaved mid-line - the -// reporter's own mutex must serialize writes, not just the counter. +// verifies no write interleaved mid-line - the reporter's own mutex must +// serialize writes, not just the counter. func TestStderrProgressReporter_ReportDone_ConcurrencySafe(t *testing.T) { var buf bytes.Buffer r := newStderrProgressReporter(&buf) - const n = 50 + const n = 2 * pipedProgressEvery var wg sync.WaitGroup for i := 1; i <= n; i++ { wg.Add(1) @@ -99,12 +98,13 @@ func TestStderrProgressReporter_ReportDone_ConcurrencySafe(t *testing.T) { } wg.Wait() + // In piped mode exactly the 25th and 50th completions print. lines := strings.Split(strings.TrimRight(buf.String(), "\n"), "\n") - if len(lines) != n { - t.Fatalf("got %d lines, want %d (a corrupted/interleaved write would produce a different count)", len(lines), n) + if len(lines) != 2 { + t.Fatalf("got %d lines (%q), want 2 (a corrupted/interleaved write would change the count)", len(lines), buf.String()) } - linePattern := regexp.MustCompile(`^\[\d+/\d+\] model=m test=t score=1\.00 tokens=0 \(0s\)$`) + linePattern := regexp.MustCompile(`^test \d+ of \d+$`) for _, line := range lines { if !linePattern.MatchString(line) { t.Errorf("malformed or interleaved line: %q", line)