Skip to content

Commit 99bcd24

Browse files
author
bcode
committed
cleanup: remove TEMP stderr diagnostics from rc3-rc5
Remove the [bcode]/[bcode-laminar] stderr lines that helped localize the headless V4 shutdown hook bugs. The actual fixes (async shutdown hook, pending-flush tracking, drop of sdk.shutdown bus race, drop of broken trace.getTracerProvider().forceFlush fallback) stay. Verified rc6 on V4 staging: trace b2837d1e-... has the bcode-laminar turn span landed with all session.llm/ai.streamText.doStream/bash spans correctly parented. Multi-turn trace 4f53f62c-... (10 LLM rounds) also clean. Only remaining orphan is the v4.run cloud-control-plane span (separate known bug -- CP emits to wrong Laminar project).
1 parent 594023b commit 99bcd24

2 files changed

Lines changed: 32 additions & 108 deletions

File tree

packages/bcode-laminar/src/plugin.ts

Lines changed: 18 additions & 74 deletions
Original file line numberDiff line numberDiff line change
@@ -90,92 +90,44 @@ export const LaminarPlugin: Plugin = ({ client }) => {
9090
config.experimental = { ...(config.experimental ?? {}), openTelemetry: true }
9191
}
9292
},
93-
// Synchronous end-of-turn drain. The bus-based session.idle /
94-
// server.instance.disposed events race with Effect scope teardown in
95-
// headless `bcode run` mode and don't reliably deliver, so the turn span
96-
// was historically being left un-ended and never exported. The host calls
97-
// this hook from its top-level finally before forceFlush, so span.end()
98-
// here gets its export drained by the host's existing forceFlush race.
93+
// End-of-process drain. The host calls this from its top-level finally
94+
// before `process.exit()`. Awaits any forceFlush Promises kicked off by
95+
// bus event handlers (session.idle, session.deleted) — those are orphan
96+
// microtasks from the host's perspective and `process.exit()` would kill
97+
// their in-flight OTLP HTTP exports otherwise. Host bounds this with
98+
// `Promise.race([hooks, 3000ms])` so a wedged exporter cannot hang exit.
9999
shutdown: async () => {
100-
// End any still-open turn spans, then drain. Awaits both an explicit
101-
// forceFlush AND any pendingFlushes kicked off by the bus event
102-
// handlers (session.idle, session.deleted) that the host doesn't
103-
// otherwise wait for. The host's `Promise.race([hooks, 3000ms])`
104-
// bounds this so a wedged exporter cannot hang `process.exit()`.
105-
//
106-
// The pendingFlushes set is the critical fix: session.idle's await
107-
// on processor.forceFlush() is an orphan microtask from the host's
108-
// perspective — it kicks off the OTLP HTTP export but `process.exit()`
109-
// would kill the request mid-flight without us tracking it here.
110-
//
111-
// stderr writes go to v4-worker's bcode-output-<runId>.log so cloud
112-
// verification can see whether this path executed. Temporary, will
113-
// be removed once headless V4 telemetry is settled.
114-
const sessionIds = Object.keys(sessionCurrentTurnSpan)
115-
process.stderr.write(
116-
`[bcode-laminar] shutdown: ending ${sessionIds.length} open turn span(s), waiting on ${pendingFlushes.size} pending flush(es)\n`,
117-
)
118-
for (const sessionId of sessionIds) {
100+
for (const sessionId of Object.keys(sessionCurrentTurnSpan)) {
119101
const span = sessionCurrentTurnSpan[sessionId]
120102
if (!span) continue
121-
try {
122-
span.end()
123-
} catch (err) {
124-
process.stderr.write(
125-
`[bcode-laminar] span.end threw for session ${sessionId}: ${(err as Error).message}\n`,
126-
)
127-
}
103+
span.end()
128104
delete sessionCurrentTurnSpan[sessionId]
129105
}
130-
const start = Date.now()
131-
// Kick a final flush AND wait for any in-flight ones from bus handlers.
132106
trackFlush(processor.forceFlush())
133-
try {
134-
await Promise.all(Array.from(pendingFlushes))
135-
process.stderr.write(
136-
`[bcode-laminar] shutdown: all flushes done in ${Date.now() - start}ms\n`,
137-
)
138-
} catch (err) {
139-
process.stderr.write(
140-
`[bcode-laminar] shutdown: flush threw after ${Date.now() - start}ms: ${(err as Error).message}\n`,
141-
)
142-
}
107+
await Promise.all(Array.from(pendingFlushes))
143108
},
144109
event: async ({ event }) => {
145110
switch (event.type) {
146111
case "session.idle": {
147112
const sessionId = event.properties.sessionID
148113
const span = sessionCurrentTurnSpan[sessionId]
149114
if (span) {
150-
const sid = span.spanContext().spanId
151-
process.stderr.write(
152-
`[bcode-laminar] session.idle: ending turn span ${sid} session=${sessionId}\n`,
153-
)
154115
span.end()
155116
delete sessionCurrentTurnSpan[sessionId]
156-
} else {
157-
process.stderr.write(
158-
`[bcode-laminar] session.idle: no turn span for session=${sessionId}\n`,
159-
)
160117
}
161-
// Track the flush Promise so the sync shutdown hook can await it
162-
// before process.exit. Fire-and-forget from this fiber's POV.
118+
// Track the flush Promise so the shutdown hook can await it before
119+
// `process.exit()`. Fire-and-forget from this fiber's POV.
163120
trackFlush(processor.forceFlush())
164121
break
165122
}
166123
case "server.instance.disposed": {
167124
// End any turn spans still open so they're queued before the host
168-
// calls our `shutdown` hook.
169-
//
170-
// Do NOT call `sdk.shutdown()` here. It unregisters the global
171-
// TracerProvider AND closes the BatchSpanProcessor — both
172-
// observed to fire mid-await in headless `bcode run` mode, after
173-
// which the sync `shutdown` hook's `processor.forceFlush()` is a
174-
// no-op and turn spans are silently dropped. The sync hook is now
175-
// the single drain point; this handler just ends spans.
176-
const entries = Object.entries(sessionCurrentTurnSpan)
177-
process.stderr.write(`[bcode-laminar] server.instance.disposed: ending ${entries.length} open turn span(s)\n`)
178-
for (const [sessionId, span] of entries) {
125+
// calls our `shutdown` hook. Do NOT call `sdk.shutdown()` here —
126+
// it unregisters the global TracerProvider and closes the BSP,
127+
// both observed to fire mid-await in headless `bcode run` mode
128+
// and silently drop the just-ended turn span. The shutdown hook
129+
// is the single drain point.
130+
for (const [sessionId, span] of Object.entries(sessionCurrentTurnSpan)) {
179131
span.end()
180132
delete sessionCurrentTurnSpan[sessionId]
181133
}
@@ -210,12 +162,7 @@ export const LaminarPlugin: Plugin = ({ client }) => {
210162
const isSubagent = Object.values(subagentSessionIds).some((children) =>
211163
children.has(sessionID),
212164
)
213-
if (isSubagent || sessionCurrentTurnSpan[sessionID]) {
214-
process.stderr.write(
215-
`[bcode-laminar] chat.message: skip (isSubagent=${isSubagent}, hasOpen=${!!sessionCurrentTurnSpan[sessionID]}) session=${sessionID}\n`,
216-
)
217-
return
218-
}
165+
if (isSubagent || sessionCurrentTurnSpan[sessionID]) return
219166

220167
const span = startTurnSpan({
221168
name: "turn",
@@ -232,9 +179,6 @@ export const LaminarPlugin: Plugin = ({ client }) => {
232179
},
233180
})
234181
sessionCurrentTurnSpan[sessionID] = span
235-
process.stderr.write(
236-
`[bcode-laminar] chat.message: created turn span ${span.spanContext().spanId} session=${sessionID}\n`,
237-
)
238182
},
239183
})
240184
}

packages/opencode/src/index.ts

Lines changed: 14 additions & 34 deletions
Original file line numberDiff line numberDiff line change
@@ -249,52 +249,32 @@ try {
249249
}
250250
process.exitCode = 1
251251
} finally {
252-
// Give plugins a synchronous chance to end any open OTel spans before the
253-
// exporter drain below. The bus-based session.idle / server.instance.disposed
254-
// events race with Effect scope teardown and don't reliably reach plugin
255-
// subscribers in headless `bcode run` mode, so we expose a direct sync hook
256-
// (see packages/opencode/src/plugin/index.ts pluginShutdownHooks).
257-
// The import is wrapped so a module-load failure can't strand the process
258-
// before forceFlush + process.exit() below.
259-
// Plugin shutdown hooks are the single drain point. Each hook may return
260-
// a Promise (e.g. bcode-laminar returning its BatchSpanProcessor's
261-
// forceFlush) which we await with a 3s budget so a wedged exporter can't
262-
// hang `process.exit()`. The previous fallback that called
263-
// `trace.getTracerProvider().forceFlush()` was a no-op — the OTel API
264-
// proxy provider doesn't expose forceFlush, and the bus-driven
265-
// `server.instance.disposed` handler had often already called
266-
// `sdk.shutdown()` and unregistered the global by the time we got here.
252+
// Plugin shutdown hooks are the single drain point for OTel-based plugins
253+
// (e.g. bcode-laminar). Each hook may return a Promise — bcode-laminar
254+
// returns its BatchSpanProcessor's forceFlush plus any in-flight flushes
255+
// kicked off by bus event handlers — which we await with a 3s budget so
256+
// a wedged exporter cannot hang `process.exit()`.
267257
//
268-
// stderr writes go to v4-worker's bcode-output-<runId>.log so cloud
269-
// verification can see whether this path executed and how long it took.
270-
// Will be removed once headless V4 telemetry is fully settled.
258+
// The host-side fallback that called `trace.getTracerProvider().forceFlush()`
259+
// was dropped: the OTel API's ProxyTracerProvider doesn't expose forceFlush,
260+
// and the bus-driven `server.instance.disposed` handler used to call
261+
// `sdk.shutdown()` and unregister the global before this finally ran.
262+
// The plugin-owned drain (with closure ref to its own processor) is
263+
// immune to both issues.
271264
try {
272265
const { pluginShutdownHooks } = await import("./plugin")
273-
const hooks = Array.from(pluginShutdownHooks)
274-
process.stderr.write(`[bcode] shutdown: invoking ${hooks.length} plugin shutdown hook(s)\n`)
275-
const start = Date.now()
276266
await Promise.race([
277267
Promise.allSettled(
278-
hooks.map((hook) =>
268+
Array.from(pluginShutdownHooks).map((hook) =>
279269
Promise.resolve()
280270
.then(hook)
281-
.catch((err: Error) => {
282-
process.stderr.write(`[bcode] shutdown: hook threw: ${err.message}\n`)
283-
Log.Default.error("plugin shutdown hook failed", { error: err })
284-
}),
271+
.catch((err: Error) => Log.Default.error("plugin shutdown hook failed", { error: err })),
285272
),
286273
),
287-
new Promise<void>((resolve) =>
288-
setTimeout(() => {
289-
process.stderr.write(`[bcode] shutdown: timed out after 3000ms\n`)
290-
resolve()
291-
}, 3000),
292-
),
274+
new Promise<void>((resolve) => setTimeout(resolve, 3000)),
293275
])
294-
process.stderr.write(`[bcode] shutdown: done in ${Date.now() - start}ms\n`)
295276
} catch (err) {
296277
Log.Default.error("plugin shutdown import failed", { error: err })
297-
process.stderr.write(`[bcode] shutdown: import failed: ${(err as Error).message}\n`)
298278
}
299279
// Some subprocesses don't react properly to SIGTERM and similar signals.
300280
// Most notably, some docker-container-based MCP servers don't handle such signals unless

0 commit comments

Comments
 (0)