Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
36 changes: 36 additions & 0 deletions cmd/harnesscli/tui/components/spinner/completion_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -303,3 +303,39 @@ func TestTUI025_VisualSnapshot_200x50(t *testing.T) {
}
t.Logf("Snapshot written: %s", path)
}

// TestCompletionDurationIsFrozenAtStop pins issue #1434: "Worked for <d>"
// 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)
}
}
}
21 changes: 18 additions & 3 deletions cmd/harnesscli/tui/components/spinner/model.go
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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 ""
Expand Down Expand Up @@ -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
Expand All @@ -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 "<glyph> <hint>" 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
Expand Down
43 changes: 43 additions & 0 deletions docs/logs/engineering-log.md
Original file line number Diff line number Diff line change
@@ -1,5 +1,48 @@
# Engineering Log

## 2026-09-08 — Issue #1434 completion line kept counting after the run finished

- Symptom: `Worked for <d>` 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
Expand Down
Loading