Skip to content

Commit 49fd9be

Browse files
authored
fix(tracing): reliability follow-ups from v0.8.4 review (#901, #902, #903) (#905)
* fix(tracing): reliability follow-ups from the v0.8.4 review (#901, #902, #903) Three follow-ups filed during the v0.8.4 release review of the trace-data-loss fix (#895): #901 — reconstructed spans no longer masquerade as failures. When `rehydrateFromFile` force-closes an in-flight generation span (worker restart / cache eviction), the span kept `status: "error"`, so the viewer painted it red and counted it in the session error total — a false alarm on a postmortem surface. Spans now also carry `interrupted: true`; the viewer renders them with an amber "⚠" affordance and an "Interrupted" detail label instead of red, and the session error count (`errSpans`) excludes them. `status: "error"` is kept so the boundary stays visible, so existing rehydrate tests are unaffected. #902 — `getOrCreateTrace` can no longer resurrect a Trace into a cleared cache. The async rehydrate added an await point where a concurrent `startEventStream` (e.g. `setWorkspace`) can abort the stream and `sessionTraces.clear()` while we're suspended. On resume the old code inserted the freshly built Trace into the just-cleared map — an orphan writer under a dead stream. We now capture the owning stream before the await and, if it was replaced, discard the Trace (`endTrace`) and defer to the live stream instead of inserting. #903 — long-lived traces no longer grow `ses_<id>.json` without bound. `snapshot()` rewrites the entire spans array on every event, so an unbounded session paid O(n) per write (O(n^2) overall) and grew the file forever. `capSpansForSerialization` bounds the on-disk projection to `MAX_SERIALIZED_SPANS` (default 5000, override via `ALTIMATE_TRACE_MAX_SPANS`) by keeping the head (prompt + first tools) and tail (recent activity) and eliding the middle with a single marker span. In-memory spans are untouched; summary counters are separate counters, so totals are unaffected. Tests: `test/altimate/tracing-followups.test.ts` — interrupted flag is set on rehydrate; viewer carries the amber/`!sp.interrupted` contract and the flag in embedded data; `capSpansForSerialization` head/tail/marker behavior, no-op under cap, and no-benefit guard; plus a scope-bounded source contract for the #902 guard ordering (await → guard → insert). `worker.ts` edits are wrapped in `altimate_change` markers (upstream-shared). tracing.ts / viewer.ts are altimate-owned. Closes #901 Closes #902 Closes #903 * fix(tracing): harden follow-ups per multi-model review (#901, #902, #903) Addresses findings from the GPT-5.4 + Kimi-K2.5 review panel: #902 (MAJOR) — key the orphan-writer guard on a monotonic `streamGeneration` counter bumped in startEventStream, not on AbortController object identity. The identity check was correct only while startEventStream always allocates a fresh controller; the counter makes ownership explicit and removes that hidden dependency. The check and the cache insert run in one synchronous turn (no await between), so the insert can't race a later startEventStream. #903 (MAJOR) — capSpansForSerialization now explicitly guarantees the structural root (session) span survives the cut even if it isn't in the head slice, instead of relying on "root happens to be index 0". Rehydrate and the viewer tree both require the root, and the elision marker is parented to it. Added table-driven tests: root-not-at-index-0, tiny caps (1–5) with marker-parent validity, the exact head+tail+1===length boundary, and elided-count accuracy. #901 (Kimi blockers) — interrupted spans now render amber (not red) on EVERY viewer surface, not just the preview/detail: waterfall row + icon class, tree-view meta ("interrupted" in orange), and log-view row (⚠ amber). errSpans already excluded them; this makes the visual treatment consistent so a reconstructed trace never looks like a failed one anywhere. Known minor (deferred, noted on PR): a trace containing ONLY interrupted spans no longer contributes to the summary error count (correct) but also shows no "incomplete" hint in the summary; a dedicated interrupted/incomplete banner is a small follow-up.
1 parent db81d41 commit 49fd9be

4 files changed

Lines changed: 350 additions & 10 deletions

File tree

packages/opencode/src/altimate/observability/tracing.ts

Lines changed: 69 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,14 @@ export interface TraceSpan {
4747
endTime?: number
4848
status: "ok" | "error"
4949
statusMessage?: string
50+
/**
51+
* True when this span was force-closed by trace reconstruction (worker
52+
* restart / cache eviction) rather than by a real error. The span keeps
53+
* `status: "error"` so its boundary stays visible, but consumers (the viewer,
54+
* error aggregations) should treat it as "incomplete (reconstructed)" — not a
55+
* genuine agent/tool failure.
56+
*/
57+
interrupted?: boolean
5058

5159
// --- LLM / generation fields (populated for kind=generation) ---
5260
model?: {
@@ -349,6 +357,62 @@ function formatDurationShort(ms: number): string {
349357
// Exported so the viewer's chat-tab dedupe can compare against the same boundary
350358
// (otherwise it'd silently drift if either side changes the magic number).
351359
export const USER_MESSAGE_INPUT_MAX_CHARS = 4000
360+
361+
/**
362+
* Upper bound on the number of spans serialized into a single `ses_<id>.json`.
363+
* `snapshot()` rewrites the entire spans array on every event, so an unbounded
364+
* long-lived session would grow the file without limit and pay O(n) per write
365+
* (O(n²) over the session). When a trace exceeds this, serialization keeps the
366+
* head (early context: prompt + first tools) and the tail (most recent
367+
* activity) and elides the middle with a single marker span — bounding both
368+
* file size and per-event write cost. In-memory spans are untouched; only the
369+
* on-disk projection is capped. Override with `ALTIMATE_TRACE_MAX_SPANS`.
370+
*/
371+
export const MAX_SERIALIZED_SPANS = (() => {
372+
const raw = parseInt(process.env["ALTIMATE_TRACE_MAX_SPANS"] ?? "", 10)
373+
return Number.isFinite(raw) && raw > 0 ? raw : 5000
374+
})()
375+
376+
/**
377+
* Bound the spans written to disk to `cap` while preserving the most useful
378+
* context: keep the head (root span, prompt, first tool calls) and the tail
379+
* (most recent activity), and replace the elided middle with one marker span.
380+
* Returns the input unchanged when it's already within the cap.
381+
*/
382+
export function capSpansForSerialization(spans: TraceSpan[], cap: number = MAX_SERIALIZED_SPANS): TraceSpan[] {
383+
if (cap <= 0 || spans.length <= cap) return spans
384+
const headCount = Math.max(1, Math.floor(cap * 0.3))
385+
const tailCount = Math.max(1, cap - headCount - 1) // reserve one slot for the marker
386+
// Only elide if the result is actually smaller than the input (+1 for the
387+
// marker we'd add) — otherwise there's nothing to gain.
388+
if (headCount + tailCount + 1 >= spans.length) return spans
389+
let head = spans.slice(0, headCount)
390+
const tail = spans.slice(spans.length - tailCount)
391+
// Guarantee the structural root (session) span survives the cut even if it
392+
// isn't in the head slice — rehydrate and the viewer's tree both require it,
393+
// and the elision marker is parented to it. In practice the root is index 0
394+
// (pushed first), so this is defensive, but it makes the invariant explicit
395+
// instead of silently depending on span ordering.
396+
const rootSpan = spans.find((s) => s.parentSpanId === null) ?? null
397+
if (rootSpan && !head.some((s) => s.spanId === rootSpan.spanId) && !tail.some((s) => s.spanId === rootSpan.spanId)) {
398+
head = [rootSpan, ...head.slice(0, headCount - 1)]
399+
}
400+
const elided = spans.length - head.length - tail.length
401+
const rootId = rootSpan?.spanId ?? null
402+
const anchor = head[head.length - 1]
403+
const anchorTime = anchor?.endTime ?? anchor?.startTime ?? 0
404+
const marker: TraceSpan = {
405+
spanId: `elided-${head.length}-${tail.length}-of-${spans.length}`,
406+
parentSpanId: rootId,
407+
name: `… ${elided} spans elided (trace exceeded ${cap} spans) …`,
408+
kind: "span",
409+
startTime: anchorTime,
410+
endTime: anchorTime,
411+
status: "ok",
412+
attributes: { elided, totalSpans: spans.length },
413+
}
414+
return [...head, marker, ...tail]
415+
}
352416
// altimate_change end
353417

354418
export class Trace {
@@ -592,6 +656,9 @@ export class Trace {
592656
s.endTime = now
593657
s.status = "error"
594658
s.statusMessage = "interrupted — altimate-code restarted before this step finished recording; not an agent failure"
659+
// Distinguish a recorder restart from a real failure so the viewer and
660+
// error aggregations don't paint this red or count it as an incident.
661+
s.interrupted = true
595662
}
596663
}
597664
this.endTraceStarted = false
@@ -927,6 +994,8 @@ export class Trace {
927994
snapshotMetadata = this.metadata
928995
}
929996

997+
snapshotSpans = capSpansForSerialization(snapshotSpans)
998+
930999
return {
9311000
version: 2,
9321001
traceId: this.traceId,

packages/opencode/src/altimate/observability/viewer.ts

Lines changed: 20 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -196,6 +196,7 @@ body { font-family: -apple-system, BlinkMacSystemFont, 'Segoe UI', Helvetica, Ar
196196
.wf-preview .pv-tag.model { background: rgba(77,142,255,0.12); color: var(--secondary); }
197197
.wf-preview .pv-tag.tok { background: rgba(74,222,128,0.12); color: var(--green); }
198198
.wf-preview .pv-tag.err { background: rgba(248,113,113,0.12); color: var(--red); }
199+
.wf-preview .pv-tag.warn { background: rgba(251,191,36,0.12); color: var(--orange); }
199200
.wf-bar-c { flex: 1; height: 18px; position: relative; overflow: hidden; }
200201
.wf-bar { position: absolute; height: 100%; border-radius: 3px; min-width: 3px; opacity: 0.85; display: flex; align-items: center; padding-left: 4px; }
201202
.wf-bar.generation { background: var(--secondary); }
@@ -222,6 +223,7 @@ body { font-family: -apple-system, BlinkMacSystemFont, 'Segoe UI', Helvetica, Ar
222223
.tree-preview .pv-tag.model { background: rgba(77,142,255,0.12); color: var(--secondary); }
223224
.tree-preview .pv-tag.tok { background: rgba(74,222,128,0.12); color: var(--green); }
224225
.tree-preview .pv-tag.err { background: rgba(248,113,113,0.12); color: var(--red); }
226+
.tree-preview .pv-tag.warn { background: rgba(251,191,36,0.12); color: var(--orange); }
225227
.tree-detail { margin-top: 8px; padding: 8px; background: var(--bg); border: 1px solid var(--border); border-radius: 6px; font-size: 12px; display: none; }
226228
.tree-detail.open { display: block; }
227229
@@ -443,7 +445,9 @@ var icons = { session: '\\u25A0', generation: '\\u2B50', tool: '\\u2692', text:
443445
function getPreview(span) {
444446
var parts = [];
445447
if (span.status === 'error' && span.statusMessage) {
446-
return '<span class="pv-tag err">\\u2718</span>' + e((span.statusMessage || '').slice(0, 120));
448+
// Interrupted = recorder restart, not a real failure: amber warn, not red.
449+
var tag = span.interrupted ? '<span class="pv-tag warn">\\u26A0</span>' : '<span class="pv-tag err">\\u2718</span>';
450+
return tag + e((span.statusMessage || '').slice(0, 120));
447451
}
448452
if (span.kind === 'tool') {
449453
var inp = span.input;
@@ -467,7 +471,7 @@ function getPreview(span) {
467471
}
468472
}
469473
}
470-
if (span.status === 'error') parts.unshift('<span class="pv-tag err">\\u2718</span>');
474+
if (span.status === 'error') parts.unshift(span.interrupted ? '<span class="pv-tag warn">\\u26A0</span>' : '<span class="pv-tag err">\\u2718</span>');
471475
} else if (span.kind === 'generation') {
472476
if (span.model && span.model.modelId) parts.push('<span class="pv-tag model">' + e(span.model.modelId) + '</span>');
473477
if (span.tokens && span.tokens.total) parts.push('<span class="pv-tag tok">' + Number(span.tokens.total).toLocaleString() + ' tok</span>');
@@ -487,8 +491,9 @@ function showDetail(span) {
487491
var dur = (span.endTime || Date.now()) - (span.startTime || 0);
488492
var h = '<div class="detail-panel"><h3>' + e(span.name) + '</h3><dl class="dg">';
489493
h += '<dt>Kind</dt><dd>' + e(span.kind||'') + '</dd>';
490-
h += '<dt>Status</dt><dd' + (span.status==='error'?' style="color:var(--red)"':'') + '>' + e(span.status||'') + '</dd>';
491-
if (span.statusMessage) h += '<dt>Error</dt><dd style="color:var(--red)">' + e(span.statusMessage) + '</dd>';
494+
var statusColor = span.interrupted ? 'var(--orange)' : (span.status==='error' ? 'var(--red)' : '');
495+
h += '<dt>Status</dt><dd' + (statusColor?' style="color:'+statusColor+'"':'') + '>' + e(span.interrupted ? 'interrupted' : (span.status||'')) + '</dd>';
496+
if (span.statusMessage) h += '<dt>' + (span.interrupted ? 'Interrupted' : 'Error') + '</dt><dd style="color:' + (span.interrupted ? 'var(--orange)' : 'var(--red)') + '">' + e(span.statusMessage) + '</dd>';
492497
h += '<dt>Duration</dt><dd>' + fd(dur) + '</dd>';
493498
if (span.model) {
494499
if (span.model.modelId) h += '<dt>Model</dt><dd>' + e(span.model.modelId) + '</dd>';
@@ -565,7 +570,10 @@ function showDetail(span) {
565570
// --- Classify all tool spans upfront ---
566571
var toolSpans = nonSession.filter(function(sp) { return sp.kind === 'tool'; });
567572
var genSpans = nonSession.filter(function(sp) { return sp.kind === 'generation'; });
568-
var errSpans = nonSession.filter(function(sp) { return sp.status === 'error'; });
573+
// Reconstructed (interrupted) spans keep status:'error' for boundary
574+
// visibility, but they reflect a recorder restart — exclude them from the
575+
// session error count so a clean session isn't reported as failed.
576+
var errSpans = nonSession.filter(function(sp) { return sp.status === 'error' && !sp.interrupted; });
569577
570578
// Categorize files: changed (edit/write) vs read
571579
var changedFiles = {};
@@ -1239,12 +1247,12 @@ function showDetail(span) {
12391247
var dur = (span.endTime || Date.now()) - (span.startTime||0);
12401248
var left = (st / tTotal * 100).toFixed(2);
12411249
var width = Math.max(0.5, dur / tTotal * 100).toFixed(2);
1242-
var cls = span.status === 'error' ? 'error' : e(span.kind);
1250+
var cls = (span.status === 'error' && !span.interrupted) ? 'error' : e(span.kind);
12431251
var row = document.createElement('div');
12441252
row.className = 'wf-row';
12451253
row.setAttribute('data-idx', String(idx));
12461254
if (span.spanId) row.setAttribute('data-span-id', span.spanId);
1247-
var iconCls = span.status === 'error' ? 'error' : e(span.kind);
1255+
var iconCls = (span.status === 'error' && !span.interrupted) ? 'error' : e(span.kind);
12481256
var pv = getPreview(span);
12491257
row.innerHTML = '<div class="wf-icon ' + iconCls + '">' + (icons[span.kind]||'\\u2022') + '</div>' +
12501258
'<div class="wf-info"><div class="wf-name">' + e(span.name) + '</div>' + (pv ? '<div class="wf-preview">' + pv + '</div>' : '') + '</div>' +
@@ -1278,7 +1286,8 @@ function showDetail(span) {
12781286
meta.push(fd(dur));
12791287
if (span.tokens) meta.push(Number(span.tokens.total||0) + ' tok');
12801288
if (span.cost) meta.push(fc(span.cost));
1281-
if (span.status === 'error') meta.push('<span style="color:var(--red)">error</span>');
1289+
if (span.interrupted) meta.push('<span style="color:var(--orange)">interrupted</span>');
1290+
else if (span.status === 'error') meta.push('<span style="color:var(--red)">error</span>');
12821291
html += '<div class="tree-node"><div class="tree-item" data-idx="' + idx + '">';
12831292
html += '<div class="tree-head">';
12841293
html += '<span class="tree-type ' + e(span.kind) + '">' + e(span.kind) + '</span>';
@@ -1390,7 +1399,7 @@ function showDetail(span) {
13901399
if (span.kind === 'session') return;
13911400
var idx = spans.indexOf(span);
13921401
var ts = span.startTime ? new Date(span.startTime).toISOString().slice(11,23) : '';
1393-
var kindCls = span.status === 'error' ? 'error' : e(span.kind);
1402+
var kindCls = (span.status === 'error' && !span.interrupted) ? 'error' : e(span.kind);
13941403
html += '<div class="log-entry" data-idx="' + idx + '">';
13951404
html += '<span class="log-ts">' + ts + '</span>';
13961405
var logIcon = span.kind === 'generation' ? '\\u2B50' : span.kind === 'tool' ? '\\u2692' : '\\u25A0';
@@ -1400,7 +1409,8 @@ function showDetail(span) {
14001409
if (span.tokens) html += ' <span style="color:var(--dim);font-size:11px">' + Number(span.tokens.total||0) + ' tok</span>';
14011410
if (span.cost) html += ' <span style="color:var(--orange);font-size:11px">' + fc(span.cost) + '</span>';
14021411
if (span.tool && span.tool.durationMs != null) html += ' <span style="color:var(--dim);font-size:11px">' + fd(span.tool.durationMs) + '</span>';
1403-
if (span.status === 'error') html += ' <span style="color:var(--red);font-size:11px">\\u2718 ' + e((span.statusMessage||'').slice(0,100)) + '</span>';
1412+
if (span.interrupted) html += ' <span style="color:var(--orange);font-size:11px">\\u26A0 ' + e((span.statusMessage||'').slice(0,100)) + '</span>';
1413+
else if (span.status === 'error') html += ' <span style="color:var(--red);font-size:11px">\\u2718 ' + e((span.statusMessage||'').slice(0,100)) + '</span>';
14041414
if (span.kind === 'tool' && span.input) {
14051415
var logPv = getPreview(span);
14061416
if (logPv) html += '<div class="log-data" style="color:var(--cyan);opacity:0.7;max-height:none">' + logPv + '</div>';

packages/opencode/src/cli/cmd/tui/worker.ts

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,14 @@ const eventStream = {
4747
abort: undefined as AbortController | undefined,
4848
}
4949

50+
// altimate_change start — trace: monotonic stream generation. Bumped on every
51+
// startEventStream() so an in-flight getOrCreateTrace() can detect that its
52+
// owning stream was torn down while it was suspended at an await. Keyed on a
53+
// counter rather than the AbortController's object identity so the guard does
54+
// not silently depend on startEventStream always allocating a fresh controller.
55+
let streamGeneration = 0
56+
// altimate_change end
57+
5058
// altimate_change start — trace: per-session traces
5159
const sessionTraces = new Map<string, Trace>()
5260
const sessionUserMsgIds = new Map<string, Set<string>>() // Per-session user message IDs (cleaned up on session end)
@@ -83,6 +91,13 @@ async function loadTracingConfig() {
8391
async function getOrCreateTrace(sessionID: string): Promise<Trace | null> {
8492
if (!sessionID || !tracingEnabled) return null
8593
if (sessionTraces.has(sessionID)) return sessionTraces.get(sessionID)!
94+
// altimate_change start — capture the stream generation that owns this call so
95+
// we can detect a concurrent startEventStream() (e.g. setWorkspace) that
96+
// aborted us and cleared the cache while we were suspended at the rehydrate
97+
// await below. A counter (not AbortController identity) so we don't depend on
98+
// startEventStream's allocation strategy.
99+
const generationAtEntry = streamGeneration
100+
// altimate_change end
86101
try {
87102
if (sessionTraces.size >= MAX_TRACES) {
88103
const oldest = sessionTraces.keys().next().value
@@ -106,9 +121,21 @@ async function getOrCreateTrace(sessionID: string): Promise<Trace | null> {
106121
trace.startTrace(sessionID, {})
107122
}
108123
// altimate_change end
124+
// altimate_change start — if a new stream replaced ours while we were
125+
// awaiting rehydrate, this Trace belongs to a stream that's already been
126+
// aborted and its cache cleared. Inserting it now would resurrect an orphan
127+
// writer into the freshly-cleared map. Discard it and defer to whatever the
128+
// live stream has. The check and the set below run in the same synchronous
129+
// turn (no await between them), so the insert can't race a later
130+
// startEventStream — this closes the suspend-at-await hole specifically.
131+
if (streamGeneration !== generationAtEntry) {
132+
void trace.endTrace().catch(() => {})
133+
return sessionTraces.get(sessionID) ?? null
134+
}
109135
Trace.setActive(trace)
110136
sessionTraces.set(sessionID, trace)
111137
return trace
138+
// altimate_change end
112139
} catch {
113140
return null
114141
}
@@ -117,6 +144,10 @@ async function getOrCreateTrace(sessionID: string): Promise<Trace | null> {
117144

118145
const startEventStream = (input: { directory: string; workspaceID?: string }) => {
119146
if (eventStream.abort) eventStream.abort.abort()
147+
// altimate_change start — new stream generation; invalidates any in-flight
148+
// getOrCreateTrace() suspended at its rehydrate await (see generationAtEntry).
149+
streamGeneration++
150+
// altimate_change end
120151
// Clear stale per-stream trace state before starting a new stream instance
121152
for (const [, trace] of sessionTraces) {
122153
void trace.endTrace().catch(() => {})

0 commit comments

Comments
 (0)