|
| 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