Skip to content

Commit 8014af7

Browse files
author
gluck
committed
fix(cli): show a turn as running when it starts, not when it speaks
In transcript mode the status row said idle from submit until the model's first token. Measured against a live aria, with a watcher that only subscribes: the daemon broadcast the committed question 34.5ms after submit and the first content delta at 2263.6ms. Two point two seconds of honest signal, thrown away, and much worse on a cold turn. Two separate causes. THE GUARD WAS ONE LINE TOO WIDE. armThinking does two things, and they have different owners. t.status.beginTurn() sets state the PAGER paints, in its own footer, through footerStanza. t.in.OpenThinking() opens a live region belonging to the inline renderer alone, which must not paint while the pager holds the screen. f28e6e1 guarded both on t.tr.active and its comment says why: "No-op in the pager (it renders the footer itself)". That is true of the second half and false of the first, because what the pager renders the footer FROM was inside the guard. So the guard is kept and split rather than deleted: status is set in both views, the incipit region stays inline-only. THAT ALONE FIXES ONLY THE SENDER. A prompt typed into the pager goes through commandSend, which never called armThinking; a listener never submits at all; a queued prompt begins its turn long after its own call returned. All three learn from the wire, so the wire is what arms them. Client gains OnTurnOpen, beside OnClosed, OnLive and OnMetrics, fired when a turn takes the open slot. It belongs in the client and not in the caller because "which turn owns the open slot" is already decided there, once, in claimsOpen, and that file warns in its own comments what a second opinion computed upstream costs: three branches disagreeing about the buffer is what let a page of history destroy a live turn. Recomputing the same predicate in the CLI would be that mistake again. Catch-up history arrives through Merge, which fires no callbacks, and claimsOpen refuses a sealed part, so neither reading old turns nor a mid-turn reconcile lights the spinner. The callback is edge triggered on the turn id, since the inquiry rides along on later frames of the same turn. Four tests in internal/cli/thinking_armed_test.go, verified to fail without the fix: three fail with the exact symptom, and the fourth is the sealed-frame guard, which must pass either way. Also documents the trap that ate the first draft of that file. thinking_arm_test.go compiles only on GOARCH=arm, so it was not a test that failed, it was a file that did not exist, and build, vet and test were all clean while it did not run.
1 parent d718039 commit 8014af7

4 files changed

Lines changed: 194 additions & 4 deletions

File tree

‎internal/cli/livelog_bridge.go‎

