From 807e0009dd92df0bd4a325214b5d0186482d0ff7 Mon Sep 17 00:00:00 2001 From: Haider Date: Fri, 5 Jun 2026 19:56:49 +0530 Subject: [PATCH 01/12] fix(tracing): waterfall view collapses to system-prompt span on agent-finish MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Symptom: opening `/traces` mid-session and watching the waterfall view during agent execution shows the rich trace populating correctly, but the moment the agent finishes its turn the view collapses to a single "system-prompt" span — and the data is genuinely lost on disk, not just from the viewer. Chain (verified by reading worker.ts + routes/session/index.tsx + tracing.ts): 1. `routes/session/index.tsx` has `createEffect(() => session()?.workspaceID && sdk.setWorkspace(...))`. SolidJS dirty-tracks any signal read inside the effect — so it re-runs on EVERY `session()` change (message count, status, parts updates), including the cascade at agent-finish. 2. Each fire calls `worker.setWorkspace` via RPC. 3. `worker.setWorkspace` unconditionally calls `startEventStream`. 4. `startEventStream`: for (const [, trace] of sessionTraces) { void trace.endTrace().catch(() => {}) // fire-and-forget } sessionTraces.clear() 5. On the next event for the same session, `getOrCreateTrace` hits a cache miss, calls `Trace.create()` + `startTrace(sessionID, {})`, which pushes a single root span into a freshly-empty `this.spans` and calls `this.snapshot()`. The snapshot path is derived purely from sessionID (`tracing.ts:836`), so it overwrites the rich `ses_.json` with a 1-span file. Distinct from #867 — that PR fixed intra-Trace-instance concurrency (snapshot debounce M2; FileExporter ↔ flushSync race M3). This bug is at the worker-level cache lifecycle: a new Trace instance gets constructed and its near-empty initial state clobbers the previous instance's rich state on disk. Two minimal fixes lock the contract: * `worker.ts` — make `setWorkspace` idempotent. Track `currentWorkspaceID` at module scope; early-return when the incoming value matches. Spurious calls from the UI no longer destroy traces. * `routes/session/index.tsx` — switch the workspaceID effect to `createEffect(on(() => session()?.workspaceID, ...))`. The `on()` projector restricts SolidJS dirty-tracking to that one field, so the effect only fires when workspaceID actually changes — defense in depth at the upstream trigger. Regression test in `test/cli/tui/worker-trace-clearing.test.ts` locks both contracts via source-grep (the worker-import side has top-level side effects that make in-process unit testing awkward). Out of scope (follow-up): `getOrCreateTrace` on cache miss does not rehydrate `this.spans` from the existing `ses_.json` file. After the two fixes above, this matters only on worker restart or MAX_TRACES=100 eviction — both uncommon. Worth tracking as defense in depth so the disk file is always authoritative. Typecheck clean. 152 TUI tests pass; 35 existing tracing tests pass unchanged. --- .../src/cli/cmd/tui/routes/session/index.tsx | 22 ++++-- packages/opencode/src/cli/cmd/tui/worker.ts | 14 ++++ .../cli/tui/worker-trace-clearing.test.ts | 69 +++++++++++++++++++ 3 files changed, 100 insertions(+), 5 deletions(-) create mode 100644 packages/opencode/test/cli/tui/worker-trace-clearing.test.ts diff --git a/packages/opencode/src/cli/cmd/tui/routes/session/index.tsx b/packages/opencode/src/cli/cmd/tui/routes/session/index.tsx index d6cd5a7a85..a63ddb2c94 100644 --- a/packages/opencode/src/cli/cmd/tui/routes/session/index.tsx +++ b/packages/opencode/src/cli/cmd/tui/routes/session/index.tsx @@ -183,11 +183,23 @@ export function Session() { return new CustomSpeedScroll(3) }) - createEffect(() => { - if (session()?.workspaceID) { - sdk.setWorkspace(session()?.workspaceID) - } - }) + // altimate_change start — gate setWorkspace on actual workspaceID change. + // Plain `createEffect(() => session()?.workspaceID && sdk.setWorkspace(...))` + // re-fires whenever any field on the session signal changes (message count, + // status, parts) — including the cascade of updates at agent-finish. Every + // spurious fire propagates into `worker.setWorkspace` → `startEventStream` → + // `sessionTraces.clear()` → next snapshot overwrites the rich on-disk trace + // with a near-empty one. `on()` here restricts the effect to fire only when + // the projected `workspaceID` value actually changes. + createEffect( + on( + () => session()?.workspaceID, + (workspaceID) => { + if (workspaceID) sdk.setWorkspace(workspaceID) + }, + ), + ) + // altimate_change end createEffect(async () => { await sync.session diff --git a/packages/opencode/src/cli/cmd/tui/worker.ts b/packages/opencode/src/cli/cmd/tui/worker.ts index 3e2b78de15..d3f9b174d0 100644 --- a/packages/opencode/src/cli/cmd/tui/worker.ts +++ b/packages/opencode/src/cli/cmd/tui/worker.ts @@ -261,6 +261,16 @@ const startEventStream = (input: { directory: string; workspaceID?: string }) => }) } +// altimate_change start — track the last workspaceID used to start the event stream +// so `setWorkspace` becomes idempotent on unchanged values. SolidJS effects in the +// session route can fire on every `session()` signal change (including agent-finish); +// without this guard, every fire propagates to `startEventStream` which clears +// `sessionTraces`, which causes the next snapshot from a freshly-created Trace to +// overwrite the rich on-disk trace with a near-empty one. Symptom: waterfall view +// collapses to the system-prompt span after every turn. +let currentWorkspaceID: string | undefined +// altimate_change end + startEventStream({ directory: process.cwd() }) export const rpc = { @@ -306,6 +316,10 @@ export const rpc = { await Instance.disposeAll() }, async setWorkspace(input: { workspaceID?: string }) { + // altimate_change start — idempotency guard; see currentWorkspaceID comment above + if (input.workspaceID === currentWorkspaceID) return + currentWorkspaceID = input.workspaceID + // altimate_change end startEventStream({ directory: process.cwd(), workspaceID: input.workspaceID }) }, async shutdown() { diff --git a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts new file mode 100644 index 0000000000..8097b465f2 --- /dev/null +++ b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts @@ -0,0 +1,69 @@ +import { describe, expect, test } from "bun:test" +import path from "path" +import fs from "fs/promises" + +const ROOT = path.resolve(__dirname, "../../../") + +// Regression guards for the trace-clearing-on-workspace-set bug. +// +// Bug shape (full chain): +// +// 1. SolidJS createEffect in `routes/session/index.tsx` watches +// `session()?.workspaceID` but re-runs on every `session()` signal change +// (message count, status, parts updated, …) — including the cascade at +// agent-finish. +// 2. Each fire calls `sdk.setWorkspace(workspaceID)` via RPC. +// 3. `worker.setWorkspace` unconditionally calls `startEventStream`. +// 4. `startEventStream` calls `endTrace()` on every entry in `sessionTraces` +// (fire-and-forget) and then `sessionTraces.clear()`. +// 5. On the next event for the same session, `getOrCreateTrace(sessionID)` +// hits a cache miss, calls `Trace.create()` + `startTrace(sessionID, {})`, +// which pushes a single root span into a freshly-empty `this.spans`. +// `startTrace` then writes a snapshot — overwriting the rich on-disk trace +// with a near-empty one. +// +// Observable: `/traces` waterfall view collapses to just the system-prompt +// span after every agent-finish. +// +// Two fixes lock the contract here: +// - `worker.setWorkspace` is now idempotent on unchanged workspaceID. +// - `createEffect` in `routes/session/index.tsx` uses `on(...)` so it only +// fires when the projected `workspaceID` actually changes. + +describe("trace-clearing-on-workspace-set regression", () => { + test("worker.setWorkspace short-circuits when workspaceID is unchanged", async () => { + const workerSrc = await fs.readFile(path.join(ROOT, "src/cli/cmd/tui/worker.ts"), "utf-8") + + // A `currentWorkspaceID` tracker is declared at module scope. + expect(workerSrc).toMatch(/let currentWorkspaceID:\s*string\s*\|\s*undefined/) + + // The setWorkspace handler must guard on equality with the tracker before + // calling startEventStream. Match either a strict-equality early return or + // the same pattern wrapped in a block. + expect(workerSrc).toMatch( + /async setWorkspace\(input: \{ workspaceID\?: string \}\)\s*\{[\s\S]{0,400}if \(input\.workspaceID === currentWorkspaceID\) return/, + ) + + // After the guard, the tracker must be updated to the new value, otherwise + // a subsequent same-value call wouldn't short-circuit. + expect(workerSrc).toMatch( + /if \(input\.workspaceID === currentWorkspaceID\) return\s*\n\s*currentWorkspaceID = input\.workspaceID/, + ) + }) + + test("session route's workspaceID effect uses `on()` so it only fires when workspaceID actually changes", async () => { + const routeSrc = await fs.readFile( + path.join(ROOT, "src/cli/cmd/tui/routes/session/index.tsx"), + "utf-8", + ) + + // The previous shape (`createEffect(() => { if (session()?.workspaceID) ... })`) + // re-runs on every session() signal change. The fixed shape uses `on()` with + // an explicit projector returning workspaceID, so SolidJS dirty-tracks only + // that value. + expect(routeSrc).toMatch(/createEffect\(\s*on\(\s*\(\)\s*=>\s*session\(\)\?\.workspaceID/) + + // The unguarded inline form must not reappear — that would re-introduce the bug. + expect(routeSrc).not.toMatch(/createEffect\(\(\)\s*=>\s*\{\s*\n\s*if\s*\(session\(\)\?\.workspaceID\)/) + }) +}) From 189ab1e870a4e117ebdb35109878215f6b57b633 Mon Sep 17 00:00:00 2001 From: Haider Date: Fri, 5 Jun 2026 20:13:37 +0530 Subject: [PATCH 02/12] =?UTF-8?q?fix(tracing):=20real=20root=20cause=20?= =?UTF-8?q?=E2=80=94=20session.status=3Didle=20was=20destroying=20the=20Tr?= =?UTF-8?q?ace=20every=20turn?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Previous commit on this branch was correct but not load-bearing. The actual hot path that collapsed the on-disk trace after every agent turn is in `worker.ts`: if (event.type === "session.status") { if (status === "idle" && sid) { const trace = sessionTraces.get(sid) if (trace) { void trace.endTrace().catch(() => {}) sessionTraces.delete(sid) // ← every turn sessionUserMsgIds.delete(sid) } } } `session.status === "idle"` fires after every busy→idle transition, which happens once per turn — not once per session. Each fire ended the trace AND deleted the cache entry. The next event for the same session in the next turn hit a cache miss, constructed a fresh `Trace.create()`, called `startTrace(sessionID, {})` (which pushes a single root span into empty `this.spans`), and the immediate `snapshot()` clobbered the rich on-disk `ses_.json` with a 1-span file. This also explains the "What was asked / No prompt recorded" symptom: `metadata.prompt` was captured on the now-destroyed first instance and never persisted into the replacement. Fixes in this commit: * `worker.ts`: removed the destructive `session.status === "idle"` handler. Sessions in altimate-code are long-lived; the Trace lives as long as the worker has the session in cache. Finalization happens on `shutdown` and on MAX_TRACES eviction only — both already correct. * `tracing.ts`: new `Trace.rehydrateFromFile(sessionId)` that reads the existing on-disk file and restores `this.spans`, `this.metadata`, `this.rootSpanId`, `this.startTime`, counters, and clears the root's endTime so the trace renders as still-in-progress. Returns true on success; false on missing/mismatched/malformed file. * `worker.ts:getOrCreateTrace`: on cache miss, calls `rehydrateFromFile` before falling back to `startTrace`. Defense in depth for the worker-restart / MAX_TRACES-eviction paths — even if some future path destroys the in-memory instance, the new instance loads disk state instead of overwriting. Verification * Behavioral test (`test/altimate/tracing-rehydrate.test.ts`, 4 cases): proves end-to-end that rehydrate preserves spans+metadata across Trace-instance reconstruction, returns false on missing/mismatched files, and clears the root endTime so re-opened traces accept new events. * Source-grep regression tests for worker.ts continue to lock the no-idle-clobber and rehydrate-before-startTrace contracts. * 449 pass / 0 fail across the full tracing + TUI suites (1 network flake in tracing-adversarial-2 unrelated to this change, passes on re-run). What I traced before declaring done * Inventoried every `sessionTraces.delete`, `sessionTraces.clear`, `endTrace()`, `Trace.create()`, `Trace.withExporters()`, and direct trace-file write across the whole repo. * Confirmed `this.spans` is never reassigned mid-instance (only pushed) except by the new `rehydrateFromFile`. * Confirmed no external callers of `trace.snapshot()` outside `tracing.ts`. Post-fix, the only ways a new `Trace` instance can replace an existing session's in-memory Trace are: worker boot (once), `setWorkspace` with an actually-changed workspaceID (rare, also idempotency-guarded), and MAX_TRACES eviction (uncommon at 100 sessions). All three now go through `rehydrateFromFile` first. --- .../src/altimate/observability/tracing.ts | 64 +++++++ packages/opencode/src/cli/cmd/tui/worker.ts | 38 +++-- .../test/altimate/tracing-rehydrate.test.ts | 160 ++++++++++++++++++ .../cli/tui/worker-trace-clearing.test.ts | 28 +++ 4 files changed, 276 insertions(+), 14 deletions(-) create mode 100644 packages/opencode/test/altimate/tracing-rehydrate.test.ts diff --git a/packages/opencode/src/altimate/observability/tracing.ts b/packages/opencode/src/altimate/observability/tracing.ts index e0e742bc16..fcd67525fb 100644 --- a/packages/opencode/src/altimate/observability/tracing.ts +++ b/packages/opencode/src/altimate/observability/tracing.ts @@ -490,6 +490,70 @@ export class Trace { this.snapshot() } + // altimate_change start — rehydrate a Trace from an existing on-disk file. + // Used by `getOrCreateTrace` on cache miss for a session whose trace file + // already exists (worker restart, MAX_TRACES eviction). Without this, the + // fresh Trace.create() + startTrace() path would push a single root span + // into an empty `this.spans` and the immediate snapshot would clobber the + // rich on-disk trace. Returns true if a usable trace was loaded; false + // otherwise (the caller should fall back to startTrace). + // + // Does NOT call snapshot — the file is already correct on disk; an + // unnecessary write here would compete with concurrent flushSync paths. + rehydrateFromFile(sessionId: string): boolean { + if (!this.snapshotDir) return false + const safeId = sessionId.replace(/[/\\.:]/g, "_") || "unknown" + const filePath = path.join(this.snapshotDir, `${safeId}.json`) + let raw: string + try { + raw = fsSync.readFileSync(filePath, "utf-8") + } catch { + return false + } + let trace: TraceFile + try { + trace = JSON.parse(raw) as TraceFile + } catch { + return false + } + if (!trace || trace.sessionId !== sessionId || !Array.isArray(trace.spans) || trace.spans.length === 0) { + return false + } + const root = trace.spans.find((s) => s.parentSpanId === null && s.kind === "session") + if (!root) return false + + this.sessionId = sessionId + this.spans = trace.spans.map((s) => ({ ...s })) + this.rootSpanId = root.spanId + this.metadata = { ...(trace.metadata ?? {}) } + this.startTime = root.startTime + if (trace.summary) { + this.totalTokens = trace.summary.totalTokens ?? 0 + this.totalCost = trace.summary.totalCost ?? 0 + this.toolCallCount = trace.summary.totalToolCalls ?? 0 + this.generationCount = trace.summary.totalGenerations ?? 0 + if (trace.summary.tokens) { + this.tokensBreakdown = { + input: trace.summary.tokens.input ?? 0, + output: trace.summary.tokens.output ?? 0, + reasoning: trace.summary.tokens.reasoning ?? 0, + cacheRead: trace.summary.tokens.cacheRead ?? 0, + cacheWrite: trace.summary.tokens.cacheWrite ?? 0, + } + } + } + // Mid-session rehydration: the root span's endTime (if any) was set by a + // prior endTrace; clear it so the trace doesn't render as "completed." + const r = this.spans.find((s) => s.spanId === this.rootSpanId) + if (r) { + delete (r as { endTime?: number }).endTime + r.status = "ok" + } + this.endTraceStarted = false + return true + } + // altimate_change end + /** * Enrich the trace with model/provider info from the first assistant message. * Called when the message.updated event fires with assistant role. diff --git a/packages/opencode/src/cli/cmd/tui/worker.ts b/packages/opencode/src/cli/cmd/tui/worker.ts index d3f9b174d0..c83b0def91 100644 --- a/packages/opencode/src/cli/cmd/tui/worker.ts +++ b/packages/opencode/src/cli/cmd/tui/worker.ts @@ -96,7 +96,15 @@ function getOrCreateTrace(sessionID: string): Trace | null { const trace = tracingExporters ? Trace.withExporters([...tracingExporters], { maxFiles: tracingMaxFiles }) : Trace.create() - trace.startTrace(sessionID, {}) + // altimate_change start — prefer disk-rehydration on cache miss for an + // existing session (worker restart, MAX_TRACES eviction). startTrace would + // push a fresh root span into empty `this.spans` and the immediate + // snapshot would clobber the rich on-disk file. Defense in depth in + // addition to keeping the cache alive across turns. + if (!trace.rehydrateFromFile(sessionID)) { + trace.startTrace(sessionID, {}) + } + // altimate_change end Trace.setActive(trace) sessionTraces.set(sessionID, trace) return trace @@ -229,19 +237,21 @@ const startEventStream = (input: { directory: string; workspaceID?: string }) => if (trace) trace.setTitle(String(info.title)) } } - // Finalize trace when session reaches idle (completed) - if (event.type === "session.status") { - const sid = (event as any).properties?.sessionID - const status = (event as any).properties?.status?.type - if (status === "idle" && sid) { - const trace = sessionTraces.get(sid) - if (trace) { - void trace.endTrace().catch(() => {}) - sessionTraces.delete(sid) - sessionUserMsgIds.delete(sid) - } - } - } + // altimate_change start — DO NOT finalize the trace on session.status=idle. + // `idle` fires after every turn (busy → idle transition), not at session end. + // Calling `endTrace` + `sessionTraces.delete` here treats each turn as the + // end of the session: the next event for the same session in a later turn + // hits a cache miss in getOrCreateTrace, constructs a fresh Trace.create() + // with empty `this.spans`, and the immediate `snapshot()` clobbers the + // rich on-disk `ses_.json` with a single root-span file. Symptoms: + // - waterfall view collapses to the system-prompt span after every turn + // - "What was asked / No prompt recorded" because metadata.prompt was + // captured on the destroyed instance, never on the replacement + // Sessions in altimate-code are long-lived across many turns; the Trace + // should live as long as the worker has the session in cache. Finalization + // happens on `shutdown` (worker.ts:312) and on MAX_TRACES eviction + // (worker.ts:87). No per-turn finalization is correct. + // altimate_change end } catch { // Trace must never interrupt event forwarding } diff --git a/packages/opencode/test/altimate/tracing-rehydrate.test.ts b/packages/opencode/test/altimate/tracing-rehydrate.test.ts new file mode 100644 index 0000000000..5a2bd4a38d --- /dev/null +++ b/packages/opencode/test/altimate/tracing-rehydrate.test.ts @@ -0,0 +1,160 @@ +/** + * Behavioral test for `Trace.rehydrateFromFile` and the worker's + * cache-miss-rehydrates contract. + * + * The bug being guarded against: when the in-memory `Trace` instance for a + * session is destroyed (worker restart, MAX_TRACES eviction, the now-removed + * per-turn idle finalize) and a new `Trace` is constructed for the same + * `sessionID`, the fresh `this.spans = []` plus immediate `snapshot()` in + * `startTrace` would clobber the rich on-disk `ses_.json` with a 1-span + * file. Symptom: waterfall view collapses to system-prompt; metadata.prompt + * disappears. + * + * `rehydrateFromFile` is the defense-in-depth fix: on cache miss, load the + * existing trace state instead of starting fresh. + */ + +import { describe, expect, test, beforeEach, afterEach } from "bun:test" +import fs from "fs/promises" +import path from "path" +import os from "os" +import { Trace, FileExporter, type TraceFile } from "../../src/altimate/observability/tracing" + +let tmpDir: string + +beforeEach(async () => { + tmpDir = path.join(os.tmpdir(), `tracing-rehydrate-${Date.now()}-${Math.random().toString(36).slice(2)}`) + await fs.mkdir(tmpDir, { recursive: true }) +}) + +afterEach(async () => { + await fs.rm(tmpDir, { recursive: true, force: true }).catch(() => {}) +}) + +function makeTrace() { + return Trace.withExporters([new FileExporter(tmpDir)]) +} + +async function readTraceFile(sessionId: string): Promise { + const safeId = sessionId.replace(/[/\\.:]/g, "_") + const filePath = path.join(tmpDir, `${safeId}.json`) + return JSON.parse(await fs.readFile(filePath, "utf-8")) +} + +describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { + test("rehydrate preserves spans, metadata, and counters when reconstructing on cache miss", async () => { + const sessionId = "ses_rehydrate_basic" + + // Phase 1: original Trace builds up rich state, then is discarded (simulating + // a worker restart or MAX_TRACES eviction). + const original = makeTrace() + original.startTrace(sessionId, { + title: "test session", + prompt: "do the thing", + model: "openai/gpt-5.5", + providerId: "altimate-backend", + agent: "builder", + }) + // Simulate turn-1 activity: a few tool calls + some text. + original.logToolCall({ tool: "read", state: { status: "completed", input: { f: "a" } } } as any) + original.logToolCall({ tool: "grep", state: { status: "completed", input: { p: "x" } } } as any) + original.logText({ text: "first response", time: { end: Date.now() } } as any) + // Flush to disk so the file represents the cumulative state. + await original.flush() + + const onDiskAfterPhase1 = await readTraceFile(sessionId) + expect(onDiskAfterPhase1.spans.length).toBeGreaterThan(1) + expect(onDiskAfterPhase1.metadata.prompt).toBe("do the thing") + expect(onDiskAfterPhase1.metadata.title).toBe("test session") + + // Phase 2: drop the original (worker restart / eviction). Construct a fresh + // Trace instance for the SAME sessionID. This is the path that, pre-fix, + // would have called startTrace and clobbered the file. + const reconstructed = makeTrace() + const didRehydrate = reconstructed.rehydrateFromFile(sessionId) + + expect(didRehydrate).toBe(true) + + // Without writing anything yet, the in-memory state must reflect what was + // on disk: same spans, same metadata, same root id. + const fileImmediatelyAfterRehydrate = await readTraceFile(sessionId) + expect(fileImmediatelyAfterRehydrate.spans).toEqual(onDiskAfterPhase1.spans) + expect(fileImmediatelyAfterRehydrate.metadata.prompt).toBe("do the thing") + + // Phase 3: log new activity on the reconstructed Trace and flush. The next + // snapshot must preserve the old spans AND add the new ones — not overwrite. + reconstructed.logToolCall({ tool: "edit", state: { status: "completed", input: { f: "b" } } } as any) + await reconstructed.flush() + + const onDiskAfterPhase3 = await readTraceFile(sessionId) + expect(onDiskAfterPhase3.spans.length).toBeGreaterThan(onDiskAfterPhase1.spans.length) + // Old spans still there. + for (const oldSpan of onDiskAfterPhase1.spans) { + expect(onDiskAfterPhase3.spans.some((s) => s.spanId === oldSpan.spanId)).toBe(true) + } + // Metadata was preserved across the reconstruction. + expect(onDiskAfterPhase3.metadata.prompt).toBe("do the thing") + expect(onDiskAfterPhase3.metadata.title).toBe("test session") + expect(onDiskAfterPhase3.metadata.model).toBe("openai/gpt-5.5") + }) + + test("rehydrate returns false when no on-disk trace exists (fresh session)", async () => { + const trace = makeTrace() + const result = trace.rehydrateFromFile("ses_does_not_exist") + expect(result).toBe(false) + }) + + test("rehydrate returns false when on-disk trace is for a different session", async () => { + // Stage a mismatched file at the expected path for "session-A". + await fs.writeFile( + path.join(tmpDir, "ses_target.json"), + JSON.stringify({ + version: 2, + traceId: "x", + sessionId: "ses_other", + startedAt: new Date().toISOString(), + endedAt: new Date().toISOString(), + metadata: {}, + spans: [{ spanId: "r", parentSpanId: null, name: "ses_other", kind: "session", startTime: 0, status: "ok" }], + summary: { + totalTokens: 0, + totalCost: 0, + totalToolCalls: 0, + totalGenerations: 0, + duration: 0, + status: "completed", + tokens: { input: 0, output: 0, reasoning: 0, cacheRead: 0, cacheWrite: 0 }, + }, + }), + ) + const trace = makeTrace() + const result = trace.rehydrateFromFile("ses_target") + expect(result).toBe(false) + }) + + test("rehydrate clears endTime on the root span so the trace renders as still in-progress", async () => { + const sessionId = "ses_endtime_clear" + + const original = makeTrace() + original.startTrace(sessionId, {}) + original.logToolCall({ tool: "read", state: { status: "completed", input: { f: "a" } } } as any) + await original.endTrace() // sets root endTime + const ended = await readTraceFile(sessionId) + const endedRoot = ended.spans.find((s) => s.parentSpanId === null) + expect(endedRoot?.endTime).toBeDefined() + + const reconstructed = makeTrace() + const ok = reconstructed.rehydrateFromFile(sessionId) + expect(ok).toBe(true) + + // Trigger a snapshot via a real span push so the disk file gets re-written. + reconstructed.logToolCall({ tool: "grep", state: { status: "completed", input: { p: "x" } } } as any) + await reconstructed.flush() + + const afterRehydrate = await readTraceFile(sessionId) + const root = afterRehydrate.spans.find((s) => s.parentSpanId === null) + // The trace must be re-openable: the root endTime is cleared so subsequent + // turns don't render the trace as "completed" in the viewer. + expect(root?.endTime).toBeUndefined() + }) +}) diff --git a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts index 8097b465f2..d2f306138d 100644 --- a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts +++ b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts @@ -66,4 +66,32 @@ describe("trace-clearing-on-workspace-set regression", () => { // The unguarded inline form must not reappear — that would re-introduce the bug. expect(routeSrc).not.toMatch(/createEffect\(\(\)\s*=>\s*\{\s*\n\s*if\s*\(session\(\)\?\.workspaceID\)/) }) + + // The real root cause: a session.status=idle handler that called endTrace + + // sessionTraces.delete after every turn. `idle` fires on busy→idle transition + // (i.e. after every agent turn finishes), not at session-end. Each fire + // destroyed the Trace instance; the next event in a later turn forced a fresh + // Trace.create() whose 1-span initial snapshot clobbered the rich on-disk + // trace. Also explains the "What was asked / No prompt recorded" symptom — + // metadata.prompt was captured on the destroyed instance, never on the + // replacement. The handler is now a no-op; finalization happens on worker + // shutdown and MAX_TRACES eviction only. + test("worker does NOT call endTrace+delete on session.status=idle", async () => { + const workerSrc = await fs.readFile(path.join(ROOT, "src/cli/cmd/tui/worker.ts"), "utf-8") + + // The destructive shape must not exist anywhere in the file. + expect(workerSrc).not.toMatch(/status === "idle"[\s\S]{0,200}sessionTraces\.delete/) + expect(workerSrc).not.toMatch(/status === "idle"[\s\S]{0,200}trace\.endTrace\(\)/) + }) + + // Defense-in-depth: `getOrCreateTrace` on cache miss must try to load an + // existing on-disk trace before falling back to startTrace. Otherwise a + // worker restart or MAX_TRACES eviction recreates the trace empty and + // the next snapshot clobbers the rich file. + test("getOrCreateTrace prefers rehydrateFromFile over startTrace on cache miss", async () => { + const workerSrc = await fs.readFile(path.join(ROOT, "src/cli/cmd/tui/worker.ts"), "utf-8") + expect(workerSrc).toMatch( + /if \(!trace\.rehydrateFromFile\(sessionID\)\)\s*\{\s*\n\s*trace\.startTrace\(sessionID, \{\}\)\s*\n\s*\}/, + ) + }) }) From 12ad175d15cdfb4c6e45ae3ad2547892728cfda7 Mon Sep 17 00:00:00 2001 From: Haider Date: Fri, 5 Jun 2026 20:29:49 +0530 Subject: [PATCH 03/12] fix(tracing): capture user prompt via setPrompt; drop time.end gate MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Per codex review (2026-06-05): the previous user-text branch in worker.ts gated on `part.time?.end` (which user-input parts never have set) AND called `trace.setTitle(text, text)` which would have regressed the auto-generated session title from Path C (`session.updated`) back to the raw user input ('Greeting' → 'hi') if the ordering went sideways. * New `Trace.setPrompt(prompt)` method that only mutates `metadata.prompt`. Decouples prompt capture from title mutation. * Path B in worker.ts now: (a) accepts user text parts without `part.time?.end` (it's an assistant-side concept only); (b) calls `setPrompt(text)` only — never `setTitle` — for user-identified messages. Assistant text still requires `time.end` for `logText`. * Source-grep regression tests lock both contracts: no more `part.time?.end` on the user branch, no `setTitle` from the user branch, `setPrompt` exists and doesn't touch title. --- .../src/altimate/observability/tracing.ts | 12 +++++++ packages/opencode/src/cli/cmd/tui/worker.ts | 17 +++++++--- .../cli/tui/worker-trace-clearing.test.ts | 33 +++++++++++++++++++ 3 files changed, 57 insertions(+), 5 deletions(-) diff --git a/packages/opencode/src/altimate/observability/tracing.ts b/packages/opencode/src/altimate/observability/tracing.ts index fcd67525fb..6f5f1d41a9 100644 --- a/packages/opencode/src/altimate/observability/tracing.ts +++ b/packages/opencode/src/altimate/observability/tracing.ts @@ -579,6 +579,18 @@ export class Trace { if (prompt) this.metadata.prompt = prompt } + // altimate_change start — set only the user prompt without mutating title. + // The bus emits an auto-generated session title (Path C, `session.updated`) + // separately from the user's actual prompt text (Path B, `message.part.updated`). + // Capturing the prompt via `setTitle(text, text)` would race the title-agent: + // if the user text part arrived after `session.updated`, the nice generated + // title ("Greeting") would regress to the raw user input ("hi"). Use this + // method for prompt-only capture. + setPrompt(prompt: string) { + if (prompt) this.metadata.prompt = prompt + } + // altimate_change end + /** * Open a generation span from a step-start event. */ diff --git a/packages/opencode/src/cli/cmd/tui/worker.ts b/packages/opencode/src/cli/cmd/tui/worker.ts index c83b0def91..5881b8a0b8 100644 --- a/packages/opencode/src/cli/cmd/tui/worker.ts +++ b/packages/opencode/src/cli/cmd/tui/worker.ts @@ -211,16 +211,23 @@ const startEventStream = (input: { directory: string; workspaceID?: string }) => if (trace) { if (part.type === "step-start") trace.logStepStart(part) if (part.type === "step-finish") trace.logStepFinish(part) - if (part.type === "text" && part.time?.end) { + // altimate_change start — split the user-vs-assistant text routes. + // User text parts arrive without `time.end` set (it's a meaningful + // concept only for processing-end of assistant chunks), so the old + // `&& part.time?.end` gate dropped the prompt entirely. We trust + // `sessionUserMsgIds.has(messageID)` as the user-text signal and + // call `setPrompt(text)` only — never `setTitle` — to avoid racing + // the auto-generated title from `session.updated` (Path C). + if (part.type === "text") { if (part.messageID && sessionUserMsgIds.get(part.sessionID)?.has(part.messageID)) { - // This is user prompt text — capture as title/prompt const text = String(part.text || "") - if (text) trace.setTitle(text.slice(0, 80), text) - } else { - // This is assistant response text + if (text) trace.setPrompt(text) + } else if (part.time?.end) { + // Assistant response text (only counts when processing-end fires) trace.logText(part) } } + // altimate_change end if (part.type === "tool" && (part.state?.status === "completed" || part.state?.status === "error")) { trace.logToolCall(part) } diff --git a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts index d2f306138d..516f95d184 100644 --- a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts +++ b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts @@ -94,4 +94,37 @@ describe("trace-clearing-on-workspace-set regression", () => { /if \(!trace\.rehydrateFromFile\(sessionID\)\)\s*\{\s*\n\s*trace\.startTrace\(sessionID, \{\}\)\s*\n\s*\}/, ) }) + + // User-text-part branch must accept parts that have no `time.end` (user input + // never has a meaningful processing-end) and must capture the prompt via + // `setPrompt` — NOT `setTitle`. Otherwise the user text races the + // title-agent's auto-generated title from `session.updated` and overwrites + // it (e.g. "Greeting" → "hi"). See codex review feedback this round. + test("user text part is captured via setPrompt, drops time.end precondition, never touches title", async () => { + const workerSrc = await fs.readFile(path.join(ROOT, "src/cli/cmd/tui/worker.ts"), "utf-8") + + // The old shape gated on `part.time?.end` for the entire user/assistant + // branch — that shape must not be present anymore, because user-input + // parts never have `time.end` set. + expect(workerSrc).not.toMatch(/if \(part\.type === "text" && part\.time\?\.end\)/) + + // The user-text branch must call setPrompt (not setTitle) so the auto- + // generated session title from Path C isn't overwritten by raw user text. + expect(workerSrc).toMatch(/sessionUserMsgIds\.get\(part\.sessionID\)\?\.has\(part\.messageID\)[\s\S]{0,200}trace\.setPrompt/) + // The user-text branch must NOT call setTitle. + expect(workerSrc).not.toMatch( + /sessionUserMsgIds\.get\(part\.sessionID\)\?\.has\(part\.messageID\)[\s\S]{0,200}trace\.setTitle\(text/, + ) + }) + + test("Trace.setPrompt exists and only mutates metadata.prompt", async () => { + const tracingSrc = await fs.readFile( + path.join(ROOT, "src/altimate/observability/tracing.ts"), + "utf-8", + ) + // Method must exist with the documented signature. + expect(tracingSrc).toMatch(/setPrompt\(prompt: string\)\s*\{[\s\S]{0,200}this\.metadata\.prompt = prompt/) + // Must NOT touch metadata.title. + expect(tracingSrc).not.toMatch(/setPrompt\(prompt: string\)\s*\{[\s\S]{0,300}this\.metadata\.title/) + }) }) From b86ecb4ac392afdf1a3d6a345abb1b71a877af01 Mon Sep 17 00:00:00 2001 From: Haider Date: Fri, 5 Jun 2026 20:42:36 +0530 Subject: [PATCH 04/12] fix(tracing): record user messages as spans so chat tab renders multi-turn MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The chat tab in the trace viewer renders 'metadata.prompt' as a single 'You' bubble at the top, then iterates 'kind: generation' spans for assistant replies. There's no place for any user message beyond the first to land — `setPrompt` overwrites on every call, and the viewer only reads the latest value. Symptom: a 3-turn session shows only the LAST user prompt followed by all earlier assistant responses, with the older user messages dropped. Fix splits the data and the rendering: * New `Trace.logUserMessage(text)` pushes a `kind: 'user-message'` span with the user text as input. Snapshots immediately like other log* methods. * New 'user-message' variant added to the TraceSpan.kind union. * worker.ts Path B: now also calls `logUserMessage(text)` alongside `setPrompt(text)` for user-identified text parts (the first one populates metadata.prompt for the Summary tab; all of them populate per-turn spans for the Chat tab). * viewer.ts chat-view: builds a chronologically sorted list of user-message + generation spans and walks it in startTime order. Older traces without user-message spans fall back to rendering metadata.prompt as before. * Behavioral test in tracing-rehydrate.test.ts proves the spans are written, ordered chronologically, and preserve the user text. 10 unit tests in worker-trace-clearing + 8 in tracing-rehydrate pass; 35 existing tracing tests pass unchanged; typecheck clean. --- .../src/altimate/observability/tracing.ts | 29 ++++++++++++++++++- .../src/altimate/observability/viewer.ts | 24 ++++++++++++--- packages/opencode/src/cli/cmd/tui/worker.ts | 11 ++++++- .../test/altimate/tracing-rehydrate.test.ts | 26 +++++++++++++++++ 4 files changed, 84 insertions(+), 6 deletions(-) diff --git a/packages/opencode/src/altimate/observability/tracing.ts b/packages/opencode/src/altimate/observability/tracing.ts index 6f5f1d41a9..5c7c8a237a 100644 --- a/packages/opencode/src/altimate/observability/tracing.ts +++ b/packages/opencode/src/altimate/observability/tracing.ts @@ -42,7 +42,7 @@ export interface TraceSpan { spanId: string parentSpanId: string | null name: string - kind: "session" | "generation" | "tool" | "text" | "span" + kind: "session" | "generation" | "tool" | "text" | "span" | "user-message" startTime: number endTime?: number status: "ok" | "error" @@ -591,6 +591,33 @@ export class Trace { } // altimate_change end + // altimate_change start — record an individual user message as a span so the + // chat tab can render multi-turn conversations. Without this, the viewer's + // chat tab can only display `metadata.prompt` at the top — a single string — + // and every later user message is silently dropped from the conversation + // rendering. Tracked as `kind: "user-message"` so the viewer can interleave + // these with `kind: "generation"` spans by startTime. + logUserMessage(text: string) { + if (!this.rootSpanId) return + if (!text) return + try { + this.spans.push({ + spanId: randomUUIDv7(), + parentSpanId: this.rootSpanId, + name: "user-message", + kind: "user-message", + startTime: Date.now(), + endTime: Date.now(), + status: "ok", + input: text.slice(0, 4000), + }) + this.snapshot() + } catch { + // best-effort + } + } + // altimate_change end + /** * Open a generation span from a step-start event. */ diff --git a/packages/opencode/src/altimate/observability/viewer.ts b/packages/opencode/src/altimate/observability/viewer.ts index eb8f5918d0..c442d71138 100644 --- a/packages/opencode/src/altimate/observability/viewer.ts +++ b/packages/opencode/src/altimate/observability/viewer.ts @@ -1310,13 +1310,29 @@ function showDetail(span) { (function() { var el = document.getElementById('v-chat'); var html = ''; - if (t.metadata.prompt) { + // Build a chronologically sorted list of conversation turns by interleaving + // user-message spans with generation spans. Older traces (no user-message + // spans) fall back to rendering metadata.prompt at the top as a single "You" + // bubble. Once user-message spans are present, we prefer those and skip + // metadata.prompt to avoid double-rendering the first turn. + var userMsgs = spans.filter(function(s){return s.kind==='user-message';}); + var gens = spans.filter(function(s){return s.kind==='generation';}); + if (userMsgs.length === 0 && t.metadata.prompt) { html += '
\\u25B6 You
'; html += '
' + e(t.metadata.prompt) + '
'; } - var gens = spans.filter(function(s){return s.kind==='generation';}); - gens.forEach(function(gen) { - var tools = spans.filter(function(s){return s.parentSpanId===gen.spanId && s.kind==='tool';}); + var turns = userMsgs.concat(gens).sort(function(a, b) { return (a.startTime||0) - (b.startTime||0); }); + turns.forEach(function(s) { + if (s.kind === 'user-message') { + var utxt = typeof s.input === 'string' ? s.input : (s.input != null ? JSON.stringify(s.input) : ''); + if (!utxt) return; + html += '
\\u25B6 You
'; + html += '
' + e(utxt) + '
'; + return; + } + // Generation: render its tool children first, then the agent response. + var gen = s; + var tools = spans.filter(function(c){return c.parentSpanId===gen.spanId && c.kind==='tool';}); if (tools.length) { tools.forEach(function(tool) { html += '
'; diff --git a/packages/opencode/src/cli/cmd/tui/worker.ts b/packages/opencode/src/cli/cmd/tui/worker.ts index 5881b8a0b8..d29202d25e 100644 --- a/packages/opencode/src/cli/cmd/tui/worker.ts +++ b/packages/opencode/src/cli/cmd/tui/worker.ts @@ -221,7 +221,16 @@ const startEventStream = (input: { directory: string; workspaceID?: string }) => if (part.type === "text") { if (part.messageID && sessionUserMsgIds.get(part.sessionID)?.has(part.messageID)) { const text = String(part.text || "") - if (text) trace.setPrompt(text) + if (text) { + trace.setPrompt(text) + // altimate_change start — record each user message as a span + // so the chat tab can render multi-turn conversations. + // Without a span, the viewer can only display `metadata.prompt` + // (singular) and every subsequent user message is silently + // dropped from the conversation rendering. + trace.logUserMessage(text) + // altimate_change end + } } else if (part.time?.end) { // Assistant response text (only counts when processing-end fires) trace.logText(part) diff --git a/packages/opencode/test/altimate/tracing-rehydrate.test.ts b/packages/opencode/test/altimate/tracing-rehydrate.test.ts index 5a2bd4a38d..fa495b112d 100644 --- a/packages/opencode/test/altimate/tracing-rehydrate.test.ts +++ b/packages/opencode/test/altimate/tracing-rehydrate.test.ts @@ -132,6 +132,32 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { expect(result).toBe(false) }) + test("logUserMessage records each user turn as a span so the chat tab can interleave them", async () => { + const sessionId = "ses_user_messages" + + const trace = makeTrace() + trace.startTrace(sessionId, {}) + trace.logUserMessage("first user message") + trace.logToolCall({ tool: "read", state: { status: "completed", input: { f: "a" } } } as any) + trace.logUserMessage("second user message") + trace.logToolCall({ tool: "grep", state: { status: "completed", input: { p: "x" } } } as any) + trace.logUserMessage("third user message") + await trace.flush() + + const fileContent = await readTraceFile(sessionId) + const userMessages = fileContent.spans.filter((s) => s.kind === "user-message") + expect(userMessages).toHaveLength(3) + expect((userMessages[0] as any).input).toBe("first user message") + expect((userMessages[1] as any).input).toBe("second user message") + expect((userMessages[2] as any).input).toBe("third user message") + + // Chronological order — user-message spans must precede each generation/tool + // span that came after them, so the chat tab renders them in turn order. + const allSpans = fileContent.spans + const sortedByStart = [...allSpans].sort((a, b) => (a.startTime || 0) - (b.startTime || 0)) + expect(sortedByStart).toEqual(allSpans) + }) + test("rehydrate clears endTime on the root span so the trace renders as still in-progress", async () => { const sessionId = "ses_endtime_clear" From ec0d877ae449bb339bb71eddcaae944729b71914 Mon Sep 17 00:00:00 2001 From: Haider Date: Fri, 5 Jun 2026 21:13:33 +0530 Subject: [PATCH 05/12] =?UTF-8?q?docs:=20trace-bugs=20followup=20to=20#867?= =?UTF-8?q?=20=E2=80=94=20what=20this=20branch=20actually=20fixes?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../opencode/specs/trace-bugs-followup-867.md | 295 ++++++++++++++++++ 1 file changed, 295 insertions(+) create mode 100644 packages/opencode/specs/trace-bugs-followup-867.md diff --git a/packages/opencode/specs/trace-bugs-followup-867.md b/packages/opencode/specs/trace-bugs-followup-867.md new file mode 100644 index 0000000000..4c5bdcba0f --- /dev/null +++ b/packages/opencode/specs/trace-bugs-followup-867.md @@ -0,0 +1,295 @@ +# Trace bugs — what this branch fixes and why #867 didn't catch them + +Companion document to the `fix/trace-clearing-on-workspace-set` branch. +Lists the actual bugs found and fixed; excludes the diagnostic dead-ends +that didn't pan out. + +## Bugs fixed in this branch + +### 1. Per-turn `session.status === "idle"` finalized the trace every turn + +**Location**: `packages/opencode/src/cli/cmd/tui/worker.ts:232-243` (removed in this branch) + +**Mechanism**: the handler called `trace.endTrace()` + `sessionTraces.delete(sid)` +whenever `event.type === "session.status"` and `status.type === "idle"`. +`idle` is a **busy→idle transition** — it fires after every agent turn +finishes, not at session end. Every fire destroyed the Trace instance +and removed it from the cache. The next event for the same session in +the next turn hit a cache miss in `getOrCreateTrace`, called +`Trace.create()` + `startTrace(sessionID, {})`, which pushed a single +root span into a freshly-empty `this.spans` and the immediate `snapshot()` +clobbered the rich on-disk `ses_.json` with a 1-span file. + +**Symptom**: +- Waterfall view collapsed to the system-prompt span after every turn +- `metadata.prompt` reset to undefined ("What was asked / No prompt + recorded") +- Token / generation / tool-call counters in `summary` reset to 0/null + +**Severity**: hot path on every multi-turn session. Fired ~once per +agent turn for every session in the cache. + +**Why the comment in the code was misleading**: the original handler +carried the comment "Finalize trace when session reaches idle +(completed)" — the developer who wrote it conflated `idle` (per-turn +event) with session-end. Sessions in altimate-code are long-lived +across many turns; finalization belongs on `shutdown` or eviction, not +per-turn idle. + +**Fix**: handler removed. Trace lives as long as the worker has the +session in its `sessionTraces` map. Finalization happens only on +`worker.shutdown` and on MAX_TRACES eviction — both already correct. + +### 2. `getOrCreateTrace` cache-miss never rehydrated from disk + +**Location**: `packages/opencode/src/cli/cmd/tui/worker.ts:83-106`, +`packages/opencode/src/altimate/observability/tracing.ts` +(`rehydrateFromFile`, new method) + +**Mechanism**: when `sessionTraces.has(sessionID)` returned false, the +worker called `Trace.create()` + `startTrace(sessionID, {})` — which +unconditionally pushed a fresh root span into empty `this.spans` and +wrote a snapshot. The on-disk path is derived purely from `sessionID`, +so the snapshot clobbered any pre-existing rich trace at that path. + +**Triggered when**: +- Worker process restart (sessionTraces empty on boot, user resumes + a session whose trace file already has content) +- MAX_TRACES=100 eviction (the evicted session may be revisited later) +- Any future code path that drops in-memory state for an active session + +After fix #1, these are uncommon — but still real edge cases. + +**Fix**: new `Trace.rehydrateFromFile(sessionId)` reads +`~/.local/share/altimate-code/traces/ses_.json` if it exists, +parses it, restores `this.spans`, `this.metadata`, `this.rootSpanId`, +`this.startTime`, and the running counters (`totalTokens`, +`toolCallCount`, `generationCount`, token breakdown). Clears the root +span's `endTime` so the trace renders as still-in-progress and accepts +new events. `getOrCreateTrace` now prefers rehydration over +`startTrace`; falls back to `startTrace` only when no usable on-disk +file is found. + +### 3. `worker.setWorkspace` was not idempotent + +**Location**: `packages/opencode/src/cli/cmd/tui/worker.ts:308-313` + +**Mechanism**: each call unconditionally invoked `startEventStream`, +which called `endTrace()` on every entry in `sessionTraces` (fire-and- +forget) and then `sessionTraces.clear()`. Combined with the SolidJS +effect upstream (see #4), this meant every spurious effect re-run +destroyed the entire trace cache. + +**Fix**: track `currentWorkspaceID` at module scope; early-return when +`input.workspaceID === currentWorkspaceID`. Defense in depth against the +upstream UI sending spurious calls. + +### 4. SolidJS effect on workspaceID re-ran on every session signal change + +**Location**: `packages/opencode/src/cli/cmd/tui/routes/session/index.tsx:186-190` + +**Mechanism**: `createEffect(() => session()?.workspaceID && sdk.setWorkspace(...))` +reads `session()` inside the effect — SolidJS dirty-tracks the entire +session signal, not the projected `workspaceID`. So the effect re-ran +on every `session()` update (message count, status, parts updated, +title regenerated, …). Each fire propagated into the worker's +`setWorkspace`. + +**Fix**: switched to `createEffect(on(() => session()?.workspaceID, ...))`. +The `on()` projector restricts dirty-tracking to that one field, so +the effect only fires when `workspaceID` actually changes. + +### 5. User prompt was never captured + +**Location**: `packages/opencode/src/cli/cmd/tui/worker.ts` (Path B in +the `message.part.updated` handler) + +**Mechanism**: three different code paths fed `metadata.prompt`: + +- **Path A** (`message.updated` for user role): only fired if + `info.summary?.title || info.summary?.body` was populated — i.e. + only after the title-agent had run. For a first turn, summary is + empty when the event arrives. Doesn't fire. +- **Path B** (`message.part.updated` text part): gated on + `part.type === "text" && part.time?.end`. **User-input parts never + have `time.end` set** — it's a meaningful concept only for + processing-end of assistant chunks. Gate never opens for user text. +- **Path C** (`session.updated` with auto-generated title): called + `trace.setTitle(String(info.title))` with **one argument only** — + set the title but not the prompt. + +Result: title got captured (via Path C, with the auto-generated +"Greeting"-style title), prompt stayed `undefined`. Viewer shows +"What was asked / No prompt recorded". + +**Codex review feedback (2026-06-05)**: even if we drop the `time.end` +gate in Path B, calling `trace.setTitle(text, text)` mutates **both** +title and prompt. If Path B fires after Path C, the nice auto- +generated title regresses to raw user input ("Greeting" → "hi"). The +right fix decouples title mutation from prompt capture. + +**Fix**: +- New `Trace.setPrompt(prompt)` method on the Trace class. Only + mutates `metadata.prompt`. Never touches title. +- Path B in `worker.ts`: dropped `part.time?.end` for the user- + identified branch; calls `setPrompt(text)` instead of + `setTitle(text, text)`. Assistant-text branch still requires + `time.end` for `logText`. + +### 6. User messages were not first-class events in the trace data model + +**Location**: trace data model (no `kind: "user-message"` span before +this branch), `viewer.ts` chat-view renderer + +**Mechanism**: the trace recorded user input only as a single +`metadata.prompt` string. Each new `setPrompt` overwrote the previous +value. The viewer's chat tab rendered `metadata.prompt` as one +"▶ You" bubble at the top, then iterated `kind: "generation"` spans +for assistant replies. There was no place for any user message +beyond the first. + +**Symptom on a 3-turn session**: chat tab showed the **last** user +prompt followed by **all** earlier assistant responses, with the older +user messages dropped. + +**Fix**: +- New `Trace.logUserMessage(text)` pushes a `kind: "user-message"` + span. `TraceSpan.kind` union extended. +- Worker Path B calls `logUserMessage(text)` alongside `setPrompt(text)` + for each user-identified part. +- Viewer chat-view rebuilt: filters both user-message and generation + spans, sorts by `startTime`, walks them in turn order. Renders each + user-message span as its own "▶ You" bubble. Older traces without + user-message spans fall back to `metadata.prompt`-at-top — + backward compatible. + +--- + +## What PR #867 fixed (for comparison) + +PR #867 (merged 2026-06-01, "fix(tracing): close trace corruption in +long-running sessions") closed two concurrency bugs and explicitly +left a third as a documented design hazard: + +### M2 — debounce dropped events with no follow-up snapshot + +`Trace.snapshot()` returned early when `snapshotPending=true` and was +never re-scheduled. In bursty turns (an LLM step firing several tool +calls back-to-back), the disk file lagged memory until a fresh event +arrived in a future turn. If the process exited in the gap, the burst's +tail was lost. + +**Fix**: `snapshotRequestedDuringPending` flag whenever `snapshot()` +short-circuits. In `.finally()`, if the flag is set and the trace is +neither crashed nor ending, schedule exactly one follow-up snapshot +via `queueMicrotask`. Bounded — at most one extra write per +"burst → quiet" cycle regardless of burst size. + +### M3 — `FileExporter.export()` raced `flushSync` with no `crashed` guard + +`endTrace()` calls `exporter.export()`, which does `writeFile(tmp)` +→ `rename(tmp, final)`. On multi-MB traces the writeFile takes 100+ms, +a wide window for `flushSync` to interleave. The `crashed` flag added +in commit `38463876b` only guarded `Trace.snapshot()`, not +`FileExporter.export()`, so `flushSync`'s synchronous crashed write +was overwritten by the export's rename. + +**Fix**: per-session `_crashed` flag on `FileExporter` with +`markCrashed()`. Checked at entry, before writeFile, and before rename +(drop tmp + bail). `flushSync` iterates exporters and calls +`markCrashed()` on each before its own synchronous write. + +### M2 companion — `endTraceStarted` gate + +Once `endTrace()` claims the canonical write, no concurrent snapshot +may run — they would race endTrace's mutation of the root span +(endTime, status) and could clobber endTrace's content with stale +pre-end state. + +### M1 — NOT closed in #867 + +The TOCTOU between the synchronous `if (this.crashed)` check and the +asynchronous kernel `fs.rename` syscall. Documented as a known design +hazard; existing `crashed` flag from `38463876b` protects against it +on local SSD (microsecond rename window). Theoretical exposure remains +on slow/network filesystems. + +--- + +## Why #867 didn't catch the bugs in this branch + +### Different layer of abstraction + +PR #867's bugs all live at the **intra-Trace-instance concurrency +layer** — within one Trace object's state machine: + +- Snapshot debounce/follow-up timing within one instance +- FileExporter ↔ flushSync interleave for one instance's write +- endTrace ↔ snapshot races for one instance + +This branch's bugs (#1, #2, #3, #4) all live at the **cross-instance +lifecycle layer** — when one Trace instance gets destroyed and another +is constructed for the same `sessionID`: + +- When destruction happens (idle handler / setWorkspace / cache eviction) +- What happens on the next `Trace.create()` (no disk rehydration) +- What the upstream UI triggers cause it (SolidJS effect) + +The two layers are orthogonal. #867's reproducers (`tracing-rename-race.test.ts`, +`tracing-display-crash.test.ts`) all hold one Trace instance for their +entire test lifecycle and exercise crash/burst conditions against +that instance. They cannot detect a bug whose mechanism is "destroy +the instance, build a new one, watch the new one's first write +clobber the old one's file." + +### The destructive handler was intentional code, not a concurrency bug + +The per-turn idle handler (#1) was **the developer's intent** — they +explicitly named it "Finalize trace when session reaches idle +(completed)". The bug is a semantic misunderstanding of what `idle` +means at the event level (per-turn vs per-session), not a race or +data corruption. #867's reproducer matrix wouldn't have surfaced it +because none of the M-class bugs involved destroying the Trace and +the reproducers all assumed a single instance. + +### Data-feed and rendering layers were out of scope + +#867 worked on the **persistence layer** (FileExporter, snapshot, +flushSync). The prompt-capture and chat-rendering bugs (#5, #6) live +at: + +- **Worker event-handler layer** (`worker.ts`) — what gets fed into + the Trace from the bus event stream +- **Trace data-model layer** (`tracing.ts`) — what fields and span + kinds the Trace exposes +- **Viewer layer** (`viewer.ts`) — how rendered HTML iterates spans + +All three are independent of crash/race safety. A 100%-correct +persistence layer can still ship a 1-span trace file if upstream +feeds only 1 span, or render a single "You" bubble if the data model +only carries `metadata.prompt`. + +### No cross-turn integration tests + +Existing tracing tests are concurrency reproducers and unit tests of +isolated methods. None exercise the full event-stream-to-trace-file +path for a multi-turn session. The cross-turn nature of the idle +clobber requires a test that drives at least two `busy → idle` cycles +through the worker's event handler against a real `Trace` instance. + +This branch adds: + +- `test/cli/tui/worker-trace-clearing.test.ts` — source-grep contract + tests that lock the no-idle-clobber, rehydrate-before-startTrace, + and `setPrompt`-not-`setTitle` invariants in worker.ts. +- `test/altimate/tracing-rehydrate.test.ts` — behavioral tests for + `Trace.rehydrateFromFile` (preserve spans/metadata/counters, + reject missing/mismatched/malformed files, clear endTime on + rehydrate) and for `logUserMessage` (chronological ordering). + +A higher-fidelity follow-up would be a real-worker integration test +that emits a synthetic `session.status` idle event between two turns +and asserts the trace file does not collapse — that needs the worker +event loop running against a stub bus. Worth adding as a separate +PR; the source-grep + behavioral tests are sufficient to lock the +contracts in this PR. From 38e0caed5567f1aa285a7bc683631395e3900f88 Mon Sep 17 00:00:00 2001 From: Haider Date: Fri, 5 Jun 2026 23:11:48 +0530 Subject: [PATCH 06/12] fix(tracing): address PR #895 bot review feedback MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * Trace.rehydrateFromFile (cubic P2): restore traceId from the on-disk file so post-rehydrate snapshots/exports preserve trace identity across instance lifetimes. Without this, every snapshot after rehydration writes a fresh random traceId. * Trace.rehydrateFromFile (cubic P2): normalize sessionId via the same sanitization buildTraceFile applies before comparing to trace.sessionId. Previously, sessions with /, \, ., or : in the id would be falsely rejected and recreated. * viewer chat-view (cubic P2): always render metadata.prompt at the top unless an existing user-message span carries the same text. Pre-fix traces (only metadata.prompt) and mixed traces (rehydrated pre-fix data + new turns) now render the first user turn correctly. Previously, the fallback was gated on userMsgs.length === 0 and dropped the legacy first turn in mixed traces. * worker-trace-clearing.test.ts (CodeRabbit, cubic P3): broaden the negative regression guards to catch all three flagged bug spellings — inline expression, inline ternary, block body with if — for the workspaceID effect; and to reject part.time?.end nested inside the user-text branch (identified by sessionUserMsgIds.get(...).has(...)). * routes/session/index.tsx: paraphrased the bug-shape literal that was in a comment so the broadened test regex doesn't catch our own documentation as the bug. * tracing-rehydrate.test.ts: behavioral tests for the traceId preservation and sanitized-sessionId match. Skipped CodeRabbit's tmpdir-fixture-style suggestion — the convention isn't followed by the existing tracing tests (tracing-display-crash, tracing-rename-race) so changing this one file alone would be inconsistent and out of scope for this PR. 48 affected tests pass; typecheck clean. --- .../src/altimate/observability/tracing.ts | 18 +++++- .../src/altimate/observability/viewer.ts | 24 +++++--- .../src/cli/cmd/tui/routes/session/index.tsx | 13 ++-- .../test/altimate/tracing-rehydrate.test.ts | 59 +++++++++++++++++++ .../cli/tui/worker-trace-clearing.test.ts | 20 ++++++- 5 files changed, 118 insertions(+), 16 deletions(-) diff --git a/packages/opencode/src/altimate/observability/tracing.ts b/packages/opencode/src/altimate/observability/tracing.ts index 5c7c8a237a..777ad39954 100644 --- a/packages/opencode/src/altimate/observability/tracing.ts +++ b/packages/opencode/src/altimate/observability/tracing.ts @@ -516,13 +516,29 @@ export class Trace { } catch { return false } - if (!trace || trace.sessionId !== sessionId || !Array.isArray(trace.spans) || trace.spans.length === 0) { + // `buildTraceFile` writes the sanitized form of `sessionId` (see ~line 808 + // `.replace(/[/\\.:]/g, "_")`), so compare the same way — otherwise valid + // trace files with `/`, `\`, `.`, `:` in the session id would be rejected + // and the caller would fall back to `startTrace`, clobbering them. + const normalizedSessionId = sessionId.replace(/[/\\.:]/g, "_") || "unknown" + if ( + !trace || + trace.sessionId !== normalizedSessionId || + !Array.isArray(trace.spans) || + trace.spans.length === 0 + ) { return false } const root = trace.spans.find((s) => s.parentSpanId === null && s.kind === "session") if (!root) return false this.sessionId = sessionId + // Restore the original traceId so post-rehydrate snapshots/exports keep + // the same trace identity (downstream OTLP/Jaeger-style consumers and the + // trace viewer URL both depend on it being stable across rehydration). + if (typeof trace.traceId === "string" && trace.traceId.length > 0) { + this.traceId = trace.traceId + } this.spans = trace.spans.map((s) => ({ ...s })) this.rootSpanId = root.spanId this.metadata = { ...(trace.metadata ?? {}) } diff --git a/packages/opencode/src/altimate/observability/viewer.ts b/packages/opencode/src/altimate/observability/viewer.ts index c442d71138..d2b611cc47 100644 --- a/packages/opencode/src/altimate/observability/viewer.ts +++ b/packages/opencode/src/altimate/observability/viewer.ts @@ -1311,15 +1311,25 @@ function showDetail(span) { var el = document.getElementById('v-chat'); var html = ''; // Build a chronologically sorted list of conversation turns by interleaving - // user-message spans with generation spans. Older traces (no user-message - // spans) fall back to rendering metadata.prompt at the top as a single "You" - // bubble. Once user-message spans are present, we prefer those and skip - // metadata.prompt to avoid double-rendering the first turn. + // user-message spans with generation spans. We render \`metadata.prompt\` at + // the top as a fallback whenever it carries a value not already represented + // by a user-message span — that covers three cases: + // 1. Pre-fix traces with no user-message spans (just the legacy prompt). + // 2. Mixed traces: an older session rehydrated with only metadata.prompt, + // then continued under the new code which added user-message spans for + // later turns. Without this, the legacy first turn would be dropped. + // 3. Brand-new traces where the first user-message span input equals + // metadata.prompt — we skip the duplicate to avoid double-rendering. var userMsgs = spans.filter(function(s){return s.kind==='user-message';}); var gens = spans.filter(function(s){return s.kind==='generation';}); - if (userMsgs.length === 0 && t.metadata.prompt) { - html += '
\\u25B6 You
'; - html += '
' + e(t.metadata.prompt) + '
'; + if (t.metadata.prompt) { + var promptAlreadyInSpan = userMsgs.some(function(u){ + return typeof u.input === 'string' && u.input === t.metadata.prompt; + }); + if (!promptAlreadyInSpan) { + html += '
\\u25B6 You
'; + html += '
' + e(t.metadata.prompt) + '
'; + } } var turns = userMsgs.concat(gens).sort(function(a, b) { return (a.startTime||0) - (b.startTime||0); }); turns.forEach(function(s) { diff --git a/packages/opencode/src/cli/cmd/tui/routes/session/index.tsx b/packages/opencode/src/cli/cmd/tui/routes/session/index.tsx index a63ddb2c94..d86e7b7409 100644 --- a/packages/opencode/src/cli/cmd/tui/routes/session/index.tsx +++ b/packages/opencode/src/cli/cmd/tui/routes/session/index.tsx @@ -184,13 +184,14 @@ export function Session() { }) // altimate_change start — gate setWorkspace on actual workspaceID change. - // Plain `createEffect(() => session()?.workspaceID && sdk.setWorkspace(...))` - // re-fires whenever any field on the session signal changes (message count, - // status, parts) — including the cascade of updates at agent-finish. Every - // spurious fire propagates into `worker.setWorkspace` → `startEventStream` → + // A plain inline `createEffect` callback that reads the session signal would + // re-fire whenever ANY field on the signal changes (message count, status, + // parts) — including the cascade of updates at agent-finish. Every spurious + // fire propagates into `worker.setWorkspace` → `startEventStream` → // `sessionTraces.clear()` → next snapshot overwrites the rich on-disk trace - // with a near-empty one. `on()` here restricts the effect to fire only when - // the projected `workspaceID` value actually changes. + // with a near-empty one. The `on()` projector below restricts SolidJS dirty- + // tracking to the workspaceID value alone, so the effect only fires when + // that field actually changes. createEffect( on( () => session()?.workspaceID, diff --git a/packages/opencode/test/altimate/tracing-rehydrate.test.ts b/packages/opencode/test/altimate/tracing-rehydrate.test.ts index fa495b112d..92366c50eb 100644 --- a/packages/opencode/test/altimate/tracing-rehydrate.test.ts +++ b/packages/opencode/test/altimate/tracing-rehydrate.test.ts @@ -104,6 +104,65 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { expect(result).toBe(false) }) + test("rehydrate preserves traceId across instance reconstruction", async () => { + // Without this, downstream trace consumers (viewer URL, OTLP exporters) + // see a different traceId on every snapshot after rehydration — breaks + // trace identity across instance lifetimes. + const sessionId = "ses_traceid_preservation" + const original = makeTrace() + original.startTrace(sessionId, {}) + original.logToolCall({ tool: "read", state: { status: "completed", input: { f: "a" } } } as any) + await original.flush() + const beforeFile = await readTraceFile(sessionId) + const originalTraceId = beforeFile.traceId + expect(typeof originalTraceId).toBe("string") + + const reconstructed = makeTrace() + expect(reconstructed.rehydrateFromFile(sessionId)).toBe(true) + reconstructed.logToolCall({ tool: "grep", state: { status: "completed", input: { p: "x" } } } as any) + await reconstructed.flush() + const afterFile = await readTraceFile(sessionId) + expect(afterFile.traceId).toBe(originalTraceId) + }) + + test("rehydrate matches sessionIds containing sanitized characters", async () => { + // `buildTraceFile` writes the sanitized form (slashes/dots/colons → "_"). + // The match check needs to normalize before comparing, otherwise valid + // files would be rejected for sessions with those characters. + const sessionId = "ses_with/slash.and:colon" + const safeId = sessionId.replace(/[/\\.:]/g, "_") + // Write a valid file at the sanitized path with the sanitized sessionId + // inside (mirrors what buildTraceFile actually does). + await fs.writeFile( + path.join(tmpDir, `${safeId}.json`), + JSON.stringify({ + version: 2, + traceId: "tr_x", + sessionId: safeId, + startedAt: new Date(0).toISOString(), + endedAt: new Date(0).toISOString(), + metadata: {}, + spans: [ + { spanId: "r", parentSpanId: null, name: safeId, kind: "session", startTime: 0, status: "ok" }, + ], + summary: { + totalTokens: 0, + totalCost: 0, + totalToolCalls: 0, + totalGenerations: 0, + duration: 0, + status: "completed", + tokens: { input: 0, output: 0, reasoning: 0, cacheRead: 0, cacheWrite: 0 }, + }, + }), + ) + + const trace = makeTrace() + // Pass the RAW sessionId (with slashes/dots/colons). Pre-fix this would have + // returned false because "ses_with/slash.and:colon" !== "ses_with_slash_and_colon". + expect(trace.rehydrateFromFile(sessionId)).toBe(true) + }) + test("rehydrate returns false when on-disk trace is for a different session", async () => { // Stage a mismatched file at the expected path for "session-A". await fs.writeFile( diff --git a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts index 516f95d184..5d2003b6a4 100644 --- a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts +++ b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts @@ -63,8 +63,16 @@ describe("trace-clearing-on-workspace-set regression", () => { // that value. expect(routeSrc).toMatch(/createEffect\(\s*on\(\s*\(\)\s*=>\s*session\(\)\?\.workspaceID/) - // The unguarded inline form must not reappear — that would re-introduce the bug. - expect(routeSrc).not.toMatch(/createEffect\(\(\)\s*=>\s*\{\s*\n\s*if\s*\(session\(\)\?\.workspaceID\)/) + // Reject the three bug-equivalent spellings the reviewers flagged. Each + // pattern is bounded so it can't span across unrelated createEffect bodies + // elsewhere in the file (the route file has many createEffects). + // + // Inline expression: `createEffect(() => session()?.workspaceID && ...)` + // Inline ternary: `createEffect(() => session()?.workspaceID ? ... : ...)` + expect(routeSrc).not.toMatch(/createEffect\(\s*\(\s*\)\s*=>\s*session\(\)\?\.workspaceID\s*[&?]/) + // Block body with `if (session()?.workspaceID)` — `[^{}]*?` prevents the + // match from crossing into other blocks. + expect(routeSrc).not.toMatch(/createEffect\(\s*\(\s*\)\s*=>\s*\{[^{}]*?if\s*\(session\(\)\?\.workspaceID/) }) // The real root cause: a session.status=idle handler that called endTrace + @@ -108,6 +116,14 @@ describe("trace-clearing-on-workspace-set regression", () => { // parts never have `time.end` set. expect(workerSrc).not.toMatch(/if \(part\.type === "text" && part\.time\?\.end\)/) + // Broader guard: no `part.time?.end` check is permitted INSIDE the + // user-text branch (identified by `sessionUserMsgIds.get(...).has(...)`). + // Catches a nested `if (part.time?.end)` shape that would re-introduce + // the same drop. + expect(workerSrc).not.toMatch( + /sessionUserMsgIds\.get\(part\.sessionID\)\?\.has\(part\.messageID\)[\s\S]{0,400}part\.time\?\.end/, + ) + // The user-text branch must call setPrompt (not setTitle) so the auto- // generated session title from Path C isn't overwritten by raw user text. expect(workerSrc).toMatch(/sessionUserMsgIds\.get\(part\.sessionID\)\?\.has\(part\.messageID\)[\s\S]{0,200}trace\.setPrompt/) From 7bee91372015ee79fe78768c053283c9ec3c25e1 Mon Sep 17 00:00:00 2001 From: Haider Date: Fri, 5 Jun 2026 23:20:23 +0530 Subject: [PATCH 07/12] test(tracing): migrate tracing-rehydrate to tmpdir() fixture MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CodeRabbit pointed out that `packages/opencode/test/AGENTS.md` documents `tmpdir()` from `fixture/fixture.ts` as the project convention. My earlier reply skipped the migration on the grounds that sibling tracing tests don't follow the convention — but for code I'm adding fresh, the right move is to follow the documented standard. The sibling tests predate it and should be swept in a separate cleanup PR. Replaces the manual `os.tmpdir() + beforeEach/afterEach` pattern with `await using tmp = await tmpdir()` per test. Helpers `makeTrace` and `readTraceFile` now take `dir` as a first parameter so each test threads its own tmp directory through. 46 affected tests pass. --- .../test/altimate/tracing-rehydrate.test.ts | 70 +++++++++---------- 1 file changed, 33 insertions(+), 37 deletions(-) diff --git a/packages/opencode/test/altimate/tracing-rehydrate.test.ts b/packages/opencode/test/altimate/tracing-rehydrate.test.ts index 92366c50eb..dfb53aab9f 100644 --- a/packages/opencode/test/altimate/tracing-rehydrate.test.ts +++ b/packages/opencode/test/altimate/tracing-rehydrate.test.ts @@ -14,40 +14,30 @@ * existing trace state instead of starting fresh. */ -import { describe, expect, test, beforeEach, afterEach } from "bun:test" +import { describe, expect, test } from "bun:test" import fs from "fs/promises" import path from "path" -import os from "os" import { Trace, FileExporter, type TraceFile } from "../../src/altimate/observability/tracing" +import { tmpdir } from "../fixture/fixture" -let tmpDir: string - -beforeEach(async () => { - tmpDir = path.join(os.tmpdir(), `tracing-rehydrate-${Date.now()}-${Math.random().toString(36).slice(2)}`) - await fs.mkdir(tmpDir, { recursive: true }) -}) - -afterEach(async () => { - await fs.rm(tmpDir, { recursive: true, force: true }).catch(() => {}) -}) - -function makeTrace() { - return Trace.withExporters([new FileExporter(tmpDir)]) +function makeTrace(dir: string) { + return Trace.withExporters([new FileExporter(dir)]) } -async function readTraceFile(sessionId: string): Promise { +async function readTraceFile(dir: string, sessionId: string): Promise { const safeId = sessionId.replace(/[/\\.:]/g, "_") - const filePath = path.join(tmpDir, `${safeId}.json`) + const filePath = path.join(dir, `${safeId}.json`) return JSON.parse(await fs.readFile(filePath, "utf-8")) } describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { test("rehydrate preserves spans, metadata, and counters when reconstructing on cache miss", async () => { + await using tmp = await tmpdir() const sessionId = "ses_rehydrate_basic" // Phase 1: original Trace builds up rich state, then is discarded (simulating // a worker restart or MAX_TRACES eviction). - const original = makeTrace() + const original = makeTrace(tmp.path) original.startTrace(sessionId, { title: "test session", prompt: "do the thing", @@ -62,7 +52,7 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { // Flush to disk so the file represents the cumulative state. await original.flush() - const onDiskAfterPhase1 = await readTraceFile(sessionId) + const onDiskAfterPhase1 = await readTraceFile(tmp.path, sessionId) expect(onDiskAfterPhase1.spans.length).toBeGreaterThan(1) expect(onDiskAfterPhase1.metadata.prompt).toBe("do the thing") expect(onDiskAfterPhase1.metadata.title).toBe("test session") @@ -70,14 +60,14 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { // Phase 2: drop the original (worker restart / eviction). Construct a fresh // Trace instance for the SAME sessionID. This is the path that, pre-fix, // would have called startTrace and clobbered the file. - const reconstructed = makeTrace() + const reconstructed = makeTrace(tmp.path) const didRehydrate = reconstructed.rehydrateFromFile(sessionId) expect(didRehydrate).toBe(true) // Without writing anything yet, the in-memory state must reflect what was // on disk: same spans, same metadata, same root id. - const fileImmediatelyAfterRehydrate = await readTraceFile(sessionId) + const fileImmediatelyAfterRehydrate = await readTraceFile(tmp.path, sessionId) expect(fileImmediatelyAfterRehydrate.spans).toEqual(onDiskAfterPhase1.spans) expect(fileImmediatelyAfterRehydrate.metadata.prompt).toBe("do the thing") @@ -86,7 +76,7 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { reconstructed.logToolCall({ tool: "edit", state: { status: "completed", input: { f: "b" } } } as any) await reconstructed.flush() - const onDiskAfterPhase3 = await readTraceFile(sessionId) + const onDiskAfterPhase3 = await readTraceFile(tmp.path, sessionId) expect(onDiskAfterPhase3.spans.length).toBeGreaterThan(onDiskAfterPhase1.spans.length) // Old spans still there. for (const oldSpan of onDiskAfterPhase1.spans) { @@ -99,33 +89,36 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { }) test("rehydrate returns false when no on-disk trace exists (fresh session)", async () => { - const trace = makeTrace() + await using tmp = await tmpdir() + const trace = makeTrace(tmp.path) const result = trace.rehydrateFromFile("ses_does_not_exist") expect(result).toBe(false) }) test("rehydrate preserves traceId across instance reconstruction", async () => { + await using tmp = await tmpdir() // Without this, downstream trace consumers (viewer URL, OTLP exporters) // see a different traceId on every snapshot after rehydration — breaks // trace identity across instance lifetimes. const sessionId = "ses_traceid_preservation" - const original = makeTrace() + const original = makeTrace(tmp.path) original.startTrace(sessionId, {}) original.logToolCall({ tool: "read", state: { status: "completed", input: { f: "a" } } } as any) await original.flush() - const beforeFile = await readTraceFile(sessionId) + const beforeFile = await readTraceFile(tmp.path, sessionId) const originalTraceId = beforeFile.traceId expect(typeof originalTraceId).toBe("string") - const reconstructed = makeTrace() + const reconstructed = makeTrace(tmp.path) expect(reconstructed.rehydrateFromFile(sessionId)).toBe(true) reconstructed.logToolCall({ tool: "grep", state: { status: "completed", input: { p: "x" } } } as any) await reconstructed.flush() - const afterFile = await readTraceFile(sessionId) + const afterFile = await readTraceFile(tmp.path, sessionId) expect(afterFile.traceId).toBe(originalTraceId) }) test("rehydrate matches sessionIds containing sanitized characters", async () => { + await using tmp = await tmpdir() // `buildTraceFile` writes the sanitized form (slashes/dots/colons → "_"). // The match check needs to normalize before comparing, otherwise valid // files would be rejected for sessions with those characters. @@ -134,7 +127,7 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { // Write a valid file at the sanitized path with the sanitized sessionId // inside (mirrors what buildTraceFile actually does). await fs.writeFile( - path.join(tmpDir, `${safeId}.json`), + path.join(tmp.path, `${safeId}.json`), JSON.stringify({ version: 2, traceId: "tr_x", @@ -157,16 +150,17 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { }), ) - const trace = makeTrace() + const trace = makeTrace(tmp.path) // Pass the RAW sessionId (with slashes/dots/colons). Pre-fix this would have // returned false because "ses_with/slash.and:colon" !== "ses_with_slash_and_colon". expect(trace.rehydrateFromFile(sessionId)).toBe(true) }) test("rehydrate returns false when on-disk trace is for a different session", async () => { + await using tmp = await tmpdir() // Stage a mismatched file at the expected path for "session-A". await fs.writeFile( - path.join(tmpDir, "ses_target.json"), + path.join(tmp.path, "ses_target.json"), JSON.stringify({ version: 2, traceId: "x", @@ -186,15 +180,16 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { }, }), ) - const trace = makeTrace() + const trace = makeTrace(tmp.path) const result = trace.rehydrateFromFile("ses_target") expect(result).toBe(false) }) test("logUserMessage records each user turn as a span so the chat tab can interleave them", async () => { + await using tmp = await tmpdir() const sessionId = "ses_user_messages" - const trace = makeTrace() + const trace = makeTrace(tmp.path) trace.startTrace(sessionId, {}) trace.logUserMessage("first user message") trace.logToolCall({ tool: "read", state: { status: "completed", input: { f: "a" } } } as any) @@ -203,7 +198,7 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { trace.logUserMessage("third user message") await trace.flush() - const fileContent = await readTraceFile(sessionId) + const fileContent = await readTraceFile(tmp.path, sessionId) const userMessages = fileContent.spans.filter((s) => s.kind === "user-message") expect(userMessages).toHaveLength(3) expect((userMessages[0] as any).input).toBe("first user message") @@ -218,17 +213,18 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { }) test("rehydrate clears endTime on the root span so the trace renders as still in-progress", async () => { + await using tmp = await tmpdir() const sessionId = "ses_endtime_clear" - const original = makeTrace() + const original = makeTrace(tmp.path) original.startTrace(sessionId, {}) original.logToolCall({ tool: "read", state: { status: "completed", input: { f: "a" } } } as any) await original.endTrace() // sets root endTime - const ended = await readTraceFile(sessionId) + const ended = await readTraceFile(tmp.path, sessionId) const endedRoot = ended.spans.find((s) => s.parentSpanId === null) expect(endedRoot?.endTime).toBeDefined() - const reconstructed = makeTrace() + const reconstructed = makeTrace(tmp.path) const ok = reconstructed.rehydrateFromFile(sessionId) expect(ok).toBe(true) @@ -236,7 +232,7 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { reconstructed.logToolCall({ tool: "grep", state: { status: "completed", input: { p: "x" } } } as any) await reconstructed.flush() - const afterRehydrate = await readTraceFile(sessionId) + const afterRehydrate = await readTraceFile(tmp.path, sessionId) const root = afterRehydrate.spans.find((s) => s.parentSpanId === null) // The trace must be re-openable: the root endTime is cleared so subsequent // turns don't render the trace as "completed" in the viewer. From b110980f17279cb033c3faa74c0244004bf64ea7 Mon Sep 17 00:00:00 2001 From: Haider Date: Fri, 5 Jun 2026 23:28:51 +0530 Subject: [PATCH 08/12] fix(viewer): dedupe metadata.prompt against truncated user-message input MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit cubic flagged that `Trace.logUserMessage` slices user text at 4000 chars when persisting to the span, while `metadata.prompt` keeps the full string. The strict equality check in viewer chat-view (`u.input === t.metadata.prompt`) misses the dedupe for prompts longer than 4000 chars and renders the same text twice — once as the top-level "You" fallback bubble, once as the first user-message span. Match against both the full and the truncated form. Same fix shape cubic suggested. --- packages/opencode/src/altimate/observability/viewer.ts | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/packages/opencode/src/altimate/observability/viewer.ts b/packages/opencode/src/altimate/observability/viewer.ts index d2b611cc47..92d72dad3a 100644 --- a/packages/opencode/src/altimate/observability/viewer.ts +++ b/packages/opencode/src/altimate/observability/viewer.ts @@ -1323,12 +1323,18 @@ function showDetail(span) { var userMsgs = spans.filter(function(s){return s.kind==='user-message';}); var gens = spans.filter(function(s){return s.kind==='generation';}); if (t.metadata.prompt) { + // \`logUserMessage\` truncates span input to 4000 chars (see tracing.ts); + // \`metadata.prompt\` stores the full string. For prompts longer than the + // truncation length, strict equality would miss the dedupe and the same + // text would render twice. Match against the truncated form as well. + var promptStr = String(t.metadata.prompt); + var promptTruncated = promptStr.slice(0, 4000); var promptAlreadyInSpan = userMsgs.some(function(u){ - return typeof u.input === 'string' && u.input === t.metadata.prompt; + return typeof u.input === 'string' && (u.input === promptStr || u.input === promptTruncated); }); if (!promptAlreadyInSpan) { html += '
\\u25B6 You
'; - html += '
' + e(t.metadata.prompt) + '
'; + html += '
' + e(promptStr) + '
'; } } var turns = userMsgs.concat(gens).sort(function(a, b) { return (a.startTime||0) - (b.startTime||0); }); From 01b8ea1577f5cc5f74252d65e538d02263ec018c Mon Sep 17 00:00:00 2001 From: Haider Date: Fri, 5 Jun 2026 23:29:40 +0530 Subject: [PATCH 09/12] docs: remove redundant spec/trace-bugs-followup-867.md MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The PR description already carries the bug-by-bug origin table and the explanation of why #867's scope was disjoint from these bugs. Keeping a 295-line spec file in the repo to say the same thing again is bloat — the PR is the right place for this content. --- .../opencode/specs/trace-bugs-followup-867.md | 295 ------------------ 1 file changed, 295 deletions(-) delete mode 100644 packages/opencode/specs/trace-bugs-followup-867.md diff --git a/packages/opencode/specs/trace-bugs-followup-867.md b/packages/opencode/specs/trace-bugs-followup-867.md deleted file mode 100644 index 4c5bdcba0f..0000000000 --- a/packages/opencode/specs/trace-bugs-followup-867.md +++ /dev/null @@ -1,295 +0,0 @@ -# Trace bugs — what this branch fixes and why #867 didn't catch them - -Companion document to the `fix/trace-clearing-on-workspace-set` branch. -Lists the actual bugs found and fixed; excludes the diagnostic dead-ends -that didn't pan out. - -## Bugs fixed in this branch - -### 1. Per-turn `session.status === "idle"` finalized the trace every turn - -**Location**: `packages/opencode/src/cli/cmd/tui/worker.ts:232-243` (removed in this branch) - -**Mechanism**: the handler called `trace.endTrace()` + `sessionTraces.delete(sid)` -whenever `event.type === "session.status"` and `status.type === "idle"`. -`idle` is a **busy→idle transition** — it fires after every agent turn -finishes, not at session end. Every fire destroyed the Trace instance -and removed it from the cache. The next event for the same session in -the next turn hit a cache miss in `getOrCreateTrace`, called -`Trace.create()` + `startTrace(sessionID, {})`, which pushed a single -root span into a freshly-empty `this.spans` and the immediate `snapshot()` -clobbered the rich on-disk `ses_.json` with a 1-span file. - -**Symptom**: -- Waterfall view collapsed to the system-prompt span after every turn -- `metadata.prompt` reset to undefined ("What was asked / No prompt - recorded") -- Token / generation / tool-call counters in `summary` reset to 0/null - -**Severity**: hot path on every multi-turn session. Fired ~once per -agent turn for every session in the cache. - -**Why the comment in the code was misleading**: the original handler -carried the comment "Finalize trace when session reaches idle -(completed)" — the developer who wrote it conflated `idle` (per-turn -event) with session-end. Sessions in altimate-code are long-lived -across many turns; finalization belongs on `shutdown` or eviction, not -per-turn idle. - -**Fix**: handler removed. Trace lives as long as the worker has the -session in its `sessionTraces` map. Finalization happens only on -`worker.shutdown` and on MAX_TRACES eviction — both already correct. - -### 2. `getOrCreateTrace` cache-miss never rehydrated from disk - -**Location**: `packages/opencode/src/cli/cmd/tui/worker.ts:83-106`, -`packages/opencode/src/altimate/observability/tracing.ts` -(`rehydrateFromFile`, new method) - -**Mechanism**: when `sessionTraces.has(sessionID)` returned false, the -worker called `Trace.create()` + `startTrace(sessionID, {})` — which -unconditionally pushed a fresh root span into empty `this.spans` and -wrote a snapshot. The on-disk path is derived purely from `sessionID`, -so the snapshot clobbered any pre-existing rich trace at that path. - -**Triggered when**: -- Worker process restart (sessionTraces empty on boot, user resumes - a session whose trace file already has content) -- MAX_TRACES=100 eviction (the evicted session may be revisited later) -- Any future code path that drops in-memory state for an active session - -After fix #1, these are uncommon — but still real edge cases. - -**Fix**: new `Trace.rehydrateFromFile(sessionId)` reads -`~/.local/share/altimate-code/traces/ses_.json` if it exists, -parses it, restores `this.spans`, `this.metadata`, `this.rootSpanId`, -`this.startTime`, and the running counters (`totalTokens`, -`toolCallCount`, `generationCount`, token breakdown). Clears the root -span's `endTime` so the trace renders as still-in-progress and accepts -new events. `getOrCreateTrace` now prefers rehydration over -`startTrace`; falls back to `startTrace` only when no usable on-disk -file is found. - -### 3. `worker.setWorkspace` was not idempotent - -**Location**: `packages/opencode/src/cli/cmd/tui/worker.ts:308-313` - -**Mechanism**: each call unconditionally invoked `startEventStream`, -which called `endTrace()` on every entry in `sessionTraces` (fire-and- -forget) and then `sessionTraces.clear()`. Combined with the SolidJS -effect upstream (see #4), this meant every spurious effect re-run -destroyed the entire trace cache. - -**Fix**: track `currentWorkspaceID` at module scope; early-return when -`input.workspaceID === currentWorkspaceID`. Defense in depth against the -upstream UI sending spurious calls. - -### 4. SolidJS effect on workspaceID re-ran on every session signal change - -**Location**: `packages/opencode/src/cli/cmd/tui/routes/session/index.tsx:186-190` - -**Mechanism**: `createEffect(() => session()?.workspaceID && sdk.setWorkspace(...))` -reads `session()` inside the effect — SolidJS dirty-tracks the entire -session signal, not the projected `workspaceID`. So the effect re-ran -on every `session()` update (message count, status, parts updated, -title regenerated, …). Each fire propagated into the worker's -`setWorkspace`. - -**Fix**: switched to `createEffect(on(() => session()?.workspaceID, ...))`. -The `on()` projector restricts dirty-tracking to that one field, so -the effect only fires when `workspaceID` actually changes. - -### 5. User prompt was never captured - -**Location**: `packages/opencode/src/cli/cmd/tui/worker.ts` (Path B in -the `message.part.updated` handler) - -**Mechanism**: three different code paths fed `metadata.prompt`: - -- **Path A** (`message.updated` for user role): only fired if - `info.summary?.title || info.summary?.body` was populated — i.e. - only after the title-agent had run. For a first turn, summary is - empty when the event arrives. Doesn't fire. -- **Path B** (`message.part.updated` text part): gated on - `part.type === "text" && part.time?.end`. **User-input parts never - have `time.end` set** — it's a meaningful concept only for - processing-end of assistant chunks. Gate never opens for user text. -- **Path C** (`session.updated` with auto-generated title): called - `trace.setTitle(String(info.title))` with **one argument only** — - set the title but not the prompt. - -Result: title got captured (via Path C, with the auto-generated -"Greeting"-style title), prompt stayed `undefined`. Viewer shows -"What was asked / No prompt recorded". - -**Codex review feedback (2026-06-05)**: even if we drop the `time.end` -gate in Path B, calling `trace.setTitle(text, text)` mutates **both** -title and prompt. If Path B fires after Path C, the nice auto- -generated title regresses to raw user input ("Greeting" → "hi"). The -right fix decouples title mutation from prompt capture. - -**Fix**: -- New `Trace.setPrompt(prompt)` method on the Trace class. Only - mutates `metadata.prompt`. Never touches title. -- Path B in `worker.ts`: dropped `part.time?.end` for the user- - identified branch; calls `setPrompt(text)` instead of - `setTitle(text, text)`. Assistant-text branch still requires - `time.end` for `logText`. - -### 6. User messages were not first-class events in the trace data model - -**Location**: trace data model (no `kind: "user-message"` span before -this branch), `viewer.ts` chat-view renderer - -**Mechanism**: the trace recorded user input only as a single -`metadata.prompt` string. Each new `setPrompt` overwrote the previous -value. The viewer's chat tab rendered `metadata.prompt` as one -"▶ You" bubble at the top, then iterated `kind: "generation"` spans -for assistant replies. There was no place for any user message -beyond the first. - -**Symptom on a 3-turn session**: chat tab showed the **last** user -prompt followed by **all** earlier assistant responses, with the older -user messages dropped. - -**Fix**: -- New `Trace.logUserMessage(text)` pushes a `kind: "user-message"` - span. `TraceSpan.kind` union extended. -- Worker Path B calls `logUserMessage(text)` alongside `setPrompt(text)` - for each user-identified part. -- Viewer chat-view rebuilt: filters both user-message and generation - spans, sorts by `startTime`, walks them in turn order. Renders each - user-message span as its own "▶ You" bubble. Older traces without - user-message spans fall back to `metadata.prompt`-at-top — - backward compatible. - ---- - -## What PR #867 fixed (for comparison) - -PR #867 (merged 2026-06-01, "fix(tracing): close trace corruption in -long-running sessions") closed two concurrency bugs and explicitly -left a third as a documented design hazard: - -### M2 — debounce dropped events with no follow-up snapshot - -`Trace.snapshot()` returned early when `snapshotPending=true` and was -never re-scheduled. In bursty turns (an LLM step firing several tool -calls back-to-back), the disk file lagged memory until a fresh event -arrived in a future turn. If the process exited in the gap, the burst's -tail was lost. - -**Fix**: `snapshotRequestedDuringPending` flag whenever `snapshot()` -short-circuits. In `.finally()`, if the flag is set and the trace is -neither crashed nor ending, schedule exactly one follow-up snapshot -via `queueMicrotask`. Bounded — at most one extra write per -"burst → quiet" cycle regardless of burst size. - -### M3 — `FileExporter.export()` raced `flushSync` with no `crashed` guard - -`endTrace()` calls `exporter.export()`, which does `writeFile(tmp)` -→ `rename(tmp, final)`. On multi-MB traces the writeFile takes 100+ms, -a wide window for `flushSync` to interleave. The `crashed` flag added -in commit `38463876b` only guarded `Trace.snapshot()`, not -`FileExporter.export()`, so `flushSync`'s synchronous crashed write -was overwritten by the export's rename. - -**Fix**: per-session `_crashed` flag on `FileExporter` with -`markCrashed()`. Checked at entry, before writeFile, and before rename -(drop tmp + bail). `flushSync` iterates exporters and calls -`markCrashed()` on each before its own synchronous write. - -### M2 companion — `endTraceStarted` gate - -Once `endTrace()` claims the canonical write, no concurrent snapshot -may run — they would race endTrace's mutation of the root span -(endTime, status) and could clobber endTrace's content with stale -pre-end state. - -### M1 — NOT closed in #867 - -The TOCTOU between the synchronous `if (this.crashed)` check and the -asynchronous kernel `fs.rename` syscall. Documented as a known design -hazard; existing `crashed` flag from `38463876b` protects against it -on local SSD (microsecond rename window). Theoretical exposure remains -on slow/network filesystems. - ---- - -## Why #867 didn't catch the bugs in this branch - -### Different layer of abstraction - -PR #867's bugs all live at the **intra-Trace-instance concurrency -layer** — within one Trace object's state machine: - -- Snapshot debounce/follow-up timing within one instance -- FileExporter ↔ flushSync interleave for one instance's write -- endTrace ↔ snapshot races for one instance - -This branch's bugs (#1, #2, #3, #4) all live at the **cross-instance -lifecycle layer** — when one Trace instance gets destroyed and another -is constructed for the same `sessionID`: - -- When destruction happens (idle handler / setWorkspace / cache eviction) -- What happens on the next `Trace.create()` (no disk rehydration) -- What the upstream UI triggers cause it (SolidJS effect) - -The two layers are orthogonal. #867's reproducers (`tracing-rename-race.test.ts`, -`tracing-display-crash.test.ts`) all hold one Trace instance for their -entire test lifecycle and exercise crash/burst conditions against -that instance. They cannot detect a bug whose mechanism is "destroy -the instance, build a new one, watch the new one's first write -clobber the old one's file." - -### The destructive handler was intentional code, not a concurrency bug - -The per-turn idle handler (#1) was **the developer's intent** — they -explicitly named it "Finalize trace when session reaches idle -(completed)". The bug is a semantic misunderstanding of what `idle` -means at the event level (per-turn vs per-session), not a race or -data corruption. #867's reproducer matrix wouldn't have surfaced it -because none of the M-class bugs involved destroying the Trace and -the reproducers all assumed a single instance. - -### Data-feed and rendering layers were out of scope - -#867 worked on the **persistence layer** (FileExporter, snapshot, -flushSync). The prompt-capture and chat-rendering bugs (#5, #6) live -at: - -- **Worker event-handler layer** (`worker.ts`) — what gets fed into - the Trace from the bus event stream -- **Trace data-model layer** (`tracing.ts`) — what fields and span - kinds the Trace exposes -- **Viewer layer** (`viewer.ts`) — how rendered HTML iterates spans - -All three are independent of crash/race safety. A 100%-correct -persistence layer can still ship a 1-span trace file if upstream -feeds only 1 span, or render a single "You" bubble if the data model -only carries `metadata.prompt`. - -### No cross-turn integration tests - -Existing tracing tests are concurrency reproducers and unit tests of -isolated methods. None exercise the full event-stream-to-trace-file -path for a multi-turn session. The cross-turn nature of the idle -clobber requires a test that drives at least two `busy → idle` cycles -through the worker's event handler against a real `Trace` instance. - -This branch adds: - -- `test/cli/tui/worker-trace-clearing.test.ts` — source-grep contract - tests that lock the no-idle-clobber, rehydrate-before-startTrace, - and `setPrompt`-not-`setTitle` invariants in worker.ts. -- `test/altimate/tracing-rehydrate.test.ts` — behavioral tests for - `Trace.rehydrateFromFile` (preserve spans/metadata/counters, - reject missing/mismatched/malformed files, clear endTime on - rehydrate) and for `logUserMessage` (chronological ordering). - -A higher-fidelity follow-up would be a real-worker integration test -that emits a synthetic `session.status` idle event between two turns -and asserts the trace file does not collapse — that needs the worker -event loop running against a stub bus. Worth adding as a separate -PR; the source-grep + behavioral tests are sufficient to lock the -contracts in this PR. From 39dd742e2d380cf6330afccafbf289ffed0fc930 Mon Sep 17 00:00:00 2001 From: Haider Date: Sat, 6 Jun 2026 00:01:35 +0530 Subject: [PATCH 10/12] fix(tracing): synthetic-part gate, in-flight gen interrupt, shared truncation constant MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three follow-ups from the multi-LLM consensus review of PR #895, codex-validated: * Worker user-text branch now skips parts with `synthetic` or `ignored` set (Major #1 in the review, codex-confirmed). `Session.createUserMessage` in prompt.ts attaches many synthetic text parts to the user messageID for MCP resource banners, decoded file contents, retry/reminder text, plan-mode reminders, and agent-handoff tags. Without the gate they pass the `sessionUserMsgIds.has(messageID)` check, `metadata.prompt` ends up holding the LAST synthetic part (typically a file blob), and the chat tab renders one fake "▶ You" bubble per synthetic span — defeating the two display surfaces this PR fixes. Gated on an `isAuthoredText` predicate so the symmetric assistant-text branch is also protected. Continue via predicate rather than `continue` keyword so the outer event loop still forwards the event downstream via `Rpc.emit`. * `Trace.rehydrateFromFile` now marks any open generation span as interrupted (Major #2). The transient state `logStepStart` populated (`currentGenerationSpanId`, `generationText`, `generationToolCalls`, `pendingToolResults`) is memory-only and can't be reconstructed from disk. If we leave open spans open, the next `step-finish` for that turn drops at the `!this.currentGenerationSpanId` guard and follow-up `logToolCall` mis-parents tool spans to the root, silently degrading the trace shape. Closing the span with `status: "error"` and a `statusMessage` describing the interruption preserves the partial data and makes the boundary visible in the viewer. * Extracted the 4000-char truncation cap as `USER_MESSAGE_INPUT_MAX_CHARS` exported from tracing.ts (new cubic P3 on viewer.ts:1331). The viewer's chat-tab dedupe now interpolates the same constant so the two sides can't drift if the truncation cap ever changes. Also reused a single `Date.now()` call for the user-message span's start/end timestamps (cosmetic, addresses review nit #16). Skipped from the review: - Major #3 (no per-messageID dedupe in logUserMessage): codex confirmed user text doesn't stream/chunk — message.part.delta is assistant-only — so the symptom the review described is subsumed by Major #1's synthetic gate. No separate fix needed. - Major #5 (Path A `setTitle(text, text)` couples title and prompt): codex grep-verified that no in-repo code path populates `userMsg.summary.title` or `summary.body`; the branch is inert. Cleanup risk only, tracked in #896. Tests - New behavioral test in tracing-rehydrate.test.ts asserts that an open generation span (no `step-finish` before reconstruction) ends up with `endTime` set, `status: "error"`, and a statusMessage matching `/interrupted/i` after rehydrate + a snapshot-triggering call. - New source-grep test in worker-trace-clearing.test.ts locks both the synthetic-gate literal (`!part.synthetic && !part.ignored`) and the requirement that both `trace.setPrompt` and `trace.logUserMessage` sit inside the `isAuthoredText &&` guard. 42 affected tests pass; typecheck clean. --- .../src/altimate/observability/tracing.ts | 30 +++++++++++++-- .../src/altimate/observability/viewer.ts | 15 +++++--- packages/opencode/src/cli/cmd/tui/worker.ts | 22 ++++++++++- .../test/altimate/tracing-rehydrate.test.ts | 37 +++++++++++++++++++ .../cli/tui/worker-trace-clearing.test.ts | 20 ++++++++++ 5 files changed, 113 insertions(+), 11 deletions(-) diff --git a/packages/opencode/src/altimate/observability/tracing.ts b/packages/opencode/src/altimate/observability/tracing.ts index 777ad39954..1db0f621e8 100644 --- a/packages/opencode/src/altimate/observability/tracing.ts +++ b/packages/opencode/src/altimate/observability/tracing.ts @@ -345,6 +345,12 @@ function formatDurationShort(ms: number): string { } // altimate_change end +// altimate_change start — shared truncation cap for `logUserMessage` span input. +// Exported so the viewer's chat-tab dedupe can compare against the same boundary +// (otherwise it'd silently drift if either side changes the magic number). +export const USER_MESSAGE_INPUT_MAX_CHARS = 4000 +// altimate_change end + export class Trace { // Global active trace — set when a session starts, cleared on end. private static _active: Trace | null = null @@ -565,6 +571,23 @@ export class Trace { delete (r as { endTime?: number }).endTime r.status = "ok" } + // Close any in-flight generation spans as interrupted. The transient state + // these spans depended on (`this.currentGenerationSpanId`, `generationText`, + // `generationToolCalls`, `pendingToolResults`) lives only in memory and + // can't be reconstructed from the on-disk file. If we leave open spans + // open, the next `step-finish` event for that turn drops at the + // `if (!this.currentGenerationSpanId) return` guard in `logStepFinish` + // and any later `logToolCall` falls back to attaching tool spans to + // `rootSpanId`, silently degrading the trace shape. Marking them + // interrupted preserves the partial data and makes the boundary visible. + const now = Date.now() + for (const s of this.spans) { + if (s.kind === "generation" && s.endTime === undefined) { + s.endTime = now + s.status = "error" + s.statusMessage = "interrupted (worker restart / cache eviction before step-finish)" + } + } this.endTraceStarted = false return true } @@ -617,15 +640,16 @@ export class Trace { if (!this.rootSpanId) return if (!text) return try { + const now = Date.now() this.spans.push({ spanId: randomUUIDv7(), parentSpanId: this.rootSpanId, name: "user-message", kind: "user-message", - startTime: Date.now(), - endTime: Date.now(), + startTime: now, + endTime: now, status: "ok", - input: text.slice(0, 4000), + input: text.length > USER_MESSAGE_INPUT_MAX_CHARS ? text.slice(0, USER_MESSAGE_INPUT_MAX_CHARS) : text, }) this.snapshot() } catch { diff --git a/packages/opencode/src/altimate/observability/viewer.ts b/packages/opencode/src/altimate/observability/viewer.ts index 92d72dad3a..df80d46a66 100644 --- a/packages/opencode/src/altimate/observability/viewer.ts +++ b/packages/opencode/src/altimate/observability/viewer.ts @@ -12,7 +12,7 @@ * Branded with Altimate Trace colors. Includes share/export features for virality. */ -import type { TraceFile } from "./tracing" +import { USER_MESSAGE_INPUT_MAX_CHARS, type TraceFile } from "./tracing" export function renderTraceViewer(trace: TraceFile, options?: { live?: boolean; apiPath?: string }): string { const traceJSON = JSON.stringify(trace).replace(/<\//g, "<\\/") @@ -1323,12 +1323,15 @@ function showDetail(span) { var userMsgs = spans.filter(function(s){return s.kind==='user-message';}); var gens = spans.filter(function(s){return s.kind==='generation';}); if (t.metadata.prompt) { - // \`logUserMessage\` truncates span input to 4000 chars (see tracing.ts); - // \`metadata.prompt\` stores the full string. For prompts longer than the - // truncation length, strict equality would miss the dedupe and the same - // text would render twice. Match against the truncated form as well. + // \`logUserMessage\` truncates span input to USER_MESSAGE_INPUT_MAX_CHARS + // (see tracing.ts); \`metadata.prompt\` stores the full string. For prompts + // longer than the truncation length, strict equality would miss the dedupe + // and the same text would render twice. Match against the truncated form as + // well. The constant is interpolated at render time so the two sides can't + // drift. + var USER_MSG_TRUNCATE = ${USER_MESSAGE_INPUT_MAX_CHARS}; var promptStr = String(t.metadata.prompt); - var promptTruncated = promptStr.slice(0, 4000); + var promptTruncated = promptStr.slice(0, USER_MSG_TRUNCATE); var promptAlreadyInSpan = userMsgs.some(function(u){ return typeof u.input === 'string' && (u.input === promptStr || u.input === promptTruncated); }); diff --git a/packages/opencode/src/cli/cmd/tui/worker.ts b/packages/opencode/src/cli/cmd/tui/worker.ts index d29202d25e..eba20d591f 100644 --- a/packages/opencode/src/cli/cmd/tui/worker.ts +++ b/packages/opencode/src/cli/cmd/tui/worker.ts @@ -219,7 +219,25 @@ const startEventStream = (input: { directory: string; workspaceID?: string }) => // call `setPrompt(text)` only — never `setTitle` — to avoid racing // the auto-generated title from `session.updated` (Path C). if (part.type === "text") { - if (part.messageID && sessionUserMsgIds.get(part.sessionID)?.has(part.messageID)) { + // altimate_change start — skip synthetic / ignored text parts. + // `Session.createUserMessage` (prompt.ts) attaches many `synthetic: true` + // text parts to the user message — MCP resource banners, decoded file + // contents, retry/reminder text, plan-mode reminders, agent-handoff + // tags. They all share the user's `messageID` so they would otherwise + // pass the `sessionUserMsgIds` check below and override `metadata.prompt` + // with the LAST synthetic blob (typically file content) and render one + // fake "▶ You" bubble per synthetic part in the chat tab. The synthetic + // and ignored flags exist precisely to mark non-authored content; this + // is exactly the place to consult them. We skip silently rather than + // `continue`-ing the event-loop iteration because the outer loop still + // needs to forward the event downstream via `Rpc.emit`. + const isAuthoredText = !part.synthetic && !part.ignored + // altimate_change end + if ( + isAuthoredText && + part.messageID && + sessionUserMsgIds.get(part.sessionID)?.has(part.messageID) + ) { const text = String(part.text || "") if (text) { trace.setPrompt(text) @@ -231,7 +249,7 @@ const startEventStream = (input: { directory: string; workspaceID?: string }) => trace.logUserMessage(text) // altimate_change end } - } else if (part.time?.end) { + } else if (isAuthoredText && part.time?.end) { // Assistant response text (only counts when processing-end fires) trace.logText(part) } diff --git a/packages/opencode/test/altimate/tracing-rehydrate.test.ts b/packages/opencode/test/altimate/tracing-rehydrate.test.ts index dfb53aab9f..cc24a3af9b 100644 --- a/packages/opencode/test/altimate/tracing-rehydrate.test.ts +++ b/packages/opencode/test/altimate/tracing-rehydrate.test.ts @@ -212,6 +212,43 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { expect(sortedByStart).toEqual(allSpans) }) + test("rehydrate marks any in-flight generation span as interrupted", async () => { + // Without this, the transient state that `logStepStart` opened (currentGenerationSpanId, + // generationText, generationToolCalls, pendingToolResults) is lost on reconstruction. + // A later `step-finish` event for that turn would drop at the + // `if (!this.currentGenerationSpanId) return` guard, and follow-up `logToolCall` + // would mis-parent its span at the root. Marking open generation spans interrupted + // makes the boundary visible and prevents the silent degrade. + await using tmp = await tmpdir() + const sessionId = "ses_inflight_gen" + + const original = makeTrace(tmp.path) + original.startTrace(sessionId, {}) + // Open a generation span via logStepStart. `logStepStart` does not itself + // snapshot to disk, so follow with a tool call (which does snapshot) to + // force a flush of the open generation span. Do NOT call logStepFinish — + // the point is to leave the generation span open on disk. + original.logStepStart({ id: "step-1" } as any) + original.logToolCall({ tool: "read", state: { status: "completed", input: { f: "a" } } } as any) + await original.flush() + const beforeFile = await readTraceFile(tmp.path, sessionId) + const openGen = beforeFile.spans.find((s) => s.kind === "generation") + expect(openGen).toBeDefined() + expect(openGen?.endTime).toBeUndefined() + + const reconstructed = makeTrace(tmp.path) + expect(reconstructed.rehydrateFromFile(sessionId)).toBe(true) + // Trigger a snapshot so the rehydrated state lands on disk. + reconstructed.logToolCall({ tool: "read", state: { status: "completed", input: { f: "a" } } } as any) + await reconstructed.flush() + + const afterFile = await readTraceFile(tmp.path, sessionId) + const interruptedGen = afterFile.spans.find((s) => s.spanId === openGen?.spanId) + expect(interruptedGen?.endTime).toBeDefined() + expect(interruptedGen?.status).toBe("error") + expect(interruptedGen?.statusMessage).toMatch(/interrupted/i) + }) + test("rehydrate clears endTime on the root span so the trace renders as still in-progress", async () => { await using tmp = await tmpdir() const sessionId = "ses_endtime_clear" diff --git a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts index 5d2003b6a4..edba4e014c 100644 --- a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts +++ b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts @@ -133,6 +133,26 @@ describe("trace-clearing-on-workspace-set regression", () => { ) }) + // Major #1 from the multi-LLM consensus review (codex-verified). The user-text + // branch must NOT feed `setPrompt`/`logUserMessage` from synthetic or ignored + // parts — `Session.createUserMessage` (prompt.ts) attaches MCP resource banners, + // decoded file contents, retry/reminder text, and plan-mode reminders as + // `synthetic: true` text parts that share the user's `messageID`. Without the + // gate, `metadata.prompt` ends up holding the LAST synthetic part (typically + // a file blob) and the chat tab renders one fake "▶ You" bubble per synthetic + // span — defeating the two display surfaces this PR fixes. + test("user-text branch skips synthetic/ignored parts before calling setPrompt+logUserMessage", async () => { + const workerSrc = await fs.readFile(path.join(ROOT, "src/cli/cmd/tui/worker.ts"), "utf-8") + // The synthetic+ignored gate must exist literally somewhere. + expect(workerSrc).toMatch(/!part\.synthetic\s*&&\s*!part\.ignored/) + // And the two write paths must be co-located inside a guard built from the + // same predicate — verified by checking that the `isAuthoredText &&` gate + // appears, followed (lazily) by both `trace.setPrompt` and `trace.logUserMessage`. + expect(workerSrc).toMatch( + /isAuthoredText\s*&&[\s\S]*?trace\.setPrompt[\s\S]*?trace\.logUserMessage/, + ) + }) + test("Trace.setPrompt exists and only mutates metadata.prompt", async () => { const tracingSrc = await fs.readFile( path.join(ROOT, "src/altimate/observability/tracing.ts"), From 6267ec56f355d541345288c30cf5329410b0224a Mon Sep 17 00:00:00 2001 From: Haider Date: Sat, 6 Jun 2026 00:59:53 +0530 Subject: [PATCH 11/12] test: tighten worker-trace-clearing regex to scope-bounded match (CodeRabbit) CodeRabbit flagged that the previous source-grep assertions matched across the entire `worker.ts` file, so unrelated code positioning could satisfy them without the synthetic-gate fix being present in the actual user-text branch. * The `isAuthoredText` declaration check now asserts the const is built from BOTH flags (`!part.synthetic && !part.ignored`), not just that the literal exists somewhere. * The two write-path checks now require `trace.setPrompt` and `trace.logUserMessage` to sit inside the same `if (text) { ... }` body within the `sessionUserMsgIds...has(part.messageID)` branch. The `[^{}]` bounds on the inner spans prevent the match from extending past the closing brace of that body, so calls elsewhere in the file can't false-green the assertion. --- .../cli/tui/worker-trace-clearing.test.ts | 20 +++++++++++++------ 1 file changed, 14 insertions(+), 6 deletions(-) diff --git a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts index edba4e014c..bf43e7ebf9 100644 --- a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts +++ b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts @@ -143,13 +143,21 @@ describe("trace-clearing-on-workspace-set regression", () => { // span — defeating the two display surfaces this PR fixes. test("user-text branch skips synthetic/ignored parts before calling setPrompt+logUserMessage", async () => { const workerSrc = await fs.readFile(path.join(ROOT, "src/cli/cmd/tui/worker.ts"), "utf-8") - // The synthetic+ignored gate must exist literally somewhere. - expect(workerSrc).toMatch(/!part\.synthetic\s*&&\s*!part\.ignored/) - // And the two write paths must be co-located inside a guard built from the - // same predicate — verified by checking that the `isAuthoredText &&` gate - // appears, followed (lazily) by both `trace.setPrompt` and `trace.logUserMessage`. + // The synthetic+ignored gate must build the `isAuthoredText` predicate + // from BOTH flags. Stronger than just searching for the literal anywhere. expect(workerSrc).toMatch( - /isAuthoredText\s*&&[\s\S]*?trace\.setPrompt[\s\S]*?trace\.logUserMessage/, + /const\s+isAuthoredText\s*=\s*!part\.synthetic\s*&&\s*!part\.ignored/, + ) + // Both write paths must sit inside the user-text branch (gated on the + // `sessionUserMsgIds...has(...)` membership check) AND inside an + // `if (text)` body whose contents don't cross block boundaries. + // The `[^{}]` bounds on the inner spans prevent the match from extending + // past the closing brace of the `if (text)` body, so unrelated + // `trace.setPrompt` / `trace.logUserMessage` calls elsewhere in the file + // can't satisfy this assertion — exactly what the previous loose regex + // allowed and what CodeRabbit flagged. + expect(workerSrc).toMatch( + /sessionUserMsgIds\.get\(part\.sessionID\)\?\.has\(part\.messageID\)[\s\S]{0,400}if\s*\(\s*text\s*\)\s*\{[^{}]*trace\.setPrompt[^{}]*trace\.logUserMessage/, ) }) From 7f7115408871a33ecb786107b867f133d9080417 Mon Sep 17 00:00:00 2001 From: Haider Date: Sat, 6 Jun 2026 08:23:12 +0530 Subject: [PATCH 12/12] fix(tracing): make rehydrateFromFile async to unblock the event-loop hot path MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit cubic flagged that `fsSync.readFileSync` in `rehydrateFromFile` blocks the worker event loop during a trace cache miss. The hot path is bounded (cache miss only fires on worker restart, MAX_TRACES eviction, or initial-boot resumption of a stale session), but a multi-MB trace file makes the pause visible. * `Trace.rehydrateFromFile` now returns `Promise` and uses the async `fs.readFile`. * `getOrCreateTrace` in worker.ts becomes `async` and the three call sites in the event-stream loop now `await` it. The loop body was already async (`for await (const event of events.stream)`), so the conversion is local. * Behavioural tests in `tracing-rehydrate.test.ts` converted to `await` the now-async method (7 call sites). * The source-grep contract test for `getOrCreateTrace`'s rehydrate-before-startTrace shape now matches the `await` form. Not addressed in this commit (will reply on PR): - cubic also flagged a theoretical event-ordering race where `message.part.updated` could arrive before `message.updated`, leaving `sessionUserMsgIds` empty when the part handler runs. The producer (`Session.createUserMessage` → `updateMessage` THEN `updatePart` for each part) emits in order, and the consumer reads the event stream sequentially. The race is theoretical given the current producer; if we ever reorder, the defensive fix is to buffer unrouted parts by messageID. Out of scope for this PR. --- .../opencode/src/altimate/observability/tracing.ts | 10 ++++++++-- packages/opencode/src/cli/cmd/tui/worker.ts | 13 ++++++++----- .../test/altimate/tracing-rehydrate.test.ts | 14 +++++++------- .../test/cli/tui/worker-trace-clearing.test.ts | 5 ++++- 4 files changed, 27 insertions(+), 15 deletions(-) diff --git a/packages/opencode/src/altimate/observability/tracing.ts b/packages/opencode/src/altimate/observability/tracing.ts index 1db0f621e8..16563fd01a 100644 --- a/packages/opencode/src/altimate/observability/tracing.ts +++ b/packages/opencode/src/altimate/observability/tracing.ts @@ -506,13 +506,19 @@ export class Trace { // // Does NOT call snapshot — the file is already correct on disk; an // unnecessary write here would compete with concurrent flushSync paths. - rehydrateFromFile(sessionId: string): boolean { + // + // Async: read the file off the event-loop hot path so a worker-restart + // cache miss with a large existing trace doesn't head-of-line-block all + // session events. The actual hot path was bounded (cache-miss only) but + // the sync `readFileSync` could still pause the worker noticeably for a + // multi-MB trace. + async rehydrateFromFile(sessionId: string): Promise { if (!this.snapshotDir) return false const safeId = sessionId.replace(/[/\\.:]/g, "_") || "unknown" const filePath = path.join(this.snapshotDir, `${safeId}.json`) let raw: string try { - raw = fsSync.readFileSync(filePath, "utf-8") + raw = await fs.readFile(filePath, "utf-8") } catch { return false } diff --git a/packages/opencode/src/cli/cmd/tui/worker.ts b/packages/opencode/src/cli/cmd/tui/worker.ts index eba20d591f..777abc8ba1 100644 --- a/packages/opencode/src/cli/cmd/tui/worker.ts +++ b/packages/opencode/src/cli/cmd/tui/worker.ts @@ -80,7 +80,7 @@ async function loadTracingConfig() { // altimate_change end // altimate_change start — trace: get or create per-session trace -function getOrCreateTrace(sessionID: string): Trace | null { +async function getOrCreateTrace(sessionID: string): Promise { if (!sessionID || !tracingEnabled) return null if (sessionTraces.has(sessionID)) return sessionTraces.get(sessionID)! try { @@ -101,7 +101,8 @@ function getOrCreateTrace(sessionID: string): Trace | null { // push a fresh root span into empty `this.spans` and the immediate // snapshot would clobber the rich on-disk file. Defense in depth in // addition to keeping the cache alive across turns. - if (!trace.rehydrateFromFile(sessionID)) { + // Async to keep the event-stream loop unblocked on large existing traces. + if (!(await trace.rehydrateFromFile(sessionID))) { trace.startTrace(sessionID, {}) } // altimate_change end @@ -179,7 +180,9 @@ const startEventStream = (input: { directory: string; workspaceID?: string }) => } if (resolvedSessionID) { // Create trace eagerly on user message (arrives before part events) - const trace = sessionTraces.get(resolvedSessionID) ?? (info.role === "user" ? getOrCreateTrace(resolvedSessionID) : null) + const trace = + sessionTraces.get(resolvedSessionID) ?? + (info.role === "user" ? await getOrCreateTrace(resolvedSessionID) : null) if (info.role === "user") { if (info.id) { if (!sessionUserMsgIds.has(resolvedSessionID)) sessionUserMsgIds.set(resolvedSessionID, new Set()) @@ -191,7 +194,7 @@ const startEventStream = (input: { directory: string; workspaceID?: string }) => } } if (info.role === "assistant") { - const r = trace ?? getOrCreateTrace(resolvedSessionID) + const r = trace ?? (await getOrCreateTrace(resolvedSessionID)) r?.enrichFromAssistant({ modelID: info.modelID, providerID: info.providerID, @@ -207,7 +210,7 @@ const startEventStream = (input: { directory: string; workspaceID?: string }) => const part = (event as any).properties?.part if (part) { // Create trace on first event for this session (lazy creation) - const trace = sessionTraces.get(part.sessionID) ?? getOrCreateTrace(part.sessionID) + const trace = sessionTraces.get(part.sessionID) ?? (await getOrCreateTrace(part.sessionID)) if (trace) { if (part.type === "step-start") trace.logStepStart(part) if (part.type === "step-finish") trace.logStepFinish(part) diff --git a/packages/opencode/test/altimate/tracing-rehydrate.test.ts b/packages/opencode/test/altimate/tracing-rehydrate.test.ts index cc24a3af9b..8f26bcb910 100644 --- a/packages/opencode/test/altimate/tracing-rehydrate.test.ts +++ b/packages/opencode/test/altimate/tracing-rehydrate.test.ts @@ -61,7 +61,7 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { // Trace instance for the SAME sessionID. This is the path that, pre-fix, // would have called startTrace and clobbered the file. const reconstructed = makeTrace(tmp.path) - const didRehydrate = reconstructed.rehydrateFromFile(sessionId) + const didRehydrate = await reconstructed.rehydrateFromFile(sessionId) expect(didRehydrate).toBe(true) @@ -91,7 +91,7 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { test("rehydrate returns false when no on-disk trace exists (fresh session)", async () => { await using tmp = await tmpdir() const trace = makeTrace(tmp.path) - const result = trace.rehydrateFromFile("ses_does_not_exist") + const result = await trace.rehydrateFromFile("ses_does_not_exist") expect(result).toBe(false) }) @@ -110,7 +110,7 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { expect(typeof originalTraceId).toBe("string") const reconstructed = makeTrace(tmp.path) - expect(reconstructed.rehydrateFromFile(sessionId)).toBe(true) + expect(await reconstructed.rehydrateFromFile(sessionId)).toBe(true) reconstructed.logToolCall({ tool: "grep", state: { status: "completed", input: { p: "x" } } } as any) await reconstructed.flush() const afterFile = await readTraceFile(tmp.path, sessionId) @@ -153,7 +153,7 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { const trace = makeTrace(tmp.path) // Pass the RAW sessionId (with slashes/dots/colons). Pre-fix this would have // returned false because "ses_with/slash.and:colon" !== "ses_with_slash_and_colon". - expect(trace.rehydrateFromFile(sessionId)).toBe(true) + expect(await trace.rehydrateFromFile(sessionId)).toBe(true) }) test("rehydrate returns false when on-disk trace is for a different session", async () => { @@ -181,7 +181,7 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { }), ) const trace = makeTrace(tmp.path) - const result = trace.rehydrateFromFile("ses_target") + const result = await trace.rehydrateFromFile("ses_target") expect(result).toBe(false) }) @@ -237,7 +237,7 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { expect(openGen?.endTime).toBeUndefined() const reconstructed = makeTrace(tmp.path) - expect(reconstructed.rehydrateFromFile(sessionId)).toBe(true) + expect(await reconstructed.rehydrateFromFile(sessionId)).toBe(true) // Trigger a snapshot so the rehydrated state lands on disk. reconstructed.logToolCall({ tool: "read", state: { status: "completed", input: { f: "a" } } } as any) await reconstructed.flush() @@ -262,7 +262,7 @@ describe("Trace.rehydrateFromFile + cache-miss rehydration", () => { expect(endedRoot?.endTime).toBeDefined() const reconstructed = makeTrace(tmp.path) - const ok = reconstructed.rehydrateFromFile(sessionId) + const ok = await reconstructed.rehydrateFromFile(sessionId) expect(ok).toBe(true) // Trigger a snapshot via a real span push so the disk file gets re-written. diff --git a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts index bf43e7ebf9..925eb2e4bd 100644 --- a/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts +++ b/packages/opencode/test/cli/tui/worker-trace-clearing.test.ts @@ -98,8 +98,11 @@ describe("trace-clearing-on-workspace-set regression", () => { // the next snapshot clobbers the rich file. test("getOrCreateTrace prefers rehydrateFromFile over startTrace on cache miss", async () => { const workerSrc = await fs.readFile(path.join(ROOT, "src/cli/cmd/tui/worker.ts"), "utf-8") + // `rehydrateFromFile` is async (off-loads disk I/O from the event-stream + // hot path per cubic P2 review on tracing.ts:515) so the call must be + // awaited inside getOrCreateTrace. expect(workerSrc).toMatch( - /if \(!trace\.rehydrateFromFile\(sessionID\)\)\s*\{\s*\n\s*trace\.startTrace\(sessionID, \{\}\)\s*\n\s*\}/, + /if \(!\(await trace\.rehydrateFromFile\(sessionID\)\)\)\s*\{\s*\n\s*trace\.startTrace\(sessionID, \{\}\)\s*\n\s*\}/, ) })