Skip to content

Commit ec0d877

Browse files
committed
docs: trace-bugs followup to #867 — what this branch actually fixes
1 parent b86ecb4 commit ec0d877

1 file changed

Lines changed: 295 additions & 0 deletions

File tree

Lines changed: 295 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,295 @@
1+
# Trace bugs — what this branch fixes and why #867 didn't catch them
2+
3+
Companion document to the `fix/trace-clearing-on-workspace-set` branch.
4+
Lists the actual bugs found and fixed; excludes the diagnostic dead-ends
5+
that didn't pan out.
6+
7+
## Bugs fixed in this branch
8+
9+
### 1. Per-turn `session.status === "idle"` finalized the trace every turn
10+
11+
**Location**: `packages/opencode/src/cli/cmd/tui/worker.ts:232-243` (removed in this branch)
12+
13+
**Mechanism**: the handler called `trace.endTrace()` + `sessionTraces.delete(sid)`
14+
whenever `event.type === "session.status"` and `status.type === "idle"`.
15+
`idle` is a **busy→idle transition** — it fires after every agent turn
16+
finishes, not at session end. Every fire destroyed the Trace instance
17+
and removed it from the cache. The next event for the same session in
18+
the next turn hit a cache miss in `getOrCreateTrace`, called
19+
`Trace.create()` + `startTrace(sessionID, {})`, which pushed a single
20+
root span into a freshly-empty `this.spans` and the immediate `snapshot()`
21+
clobbered the rich on-disk `ses_<id>.json` with a 1-span file.
22+
23+
**Symptom**:
24+
- Waterfall view collapsed to the system-prompt span after every turn
25+
- `metadata.prompt` reset to undefined ("What was asked / No prompt
26+
recorded")
27+
- Token / generation / tool-call counters in `summary` reset to 0/null
28+
29+
**Severity**: hot path on every multi-turn session. Fired ~once per
30+
agent turn for every session in the cache.
31+
32+
**Why the comment in the code was misleading**: the original handler
33+
carried the comment "Finalize trace when session reaches idle
34+
(completed)" — the developer who wrote it conflated `idle` (per-turn
35+
event) with session-end. Sessions in altimate-code are long-lived
36+
across many turns; finalization belongs on `shutdown` or eviction, not
37+
per-turn idle.
38+
39+
**Fix**: handler removed. Trace lives as long as the worker has the
40+
session in its `sessionTraces` map. Finalization happens only on
41+
`worker.shutdown` and on MAX_TRACES eviction — both already correct.
42+
43+
### 2. `getOrCreateTrace` cache-miss never rehydrated from disk
44+
45+
**Location**: `packages/opencode/src/cli/cmd/tui/worker.ts:83-106`,
46+
`packages/opencode/src/altimate/observability/tracing.ts`
47+
(`rehydrateFromFile`, new method)
48+
49+
**Mechanism**: when `sessionTraces.has(sessionID)` returned false, the
50+
worker called `Trace.create()` + `startTrace(sessionID, {})` — which
51+
unconditionally pushed a fresh root span into empty `this.spans` and
52+
wrote a snapshot. The on-disk path is derived purely from `sessionID`,
53+
so the snapshot clobbered any pre-existing rich trace at that path.
54+
55+
**Triggered when**:
56+
- Worker process restart (sessionTraces empty on boot, user resumes
57+
a session whose trace file already has content)
58+
- MAX_TRACES=100 eviction (the evicted session may be revisited later)
59+
- Any future code path that drops in-memory state for an active session
60+
61+
After fix #1, these are uncommon — but still real edge cases.
62+
63+
**Fix**: new `Trace.rehydrateFromFile(sessionId)` reads
64+
`~/.local/share/altimate-code/traces/ses_<id>.json` if it exists,
65+
parses it, restores `this.spans`, `this.metadata`, `this.rootSpanId`,
66+
`this.startTime`, and the running counters (`totalTokens`,
67+
`toolCallCount`, `generationCount`, token breakdown). Clears the root
68+
span's `endTime` so the trace renders as still-in-progress and accepts
69+
new events. `getOrCreateTrace` now prefers rehydration over
70+
`startTrace`; falls back to `startTrace` only when no usable on-disk
71+
file is found.
72+
73+
### 3. `worker.setWorkspace` was not idempotent
74+
75+
**Location**: `packages/opencode/src/cli/cmd/tui/worker.ts:308-313`
76+
77+
**Mechanism**: each call unconditionally invoked `startEventStream`,
78+
which called `endTrace()` on every entry in `sessionTraces` (fire-and-
79+
forget) and then `sessionTraces.clear()`. Combined with the SolidJS
80+
effect upstream (see #4), this meant every spurious effect re-run
81+
destroyed the entire trace cache.
82+
83+
**Fix**: track `currentWorkspaceID` at module scope; early-return when
84+
`input.workspaceID === currentWorkspaceID`. Defense in depth against the
85+
upstream UI sending spurious calls.
86+
87+
### 4. SolidJS effect on workspaceID re-ran on every session signal change
88+
89+
**Location**: `packages/opencode/src/cli/cmd/tui/routes/session/index.tsx:186-190`
90+
91+
**Mechanism**: `createEffect(() => session()?.workspaceID && sdk.setWorkspace(...))`
92+
reads `session()` inside the effect — SolidJS dirty-tracks the entire
93+
session signal, not the projected `workspaceID`. So the effect re-ran
94+
on every `session()` update (message count, status, parts updated,
95+
title regenerated, …). Each fire propagated into the worker's
96+
`setWorkspace`.
97+
98+
**Fix**: switched to `createEffect(on(() => session()?.workspaceID, ...))`.
99+
The `on()` projector restricts dirty-tracking to that one field, so
100+
the effect only fires when `workspaceID` actually changes.
101+
102+
### 5. User prompt was never captured
103+
104+
**Location**: `packages/opencode/src/cli/cmd/tui/worker.ts` (Path B in
105+
the `message.part.updated` handler)
106+
107+
**Mechanism**: three different code paths fed `metadata.prompt`:
108+
109+
- **Path A** (`message.updated` for user role): only fired if
110+
`info.summary?.title || info.summary?.body` was populated — i.e.
111+
only after the title-agent had run. For a first turn, summary is
112+
empty when the event arrives. Doesn't fire.
113+
- **Path B** (`message.part.updated` text part): gated on
114+
`part.type === "text" && part.time?.end`. **User-input parts never
115+
have `time.end` set** — it's a meaningful concept only for
116+
processing-end of assistant chunks. Gate never opens for user text.
117+
- **Path C** (`session.updated` with auto-generated title): called
118+
`trace.setTitle(String(info.title))` with **one argument only** —
119+
set the title but not the prompt.
120+
121+
Result: title got captured (via Path C, with the auto-generated
122+
"Greeting"-style title), prompt stayed `undefined`. Viewer shows
123+
"What was asked / No prompt recorded".
124+
125+
**Codex review feedback (2026-06-05)**: even if we drop the `time.end`
126+
gate in Path B, calling `trace.setTitle(text, text)` mutates **both**
127+
title and prompt. If Path B fires after Path C, the nice auto-
128+
generated title regresses to raw user input ("Greeting" → "hi"). The
129+
right fix decouples title mutation from prompt capture.
130+
131+
**Fix**:
132+
- New `Trace.setPrompt(prompt)` method on the Trace class. Only
133+
mutates `metadata.prompt`. Never touches title.
134+
- Path B in `worker.ts`: dropped `part.time?.end` for the user-
135+
identified branch; calls `setPrompt(text)` instead of
136+
`setTitle(text, text)`. Assistant-text branch still requires
137+
`time.end` for `logText`.
138+
139+
### 6. User messages were not first-class events in the trace data model
140+
141+
**Location**: trace data model (no `kind: "user-message"` span before
142+
this branch), `viewer.ts` chat-view renderer
143+
144+
**Mechanism**: the trace recorded user input only as a single
145+
`metadata.prompt` string. Each new `setPrompt` overwrote the previous
146+
value. The viewer's chat tab rendered `metadata.prompt` as one
147+
"▶ You" bubble at the top, then iterated `kind: "generation"` spans
148+
for assistant replies. There was no place for any user message
149+
beyond the first.
150+
151+
**Symptom on a 3-turn session**: chat tab showed the **last** user
152+
prompt followed by **all** earlier assistant responses, with the older
153+
user messages dropped.
154+
155+
**Fix**:
156+
- New `Trace.logUserMessage(text)` pushes a `kind: "user-message"`
157+
span. `TraceSpan.kind` union extended.
158+
- Worker Path B calls `logUserMessage(text)` alongside `setPrompt(text)`
159+
for each user-identified part.
160+
- Viewer chat-view rebuilt: filters both user-message and generation
161+
spans, sorts by `startTime`, walks them in turn order. Renders each
162+
user-message span as its own "▶ You" bubble. Older traces without
163+
user-message spans fall back to `metadata.prompt`-at-top —
164+
backward compatible.
165+
166+
---
167+
168+
## What PR #867 fixed (for comparison)
169+
170+
PR #867 (merged 2026-06-01, "fix(tracing): close trace corruption in
171+
long-running sessions") closed two concurrency bugs and explicitly
172+
left a third as a documented design hazard:
173+
174+
### M2 — debounce dropped events with no follow-up snapshot
175+
176+
`Trace.snapshot()` returned early when `snapshotPending=true` and was
177+
never re-scheduled. In bursty turns (an LLM step firing several tool
178+
calls back-to-back), the disk file lagged memory until a fresh event
179+
arrived in a future turn. If the process exited in the gap, the burst's
180+
tail was lost.
181+
182+
**Fix**: `snapshotRequestedDuringPending` flag whenever `snapshot()`
183+
short-circuits. In `.finally()`, if the flag is set and the trace is
184+
neither crashed nor ending, schedule exactly one follow-up snapshot
185+
via `queueMicrotask`. Bounded — at most one extra write per
186+
"burst → quiet" cycle regardless of burst size.
187+
188+
### M3 — `FileExporter.export()` raced `flushSync` with no `crashed` guard
189+
190+
`endTrace()` calls `exporter.export()`, which does `writeFile(tmp)`
191+
→ `rename(tmp, final)`. On multi-MB traces the writeFile takes 100+ms,
192+
a wide window for `flushSync` to interleave. The `crashed` flag added
193+
in commit `38463876b` only guarded `Trace.snapshot()`, not
194+
`FileExporter.export()`, so `flushSync`'s synchronous crashed write
195+
was overwritten by the export's rename.
196+
197+
**Fix**: per-session `_crashed` flag on `FileExporter` with
198+
`markCrashed()`. Checked at entry, before writeFile, and before rename
199+
(drop tmp + bail). `flushSync` iterates exporters and calls
200+
`markCrashed()` on each before its own synchronous write.
201+
202+
### M2 companion — `endTraceStarted` gate
203+
204+
Once `endTrace()` claims the canonical write, no concurrent snapshot
205+
may run — they would race endTrace's mutation of the root span
206+
(endTime, status) and could clobber endTrace's content with stale
207+
pre-end state.
208+
209+
### M1 — NOT closed in #867
210+
211+
The TOCTOU between the synchronous `if (this.crashed)` check and the
212+
asynchronous kernel `fs.rename` syscall. Documented as a known design
213+
hazard; existing `crashed` flag from `38463876b` protects against it
214+
on local SSD (microsecond rename window). Theoretical exposure remains
215+
on slow/network filesystems.
216+
217+
---
218+
219+
## Why #867 didn't catch the bugs in this branch
220+
221+
### Different layer of abstraction
222+
223+
PR #867's bugs all live at the **intra-Trace-instance concurrency
224+
layer** — within one Trace object's state machine:
225+
226+
- Snapshot debounce/follow-up timing within one instance
227+
- FileExporter ↔ flushSync interleave for one instance's write
228+
- endTrace ↔ snapshot races for one instance
229+
230+
This branch's bugs (#1, #2, #3, #4) all live at the **cross-instance
231+
lifecycle layer** — when one Trace instance gets destroyed and another
232+
is constructed for the same `sessionID`:
233+
234+
- When destruction happens (idle handler / setWorkspace / cache eviction)
235+
- What happens on the next `Trace.create()` (no disk rehydration)
236+
- What the upstream UI triggers cause it (SolidJS effect)
237+
238+
The two layers are orthogonal. #867's reproducers (`tracing-rename-race.test.ts`,
239+
`tracing-display-crash.test.ts`) all hold one Trace instance for their
240+
entire test lifecycle and exercise crash/burst conditions against
241+
that instance. They cannot detect a bug whose mechanism is "destroy
242+
the instance, build a new one, watch the new one's first write
243+
clobber the old one's file."
244+
245+
### The destructive handler was intentional code, not a concurrency bug
246+
247+
The per-turn idle handler (#1) was **the developer's intent** — they
248+
explicitly named it "Finalize trace when session reaches idle
249+
(completed)". The bug is a semantic misunderstanding of what `idle`
250+
means at the event level (per-turn vs per-session), not a race or
251+
data corruption. #867's reproducer matrix wouldn't have surfaced it
252+
because none of the M-class bugs involved destroying the Trace and
253+
the reproducers all assumed a single instance.
254+
255+
### Data-feed and rendering layers were out of scope
256+
257+
#867 worked on the **persistence layer** (FileExporter, snapshot,
258+
flushSync). The prompt-capture and chat-rendering bugs (#5, #6) live
259+
at:
260+
261+
- **Worker event-handler layer** (`worker.ts`) — what gets fed into
262+
the Trace from the bus event stream
263+
- **Trace data-model layer** (`tracing.ts`) — what fields and span
264+
kinds the Trace exposes
265+
- **Viewer layer** (`viewer.ts`) — how rendered HTML iterates spans
266+
267+
All three are independent of crash/race safety. A 100%-correct
268+
persistence layer can still ship a 1-span trace file if upstream
269+
feeds only 1 span, or render a single "You" bubble if the data model
270+
only carries `metadata.prompt`.
271+
272+
### No cross-turn integration tests
273+
274+
Existing tracing tests are concurrency reproducers and unit tests of
275+
isolated methods. None exercise the full event-stream-to-trace-file
276+
path for a multi-turn session. The cross-turn nature of the idle
277+
clobber requires a test that drives at least two `busy → idle` cycles
278+
through the worker's event handler against a real `Trace` instance.
279+
280+
This branch adds:
281+
282+
- `test/cli/tui/worker-trace-clearing.test.ts` — source-grep contract
283+
tests that lock the no-idle-clobber, rehydrate-before-startTrace,
284+
and `setPrompt`-not-`setTitle` invariants in worker.ts.
285+
- `test/altimate/tracing-rehydrate.test.ts` — behavioral tests for
286+
`Trace.rehydrateFromFile` (preserve spans/metadata/counters,
287+
reject missing/mismatched/malformed files, clear endTime on
288+
rehydrate) and for `logUserMessage` (chronological ordering).
289+
290+
A higher-fidelity follow-up would be a real-worker integration test
291+
that emits a synthetic `session.status` idle event between two turns
292+
and asserts the trace file does not collapse — that needs the worker
293+
event loop running against a stub bus. Worth adding as a separate
294+
PR; the source-grep + behavioral tests are sufficient to lock the
295+
contracts in this PR.

0 commit comments

Comments
 (0)