Lines changed: 26 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -179,6 +179,18 @@ func (t *livelogTurn) wireClient() {
179179
}
180180
}
181181
}
182+
t.client.OnTurnOpen = func(int) {
183+
// THE WIRE, NOT THE SUBMIT. A session that sent the prompt already
184+
// armed itself in armThinking; this is for every other way a turn
185+
// starts under a live view: `:send` from inside the pager, a listener
186+
// watching an aria someone else is driving, a queued prompt that only
187+
// begins when the turn ahead of it ends. The daemon broadcasts the
188+
// committed question before it calls a provider, so this is early.
189+
t.status.beginTurn()
190+
if t.tr.active {
191+
t.tr.render()
192+
}
193+
}
182194
t.client.OnLive = func(m aria.Message) {
183195
newOpen := m.Turn != t.open.Turn
184196
t.open = m
@@ -305,15 +317,25 @@ func (t *livelogTurn) openOverflows(nodes []livedoc.Node) bool {
305317
return false
306318
}
307319

308-
// armThinking pins the footer the instant a submit is accepted: before the
309-
// prompt has round-tripped, before the model's first token. The footer is a
310-
// permanent fixture of the view, so it must not wait on the stream.
320+
// armThinking shows the turn as running the instant a submit is accepted:
321+
// before the prompt has round-tripped, before the model's first token.
322+
//
323+
// The two halves have different owners, which is why the pager guard sits
324+
// where it does. status is shared: the pager paints it in its own footer
325+
// (transcript.go, footerStanza), so it must be set in BOTH views. The incipit
326+
// live region is the inline renderer's alone, and opening one while the pager
327+
// owns the screen would paint underneath it.
328+
//
329+
// This used to guard both halves on t.tr.active, which meant the pager was
330+
// never told a turn had started. It then had nothing to draw until the first
331+
// content frame, roughly two seconds of blank on a warm turn and much more on
332+
// a cold one.
311333
func (t *livelogTurn) armThinking() {
334+
t.status.beginTurn()
312335
if t.tr.active || t.thinkingOpen {
313336
return
314337
}
315338
t.thinkingOpen = true
316-
t.status.beginTurn()
317339
t.in.OpenThinking(livedoc.RoleOutput)
318340
}
319341

Lines changed: 111 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,111 @@
1+
package cli
2+
3+
import (
4+
"bytes"
5+
"strings"
6+
"testing"
7+
"time"
8+
9+
"github.com/jack-work/figaro/api/aria"
10+
"github.com/jack-work/figaro/api/livedoc"
11+
)
12+
13+
// THE SPINNER MUST NOT WAIT FOR THE MODEL.
14+
//
15+
// The daemon commits the user's question and broadcasts it BEFORE it calls a
16+
// provider (internal/figaro/turn.go, appendUserPrompt then ariaSrv.OpenInquiry),
17+
// so a client holds "this turn is running" while the model is still thinking.
18+
// Measured on a live aria: the inquiry frame landed 35ms after submit and the
19+
// first content delta 2264ms after it. Everything the pager drew in that gap
20+
// said idle.
21+
//
22+
// Two separate defects produced that gap, so there are two tests here.
23+
24+
// One: the pager was never told. armThinking guarded BOTH of its halves on
25+
// t.tr.active, and one of those halves is the shared sessionStatus that the
26+
// pager paints in its own footer (transcript.go, footerStanza). The incipit
27+
// live region genuinely is inline-only and stays guarded.
28+
func TestArmThinkingMarksTheTurnRunningInThePager(t *testing.T) {
29+
var out bytes.Buffer
30+
status := newSessionStatus("aria1234", time.Now())
31+
lt := newLivelogTurn(&out, 80, 20, &renderSettings{}, "aria1234", time.Now(), status, nil, nil)
32+
lt.enterTranscript()
33+
34+
lt.armThinking()
35+
36+
if !status.turnRunning() {
37+
t.Fatal("armThinking left the pager showing idle; the footer has nothing to draw until first content")
38+
}
39+
// The incipit region is the inline renderer's alone. Opening one under the
40+
// pager paints beneath a screen we do not own.
41+
if lt.thinkingOpen {
42+
t.Fatal("armThinking opened an incipit live region while the pager held the screen")
43+
}
44+
}
45+
46+
// Two: nothing armed at all on the paths where the submit is not ours. A
47+
// `:send` typed into the pager goes through commandSend, a listener never
48+
// submits anything, and a queued prompt starts its turn long after its own
49+
// call returned. All three learn from the wire, so the wire is what arms them.
50+
func TestInquiryFrameMarksTheTurnRunning(t *testing.T) {
51+
var out bytes.Buffer
52+
status := newSessionStatus("aria1234", time.Now())
53+
lt := newLivelogTurn(&out, 80, 20, &renderSettings{}, "aria1234", time.Now(), status, nil, nil)
54+
lt.enterTranscript()
55+
56+
if status.turnRunning() {
57+
t.Fatal("a fresh session claims a turn is running")
58+
}
59+
// The shape the daemon actually sends first: the question, no nodes, no
60+
// live region. Nothing here says what the model will say.
61+
lt.apply(inquiryPage(7, "WHAT IS THE GAP?"))
62+
63+
if !status.turnRunning() {
64+
t.Fatal("the inquiry frame did not mark the turn running; the spinner waits out the model's latency")
65+
}
66+
}
67+
68+
// The companion that proves the two above can fail: content-bearing frames
69+
// arm the status by a different route (OnLive), so a test that fed one would
70+
// pass whether or not the inquiry path works at all.
71+
func TestInquiryArmingIsNotJustOnLive(t *testing.T) {
72+
var out bytes.Buffer
73+
status := newSessionStatus("aria1234", time.Now())
74+
lt := newLivelogTurn(&out, 80, 20, &renderSettings{}, "aria1234", time.Now(), status, nil, nil)
75+
lt.enterTranscript()
76+
77+
lt.apply(inquiryPage(7, "WHAT IS THE GAP?"))
78+
armedByInquiry := status.turnRunning()
79+
80+
status.setTurn(turnStatusIdle)
81+
lt.apply(aria.Page{Parts: []aria.TurnPart{{Turn: aria.Turn{
82+
ID: 7, Live: &aria.Live{From: 0, Nodes: []aria.NodeDelta{{
83+
ID: 0, Set: map[string]any{"type": "prose", "markdown": "the answer"},
84+
}}},
85+
}}}})
86+
armedByContent := status.turnRunning()
87+
88+
if !armedByInquiry || !armedByContent {
89+
t.Fatalf("inquiry=%v content=%v, want both true", armedByInquiry, armedByContent)
90+
}
91+
}
92+
93+
// A turn that is merely being READ is not a turn that is running. History
94+
// reaches the client through Merge, which fires no callbacks, but a sealed
95+
// turn can also arrive as a pushed frame (reconcileAriaServer fans one out
96+
// per turn on a mid-turn error path). Neither may light the spinner.
97+
func TestSealedFrameDoesNotMarkTheTurnRunning(t *testing.T) {
98+
var out bytes.Buffer
99+
status := newSessionStatus("aria1234", time.Now())
100+
lt := newLivelogTurn(&out, 80, 20, &renderSettings{}, "aria1234", time.Now(), status, nil, nil)
101+
lt.enterTranscript()
102+
103+
lt.apply(aria.Page{Parts: []aria.TurnPart{{Turn: aria.Turn{
104+
ID: 4, Inquiry: "AN OLD QUESTION", Sealed: true,
105+
Nodes: []livedoc.Node{{Type: livedoc.NodeProse, Markdown: "an old answer"}},
106+
}}}})
107+
108+
if status.turnRunning() {
109+
t.Fatalf("a sealed turn lit the spinner:\n%s", strings.TrimSpace(out.String()))
110+
}
111+
}

‎internal/livelog/aria/client.go‎

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -50,6 +50,23 @@ type Client struct {
5050
OnLive func(Message)
5151
OnDesync func(sinceLT int)
5252
OnMetrics func(Metrics)
53+
// OnTurnOpen fires once per turn, when a turn takes the open slot. It is
54+
// the counterpart of the server's turn.done: the daemon commits the user's
55+
// question and broadcasts it before it calls a provider, so this lands
56+
// while the model is still thinking rather than with its first token. A
57+
// status surface that waits for OnLive instead waits out the whole of the
58+
// model's latency, which on a warm turn is two seconds and on a cold one
59+
// is much worse.
60+
//
61+
// It belongs here and not in a caller because "which turn owns the open
62+
// slot" is decided here, once (see claimsOpen). A second opinion computed
63+
// upstream is the exact mistake this file already warns about.
64+
OnTurnOpen func(turn int)
65+
66+
// openedTurn is the turn id OnTurnOpen last reported. The inquiry rides
67+
// along on later frames of the same turn, so the callback is edge
68+
// triggered on the id rather than fired per frame.
69+
openedTurn int
5370
}
5471

5572
// heldInquiry is a turn's question and its per-sender split, parked together
@@ -266,6 +283,8 @@ func (c *Client) Apply(p Page) {
266283
c.mu.Lock()
267284
var finalized []Message
268285
desync := -1
286+
// opened is the turn that took the open slot on this page, 0 for none.
287+
opened := 0
269288
metrics := p.Metrics
270289

271290
for _, part := range p.Parts {
@@ -293,6 +312,13 @@ func (c *Client) Apply(p Page) {
293312
// slot for it would destroy the live turn on its way past.
294313
if staged && !part.ClippedHead {
295314
c.store.ClaimOpen(id)
315+
// This is the earliest a client can know a turn is running:
316+
// the question is committed and the provider has not been
317+
// called yet. Reported outside the lock with everything else.
318+
if id > c.openedTurn {
319+
c.openedTurn = id
320+
opened = id
321+
}
296322
}
297323
}
298324

@@ -430,6 +456,11 @@ func (c *Client) Apply(p Page) {
430456
if metrics != nil && c.OnMetrics != nil {
431457
c.OnMetrics(*metrics)
432458
}
459+
// Ahead of the content callbacks: a surface that reacts to both should
460+
// hear "a turn started" before it hears what the turn said.
461+
if opened != 0 && c.OnTurnOpen != nil {
462+
c.OnTurnOpen(opened)
463+
}
433464
for _, m := range finalized {
434465
if c.OnClosed != nil {
435466
c.OnClosed(m)

‎skills/figaro/contributing/maintaining.md‎

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -246,6 +246,32 @@ ran: same failure, and it has cost this project several cycles.
246246

247247
Prove the fixture can fail, then trust what it says.
248248

249+
### A test file can silently not exist
250+
251+
Go decides which files compile from the FILENAME, before it reads a line of
252+
them. A file whose name ends in `_<goos>.go` or `_<goarch>.go` is constrained
253+
to that platform, and `_test` in front of the suffix does not exempt it:
254+
`thinking_arm_test.go` compiles only on GOARCH=arm, so on this machine it is
255+
not a file with a failing test in it, it is a file that is not there.
256+
257+
The failure mode is the quiet one. `go build` is clean, `go vet` is clean,
258+
`go test ./internal/cli/` is clean, and `-run TestTheThing` answers
259+
`ok ... [no tests to run]`, which reads as a typo in the pattern rather than
260+
as a missing file. Nothing anywhere says the word "arm".
261+
262+
The suffixes that bite are ordinary English: `_arm`, `_386`, `_ios`, `_js`,
263+
`_plan9`, `_windows`, `_linux`, `_darwin`, `_android`, `_wasm`. So do not name
264+
a file after a verb ending in "arm", or after a subsystem called "linux", and
265+
when a new test does not run, check that the compiler agrees it exists before
266+
touching the test itself:
267+
268+
```bash
269+
go list -f '{{range .TestGoFiles}}{{.}}{{"\n"}}{{end}}' ./internal/cli/ | grep <name>
270+
```
271+
272+
Empty output means the filename is the bug. Rename it (`thinking_armed_test.go`)
273+
and the test appears.
274+
249275
### An equivalence oracle is not scaffolding
250276

251277
When you replace an implementation with a faster one that must behave

0 commit comments

Comments
 (0)