diff --git a/cmd/harnesscli/tui/components/spinner/completion_test.go b/cmd/harnesscli/tui/components/spinner/completion_test.go index a789e970..8a405ee9 100644 --- a/cmd/harnesscli/tui/components/spinner/completion_test.go +++ b/cmd/harnesscli/tui/components/spinner/completion_test.go @@ -303,3 +303,39 @@ func TestTUI025_VisualSnapshot_200x50(t *testing.T) { } t.Logf("Snapshot written: %s", path) } + +// TestCompletionDurationIsFrozenAtStop pins issue #1434: "Worked for " +// states how long the run took, so it must not depend on when you look at it. +// +// ElapsedSeconds() reads the wall clock, and View re-rendered it on every tick +// of the completion window, so a finished run's duration kept climbing — +// 5.0s, 5.3s, 5.6s — inflating the reported figure by up to the window's +// length. For a short run that is a large relative error. +// +// The assertion is that successive renders are identical, not that the value +// equals some number: asserting a number would be timing-dependent and flaky, +// and would not capture the property that actually matters. +func TestCompletionDurationIsFrozenAtStop(t *testing.T) { + m := New(0).Start() + m.startTime = time.Now().Add(-5 * time.Second) + m = m.Stop(100) + + first := m.View(80) + if !strings.Contains(first, "Worked for") { + t.Fatalf("expected a completion line, got %q", first) + } + // Control: the frozen value must still reflect the real elapsed time, so a + // fix that freezes it at zero or drops the duration fails here. + if !strings.Contains(first, "5.") { + t.Fatalf("frozen duration should reflect the ~5s run, got %q", first) + } + + for i := 0; i < 3; i++ { + time.Sleep(250 * time.Millisecond) + m = m.Tick() + if got := m.View(80); got != first { + t.Fatalf("completion duration changed while displayed:\n first: %q\n after tick %d: %q", + first, i+1, got) + } + } +} diff --git a/cmd/harnesscli/tui/components/spinner/model.go b/cmd/harnesscli/tui/components/spinner/model.go index 95618265..ac27f3f4 100644 --- a/cmd/harnesscli/tui/components/spinner/model.go +++ b/cmd/harnesscli/tui/components/spinner/model.go @@ -31,8 +31,17 @@ var pulse = []string{"·", "✢", "✳", "✻", "✽", "✶", "✽", "✻", "✳ // would slow the clock; gating advance slows only the glyph. // // Sum: 18 ticks, about 2.16s per cycle, against 720ms before. +// Must stay the same length as pulse: Tick advances step modulo len(pulse) and +// indexes holds with it, so a divergence would panic at runtime rather than +// fail a build. Checked in init below. var holds = []int{3, 2, 1, 1, 2, 3, 2, 1, 1, 2} +func init() { + if len(holds) != len(pulse) { + panic("spinner: holds and pulse must be the same length") + } +} + // durationThreshold is the elapsed time after which the spinner shows a duration. const durationThreshold = 2 * time.Second @@ -70,6 +79,7 @@ type Model struct { action string // what the run is currently doing; empty falls back to fallbackLabel startTime time.Time // when spinner started (for duration) tokens int // token count stored on Stop() + stoppedAfter float64 // elapsed seconds frozen at Stop; see issue #1434 active bool // true while spinner is running done bool // true after Stop() tickCount int // total ticks received @@ -135,6 +145,11 @@ func (m Model) Tick() Model { // remains visible for N ticks before going silent. // Returns a new Model; the receiver is unchanged. func (m Model) Stop(tokens int) Model { + // Freeze the duration here. The completion line states how long the run + // took, and View re-renders it on every tick of the completion window, so + // reading the wall clock there made a finished run's duration keep climbing + // — inflating the reported figure by up to the window's length. Issue #1434. + m.stoppedAfter = m.ElapsedSeconds() m.active = false m.done = true m.tokens = tokens @@ -209,7 +224,7 @@ func (m Model) View(width int) string { // Completion mode: show the finalized line for N frames, then go silent. if m.done { if m.ShowsCompletion() { - return m.CompletionLine(m.ElapsedSeconds()) + return m.CompletionLine(m.stoppedAfter) } // Silent after completion window expires. return "" @@ -246,7 +261,7 @@ func (m Model) View(width int) string { // rather than "Computing..."), so the trade-off is now worth making // explicit. Issue #1415. if lipgloss.Width(base) > width { - base = shortenLabel(currentFrame, label, base, width) + base = shortenLabel(currentFrame, label, width) } style := m.stylesOrDefault().Dim @@ -264,7 +279,7 @@ func (m Model) View(width int) string { // It first drops the duration, then truncates the label itself, and gives up // only when even " " will not fit — at which point the caller's // MaxWidth clamp takes over. -func shortenLabel(glyph, label, full string, width int) string { +func shortenLabel(glyph, label string, width int) string { withoutDuration := glyph + " " + label + " " + CancelHint if lipgloss.Width(withoutDuration) <= width { return withoutDuration diff --git a/docs/logs/engineering-log.md b/docs/logs/engineering-log.md index 44cf43d9..31ff5e4e 100644 --- a/docs/logs/engineering-log.md +++ b/docs/logs/engineering-log.md @@ -1,5 +1,48 @@ # Engineering Log +## 2026-09-08 — Issue #1434 completion line kept counting after the run finished + +- Symptom: `Worked for ` climbed while it was on screen, because `View` + re-rendered `ElapsedSeconds()` — a live wall-clock read — on every tick of the + completion window: + ``` + tick 0: "· Worked for 5.0s" tick 2: "· Worked for 5.6s" + tick 1: "· Worked for 5.3s" tick 3: "· Worked for 5.9s" + ``` + The window is 10 ticks at 120ms, so the figure a user reads was inflated by up + to ~1.2s. For a short run that is a large relative error: a 0.4s run reported + as 1.6s. +- Fix: `Stop` freezes the elapsed duration into `stoppedAfter`, and the + completion branch renders that. `ElapsedSeconds()` keeps its meaning for a + live spinner, so nothing else changes. +- Test: `TestCompletionDurationIsFrozenAtStop` asserts successive renders are + *identical* rather than asserting a number — a number would be timing- + dependent and flaky, and would not capture the property that matters. It also + keeps a control that the frozen value still reflects the real ~5s, so freezing + at zero would fail. +- Two cleanups from the same review: `shortenLabel` carried an unused `full` + parameter, removed; and `Tick` indexes `holds[m.step]` while advancing modulo + `len(pulse)`, so an `init` now enforces that the two slices stay the same + length rather than leaving a future edit to panic at runtime. +- **Provenance, and the actual lesson.** Both real findings came from *cheap* + models during a cost evaluation, on a file `gpt-6-astra` ($10/M) had already + reviewed and passed: + - `openai-gpt-oss-120b` ($0.07/M) found the growing duration. Astra raised a + related point and got it wrong — it framed elapsed time as a snapshot-test + nondeterminism problem, which is a false positive, since those tests set + `startTime` explicitly. It looked at the same code and drew the wrong + conclusion. + - `gpt-5-nano` ($0.05/M) found the unused parameter. Astra did not. + - `deepseek-v4-flash-0731` timed out at 180s with zero bytes — cheap but not + reliable here. + - `hy3-free` is listed at $0.00/M but returns `no_sellers_for_model`. Listed, + not served. + The models are not ranked, they are differently blind. Astra caught a subtle + correctness bug about mixed units (#1432) that the cheap models missed; the + cheap models caught a user-visible bug and a dead parameter that Astra missed. + Running more than one cheap reviewer is better value than running one + expensive one, and every finding still needs confirming before it is believed. + ## 2026-09-08 — Issue #1435 go-code silently dropped prompt arguments - Symptom: `go-code explain this repo` — the natural unquoted form — ran against