Skip to content

Commit 06a60fa

Browse files
authored
Fix reasoning section elapsed timers (#4629)
Fix reasoning-section elapsed timers so each thinking block measures from when that block starts, not from the beginning of the run. This prevents later “Thought for …” sections in long tool-using runs from showing inflated durations that grow across the whole run. ## Root Cause `ReasoningBlock` received the parent run timestamp and used it for both the live elapsed timer and the final collapsed `Thought for …` label. In multi-step runs, later reasoning rows can start well after the run begins — for example after a tool call returns — so anchoring every row to the run start made each new reasoning section inherit all prior run time. ## Approach - Make `ReasoningBlock` own its timing anchor locally. - Capture the first render where that reasoning row is live. - Use that captured timestamp for the live `ElapsedTime` display. - Snapshot the final duration when the row transitions from `streaming` to `completed`. - Remove the misleading parent `timestamp` prop from the reasoning block API. Rows that mount already completed still render as bare `Thought`, because the UI does not know their true start/end duration. ## Key Invariants - A reasoning block’s elapsed time is scoped to that block, not the whole run. - Later reasoning blocks must not inherit time spent in previous thinking, text, or tool-call sections. - Historical/completed reasoning rows should not invent durations from incomplete client-side timing data. - The parent response timestamp remains available for response-level metadata, but not for per-reasoning timing. ## Non-goals - This does not persist reasoning start/end timestamps in the backend schema. - This does not change response-level `✓ done in …` timing. - This does not alter reasoning ordering, markdown rendering, or redacted reasoning behavior. ## Trade-offs This uses the client-observed first-live-render time rather than a persisted provider/server timestamp. That is intentionally scoped: it fixes the live UI inflation bug without adding schema or event-model changes. Historical rows still avoid showing made-up durations. ## Verification ```bash cd packages/agents-server-ui pnpm test src/components/ReasoningSection.test.tsx pnpm typecheck ``` Also validated changeset coverage: ```bash GITHUB_BASE_REF=main node scripts/check-changeset.mjs ``` ## Files changed - `.changeset/fix-reasoning-timers.md` - Adds a patch changeset for `@electric-ax/agents-server-ui`. - `packages/agents-server-ui/src/components/AgentResponse.tsx` - Stops passing the parent run timestamp into `ReasoningBlock`. - `packages/agents-server-ui/src/components/ReasoningSection.tsx` - Captures per-reasoning-row live start time. - Uses that local start time for live and settled reasoning duration labels. - Removes the `timestamp` prop from `ReasoningBlock`. - `packages/agents-server-ui/src/components/ReasoningSection.test.tsx` - Adds regression coverage proving live reasoning timers do not start from the run timestamp. - Adds client-rendered coverage for the live → completed transition producing `Thought for Ns`.
1 parent c14a886 commit 06a60fa

4 files changed

Lines changed: 111 additions & 19 deletions

File tree

.changeset/fix-reasoning-timers.md

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,5 @@
1+
---
2+
'@electric-ax/agents-server-ui': patch
3+
---
4+
5+
Fix reasoning section elapsed timers so each thinking block measures from when that block starts, rather than from the beginning of the run.

packages/agents-server-ui/src/components/AgentResponse.tsx

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -666,7 +666,6 @@ export const AgentResponseLive = memo(function AgentResponseLive({
666666
key={entry.key}
667667
entry={entry.reasoning}
668668
isStreaming={isStreaming}
669-
timestamp={timestamp}
670669
expanded={Boolean(expandedReasoning[entry.key])}
671670
onToggle={toggleReasoning}
672671
/>
Lines changed: 92 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,92 @@
1+
// @vitest-environment jsdom
2+
3+
import { afterEach, beforeAll, describe, expect, it, vi } from 'vitest'
4+
import { act } from 'react'
5+
import { createRoot, type Root } from 'react-dom/client'
6+
import { renderToStaticMarkup } from 'react-dom/server'
7+
import { ReasoningBlock, type ReasoningEntry } from './ReasoningSection'
8+
9+
beforeAll(() => {
10+
;(
11+
globalThis as typeof globalThis & { IS_REACT_ACT_ENVIRONMENT?: boolean }
12+
).IS_REACT_ACT_ENVIRONMENT = true
13+
})
14+
15+
const streamingEntry: ReasoningEntry = {
16+
key: `reasoning-1`,
17+
order: `1`,
18+
content: `Inspecting the code.`,
19+
status: `streaming`,
20+
summary_title: `Inspecting code`,
21+
}
22+
23+
function renderReasoningBlock(
24+
root: Root,
25+
entry: ReasoningEntry,
26+
isStreaming: boolean
27+
): void {
28+
act(() => {
29+
root.render(
30+
<ReasoningBlock
31+
entry={entry}
32+
isStreaming={isStreaming}
33+
expanded={false}
34+
onToggle={() => {}}
35+
/>
36+
)
37+
})
38+
}
39+
40+
afterEach(() => {
41+
vi.useRealTimers()
42+
})
43+
44+
describe(`ReasoningBlock`, () => {
45+
it(`anchors live thinking elapsed time to the reasoning block start, not the run start`, () => {
46+
vi.useFakeTimers()
47+
try {
48+
const runStartedAt = new Date(`2026-01-01T00:00:00.000Z`).getTime()
49+
vi.setSystemTime(runStartedAt + 5 * 60 * 1000)
50+
51+
const markup = renderToStaticMarkup(
52+
<ReasoningBlock
53+
entry={streamingEntry}
54+
isStreaming={true}
55+
expanded={false}
56+
onToggle={() => {}}
57+
/>
58+
)
59+
60+
expect(markup).toContain(`Elapsed time: 0s`)
61+
expect(markup).not.toContain(`Elapsed time: 5m`)
62+
} finally {
63+
vi.useRealTimers()
64+
}
65+
})
66+
67+
it(`snapshots the reasoning duration when a live block completes`, () => {
68+
vi.useFakeTimers()
69+
const container = document.createElement(`div`)
70+
document.body.appendChild(container)
71+
const root = createRoot(container)
72+
73+
try {
74+
const startedAt = new Date(`2026-01-01T00:00:00.000Z`).getTime()
75+
vi.setSystemTime(startedAt)
76+
renderReasoningBlock(root, streamingEntry, true)
77+
78+
vi.setSystemTime(startedAt + 3_000)
79+
renderReasoningBlock(
80+
root,
81+
{ ...streamingEntry, status: `completed` },
82+
false
83+
)
84+
85+
expect(container.textContent).toContain(`Thought for 3s`)
86+
} finally {
87+
act(() => root.unmount())
88+
container.remove()
89+
vi.useRealTimers()
90+
}
91+
})
92+
})

packages/agents-server-ui/src/components/ReasoningSection.tsx

Lines changed: 14 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@ import {
88
import { Stack, Text } from '../ui'
99
import { ThinkingIndicator } from './ThinkingIndicator'
1010
import { ElapsedTime } from './ElapsedTime'
11-
import { formatElapsedDuration, toMillis } from '../lib/formatTime'
11+
import { formatElapsedDuration } from '../lib/formatTime'
1212
import styles from './ReasoningSection.module.css'
1313

1414
/**
@@ -63,13 +63,11 @@ export type ReasoningEntry = {
6363
export function ReasoningBlock({
6464
entry,
6565
isStreaming,
66-
timestamp,
6766
expanded,
6867
onToggle,
6968
}: {
7069
entry: ReasoningEntry
7170
isStreaming: boolean
72-
timestamp?: number | null
7371
expanded: boolean
7472
onToggle: (key: string) => void
7573
}): React.ReactElement {
@@ -79,26 +77,24 @@ export function ReasoningBlock({
7977
[entry.key, onToggle]
8078
)
8179

82-
// Snapshot the elapsed duration at the moment streaming flips to
83-
// `completed`, the same `sawStreamingRef` trick used for "done in
84-
// Xs" on `AgentResponse`. For reasoning rows that were already
85-
// settled on first mount (page reload, scrollback into older
86-
// turns) we don't have a real end timestamp, so the closure stays
87-
// a bare "Thought" without a duration — better than printing a
88-
// wildly-wrong number from `now() - userMessageTime`.
89-
const sawStreamingRef = useRef<boolean>(isLive)
90-
if (isLive) sawStreamingRef.current = true
80+
// Capture this reasoning row's first live render time. Later rows
81+
// may start after tool calls, so using the parent run timestamp
82+
// overstates their duration. Rows mounted already completed keep a
83+
// bare "Thought" label because we do not know their actual end time.
84+
const liveStartedAtMsRef = useRef<number | null>(null)
85+
if (isLive && liveStartedAtMsRef.current == null) {
86+
liveStartedAtMsRef.current = Date.now()
87+
}
9188
const [finalDurationMs, setFinalDurationMs] = useState<number | null>(null)
9289
useEffect(() => {
9390
if (
9491
entry.status === `completed` &&
95-
sawStreamingRef.current &&
96-
timestamp != null &&
92+
liveStartedAtMsRef.current != null &&
9793
finalDurationMs == null
9894
) {
99-
setFinalDurationMs(Math.max(0, Date.now() - toMillis(timestamp)))
95+
setFinalDurationMs(Math.max(0, Date.now() - liveStartedAtMsRef.current))
10096
}
101-
}, [entry.status, timestamp, finalDurationMs])
97+
}, [entry.status, finalDurationMs])
10298

10399
// Redacted thinking — opaque payload, nothing to render.
104100
if (entry.encrypted && entry.content.trim().length === 0) {
@@ -126,12 +122,12 @@ export function ReasoningBlock({
126122
</Text>
127123
</>
128124
)}
129-
{timestamp != null && (
125+
{liveStartedAtMsRef.current != null && (
130126
<>
131127
<Text size={1} tone="muted" className={styles.separator}>
132128
·
133129
</Text>
134-
<ElapsedTime ts={timestamp} enabled={isLive} />
130+
<ElapsedTime ts={liveStartedAtMsRef.current} enabled={isLive} />
135131
</>
136132
)}
137133
</Stack>

0 commit comments

Comments
 (0)