From 6c848a7bca237ab60e7035244d4889dae44560ca Mon Sep 17 00:00:00 2001 From: Marc Seiler Date: Tue, 24 Mar 2026 14:17:55 -0400 Subject: [PATCH 1/4] feat(tracing): add OpenTelemetry traces with gen_ai.* and tool spans Adds a TracerProvider backed by OTLP/gRPC and implements full trace instrumentation across session, LLM message, and tool lifecycles. - session.created starts an opencode.session root span; parentID is used to nest subagent sessions under their parent session span - message.updated starts a gen_ai.chat span (SpanKind.CLIENT) with gen_ai.system / gen_ai.request.model attributes; on completion the span is annotated with gen_ai.usage.* token counts, cost, and finish_reason then ended with OK or ERROR status - message.part.updated (tool, running) starts an opencode.tool child span under the session span; completed/error ends it with the appropriate status and result size or error message - Out-of-order tool events (completed without prior running) are handled gracefully with a best-effort span started and immediately ended - sweepSession now ends any orphaned tool and message spans with ERROR status on session.idle and session.error, addressing the orphaned span edge case documented in issue #19 - TracerProvider.shutdown() included in the SIGTERM/SIGINT/beforeExit shutdown sequence Adds 34 new span tests; all 185 tests pass. Closes #19 --- bun.lock | 4 + package.json | 2 + src/handlers/message.ts | 225 ++++++++++++++------ src/handlers/session.ts | 66 +++++- src/index.ts | 30 ++- src/otel.ts | 18 +- src/types.ts | 6 +- tests/handlers/session.test.ts | 14 +- tests/handlers/spans.test.ts | 375 +++++++++++++++++++++++++++++++++ tests/helpers.ts | 66 +++++- 10 files changed, 728 insertions(+), 78 deletions(-) create mode 100644 tests/handlers/spans.test.ts diff --git a/bun.lock b/bun.lock index 7260ec2..cefa465 100644 --- a/bun.lock +++ b/bun.lock @@ -10,9 +10,11 @@ "@opentelemetry/api": "^1.9.0", "@opentelemetry/exporter-logs-otlp-grpc": "^0.213.0", "@opentelemetry/exporter-metrics-otlp-grpc": "^0.213.0", + "@opentelemetry/exporter-trace-otlp-grpc": "^0.213.0", "@opentelemetry/resources": "^2.6.0", "@opentelemetry/sdk-logs": "^0.213.0", "@opentelemetry/sdk-metrics": "^2.6.0", + "@opentelemetry/sdk-trace-base": "^2.6.0", "@opentelemetry/semantic-conventions": "^1.40.0", "typescript": "^5.9.3", }, @@ -44,6 +46,8 @@ "@opentelemetry/exporter-metrics-otlp-http": ["@opentelemetry/exporter-metrics-otlp-http@0.213.0", "", { "dependencies": { "@opentelemetry/core": "2.6.0", "@opentelemetry/otlp-exporter-base": "0.213.0", "@opentelemetry/otlp-transformer": "0.213.0", "@opentelemetry/resources": "2.6.0", "@opentelemetry/sdk-metrics": "2.6.0" }, "peerDependencies": { "@opentelemetry/api": "^1.3.0" } }, "sha512-yw3fTIw4KQIRXC/ZyYQq5gtA3Ogfdfz/g5HVgleobQAcjUUE8Nj3spGMx8iQPp+S+u6/js7BixufRkXhzLmpJA=="], + "@opentelemetry/exporter-trace-otlp-grpc": ["@opentelemetry/exporter-trace-otlp-grpc@0.213.0", "", { "dependencies": { "@grpc/grpc-js": "^1.14.3", "@opentelemetry/core": "2.6.0", "@opentelemetry/otlp-exporter-base": "0.213.0", "@opentelemetry/otlp-grpc-exporter-base": "0.213.0", "@opentelemetry/otlp-transformer": "0.213.0", "@opentelemetry/resources": "2.6.0", "@opentelemetry/sdk-trace-base": "2.6.0" }, "peerDependencies": { "@opentelemetry/api": "^1.3.0" } }, "sha512-L8y6piP4jBIIx1Nv7/9hkx25ql6/Cro/kQrs+f9e8bPF0Ar5Dm991v7PnbtubKz6Q4fT872H56QXUWVnz/Cs4Q=="], + "@opentelemetry/otlp-exporter-base": ["@opentelemetry/otlp-exporter-base@0.213.0", "", { "dependencies": { "@opentelemetry/core": "2.6.0", "@opentelemetry/otlp-transformer": "0.213.0" }, "peerDependencies": { "@opentelemetry/api": "^1.3.0" } }, "sha512-MegxAP1/n09Ob2dQvY5NBDVjAFkZRuKtWKxYev1R2M8hrsgXzQGkaMgoEKeUOyQ0FUyYcO29UOnYdQWmWa0PXg=="], "@opentelemetry/otlp-grpc-exporter-base": ["@opentelemetry/otlp-grpc-exporter-base@0.213.0", "", { "dependencies": { "@grpc/grpc-js": "^1.14.3", "@opentelemetry/core": "2.6.0", "@opentelemetry/otlp-exporter-base": "0.213.0", "@opentelemetry/otlp-transformer": "0.213.0" }, "peerDependencies": { "@opentelemetry/api": "^1.3.0" } }, "sha512-XgRGuLE9usFNlnw2lgMIM4HTwpcIyjdU/xPoJ8v3LbBLBfjaDkIugjc9HoWa7ZSJ/9Bhzgvm/aD0bGdYUFgnTw=="], diff --git a/package.json b/package.json index e80a617..185b33b 100644 --- a/package.json +++ b/package.json @@ -41,9 +41,11 @@ "@opentelemetry/api": "^1.9.0", "@opentelemetry/exporter-logs-otlp-grpc": "^0.213.0", "@opentelemetry/exporter-metrics-otlp-grpc": "^0.213.0", + "@opentelemetry/exporter-trace-otlp-grpc": "^0.213.0", "@opentelemetry/resources": "^2.6.0", "@opentelemetry/sdk-logs": "^0.213.0", "@opentelemetry/sdk-metrics": "^2.6.0", + "@opentelemetry/sdk-trace-base": "^2.6.0", "@opentelemetry/semantic-conventions": "^1.40.0", "typescript": "^5.9.3" }, diff --git a/src/handlers/message.ts b/src/handlers/message.ts index 6315c4a..1ae2af7 100644 --- a/src/handlers/message.ts +++ b/src/handlers/message.ts @@ -1,4 +1,5 @@ import { SeverityNumber } from "@opentelemetry/api-logs" +import { SpanStatusCode, SpanKind, context, trace } from "@opentelemetry/api" import type { AssistantMessage, EventMessageUpdated, EventMessagePartUpdated, ToolPart } from "@opencode-ai/sdk" import { errorSummary, setBoundedMap, accumulateSessionTotals, isMetricEnabled } from "../util.ts" import type { HandlerContext } from "../types.ts" @@ -13,8 +14,8 @@ type SubtaskPart = { } /** - * Handles a completed assistant message: increments token and cost counters and emits - * either an `api_request` or `api_error` log event depending on whether the message errored. + * Handles a completed assistant message: increments token and cost counters, emits + * either an `api_request` or `api_error` log event, and ends the LLM span for this message. * The `agent` attribute is sourced from the session totals, which are populated by the * `chat.message` hook when the user prompt is received. */ @@ -75,6 +76,27 @@ export function handleMessageUpdated(e: EventMessageUpdated, ctx: HandlerContext cost_usd: assistant.cost, }) + const msgSpan = ctx.messageSpans.get(assistant.id) + if (msgSpan) { + msgSpan.setAttributes({ + "gen_ai.usage.input_tokens": assistant.tokens.input, + "gen_ai.usage.output_tokens": assistant.tokens.output, + "gen_ai.usage.reasoning_tokens": assistant.tokens.reasoning, + "gen_ai.usage.cache_read_tokens": assistant.tokens.cache.read, + "gen_ai.usage.cache_creation_tokens": assistant.tokens.cache.write, + "gen_ai.response.finish_reason": assistant.error ? "error" : "stop", + cost_usd: assistant.cost, + duration_ms: duration, + }) + if (assistant.error) { + msgSpan.setStatus({ code: SpanStatusCode.ERROR, message: errorSummary(assistant.error) }) + } else { + msgSpan.setStatus({ code: SpanStatusCode.OK }) + } + msgSpan.end(assistant.time.completed) + ctx.messageSpans.delete(assistant.id) + } + if (assistant.error) { ctx.logger.emit({ severityNumber: SeverityNumber.ERROR, @@ -137,9 +159,13 @@ export function handleMessageUpdated(e: EventMessageUpdated, ctx: HandlerContext /** * Tracks tool execution time between `running` and `completed`/`error` part updates, - * records a `tool.duration` histogram measurement, and emits a `tool_result` log event. - * Also handles `subtask` parts, incrementing the sub-agent invocation counter and emitting - * a `subtask_invoked` log event. + * records a `tool.duration` histogram measurement, manages the tool child span, and emits + * a `tool_result` log event. Also handles `subtask` parts, incrementing the sub-agent + * invocation counter and emitting a `subtask_invoked` log event. + * + * For tool spans: on `running` a child span of the current session span is started and stored + * in `pendingToolSpans`. On `completed`/`error` the span is ended with appropriate status. + * If no `running` event was seen (out-of-order), a best-effort span is started and immediately ended. */ export function handleMessagePartUpdated(e: EventMessagePartUpdated, ctx: HandlerContext) { const part = e.properties.part @@ -175,70 +201,151 @@ export function handleMessagePartUpdated(e: EventMessagePartUpdated, ctx: Handle }) } - if (part.type !== "tool") return + if (part.type === "tool") { + const toolPart = part as ToolPart + const key = `${toolPart.sessionID}:${toolPart.callID}` - const toolPart = part as ToolPart - const key = `${toolPart.sessionID}:${toolPart.callID}` + if (toolPart.state.status === "running") { + const sessionSpan = ctx.sessionSpans.get(toolPart.sessionID) + const parentCtx = sessionSpan + ? trace.setSpan(context.active(), sessionSpan) + : context.active() - if (toolPart.state.status === "running") { - setBoundedMap(ctx.pendingToolSpans, key, { - tool: toolPart.tool, - sessionID: toolPart.sessionID, - startMs: toolPart.state.time.start, - }) - ctx.log("debug", "otel: tool span started", { sessionID: toolPart.sessionID, tool: toolPart.tool, key }) - return - } + const toolSpan = ctx.tracer.startSpan( + `opencode.tool ${toolPart.tool}`, + { + startTime: toolPart.state.time.start, + kind: SpanKind.INTERNAL, + attributes: { + "session.id": toolPart.sessionID, + "tool.name": toolPart.tool, + ...ctx.commonAttrs, + }, + }, + parentCtx, + ) + setBoundedMap(ctx.pendingToolSpans, key, { + tool: toolPart.tool, + sessionID: toolPart.sessionID, + startMs: toolPart.state.time.start, + span: toolSpan, + }) + ctx.log("debug", "otel: tool span started", { sessionID: toolPart.sessionID, tool: toolPart.tool, key }) + return + } - if (toolPart.state.status !== "completed" && toolPart.state.status !== "error") return + if (toolPart.state.status !== "completed" && toolPart.state.status !== "error") return - const span = ctx.pendingToolSpans.get(key) - ctx.pendingToolSpans.delete(key) - const start = span?.startMs ?? toolPart.state.time.start - const end = toolPart.state.time.end - if (end === undefined) return - const duration_ms = end - start - const success = toolPart.state.status === "completed" + const pending = ctx.pendingToolSpans.get(key) + ctx.pendingToolSpans.delete(key) + const start = pending?.startMs ?? toolPart.state.time.start + const end = toolPart.state.time.end + if (end === undefined) return + const duration_ms = end - start + const success = toolPart.state.status === "completed" - if (isMetricEnabled("tool.duration", ctx)) { - ctx.instruments.toolDurationHistogram.record(duration_ms, { - ...ctx.commonAttrs, - "session.id": toolPart.sessionID, + if (isMetricEnabled("tool.duration", ctx)) { + ctx.instruments.toolDurationHistogram.record(duration_ms, { + ...ctx.commonAttrs, + "session.id": toolPart.sessionID, + tool_name: toolPart.tool, + success, + }) + } + + const toolSpan = pending?.span ?? ctx.tracer.startSpan( + `opencode.tool ${toolPart.tool}`, + { + startTime: start, + kind: SpanKind.INTERNAL, + attributes: { + "session.id": toolPart.sessionID, + "tool.name": toolPart.tool, + ...ctx.commonAttrs, + }, + }, + ) + toolSpan.setAttribute("tool.success", success) + if (success) { + const output = (toolPart.state as { output: string }).output + toolSpan.setAttribute("tool.result_size_bytes", Buffer.byteLength(output, "utf8")) + toolSpan.setStatus({ code: SpanStatusCode.OK }) + } else { + const err = (toolPart.state as { error: string }).error + toolSpan.setAttribute("tool.error", err) + toolSpan.setStatus({ code: SpanStatusCode.ERROR, message: err }) + } + toolSpan.end(end) + + const sizeAttr = success + ? { tool_result_size_bytes: Buffer.byteLength((toolPart.state as { output: string }).output, "utf8") } + : { error: (toolPart.state as { error: string }).error } + + ctx.logger.emit({ + severityNumber: success ? SeverityNumber.INFO : SeverityNumber.ERROR, + severityText: success ? "INFO" : "ERROR", + timestamp: start, + observedTimestamp: Date.now(), + body: "tool_result", + attributes: { + "event.name": "tool_result", + "session.id": toolPart.sessionID, + tool_name: toolPart.tool, + success, + duration_ms, + ...sizeAttr, + ...ctx.commonAttrs, + }, + }) + ctx.log("debug", "otel: tool.duration histogram recorded", { + sessionID: toolPart.sessionID, tool_name: toolPart.tool, + duration_ms, success, }) - } - - const sizeAttr = success - ? { tool_result_size_bytes: Buffer.byteLength((toolPart.state as { output: string }).output, "utf8") } - : { error: (toolPart.state as { error: string }).error } - - ctx.logger.emit({ - severityNumber: success ? SeverityNumber.INFO : SeverityNumber.ERROR, - severityText: success ? "INFO" : "ERROR", - timestamp: start, - observedTimestamp: Date.now(), - body: "tool_result", - attributes: { - "event.name": "tool_result", - "session.id": toolPart.sessionID, + return ctx.log(success ? "info" : "error", "otel: tool_result", { + sessionID: toolPart.sessionID, tool_name: toolPart.tool, success, duration_ms, - ...sizeAttr, - ...ctx.commonAttrs, + }) + } +} + +/** + * Starts an LLM span for an assistant message when it first appears in `message.updated`. + * The span is parented to the session span and carries `gen_ai.*` semantic attributes for + * the model and provider. It is ended in `handleMessageUpdated` once the message completes. + * + * Only called for assistant messages that have not yet completed (`time.completed` absent). + */ +export function startMessageSpan( + sessionID: string, + messageID: string, + modelID: string, + providerID: string, + startTime: number, + ctx: HandlerContext, +) { + if (ctx.messageSpans.has(messageID)) return + const sessionSpan = ctx.sessionSpans.get(sessionID) + const parentCtx = sessionSpan + ? trace.setSpan(context.active(), sessionSpan) + : context.active() + + const msgSpan = ctx.tracer.startSpan( + "gen_ai.chat", + { + startTime, + kind: SpanKind.CLIENT, + attributes: { + "gen_ai.system": providerID, + "gen_ai.request.model": modelID, + "session.id": sessionID, + ...ctx.commonAttrs, + }, }, - }) - ctx.log("debug", "otel: tool.duration histogram recorded", { - sessionID: toolPart.sessionID, - tool_name: toolPart.tool, - duration_ms, - success, - }) - return ctx.log(success ? "info" : "error", "otel: tool_result", { - sessionID: toolPart.sessionID, - tool_name: toolPart.tool, - success, - duration_ms, - }) + parentCtx, + ) + setBoundedMap(ctx.messageSpans, messageID, msgSpan) } diff --git a/src/handlers/session.ts b/src/handlers/session.ts index 7fc69c9..1c4d823 100644 --- a/src/handlers/session.ts +++ b/src/handlers/session.ts @@ -1,9 +1,10 @@ import { SeverityNumber } from "@opentelemetry/api-logs" +import { SpanStatusCode, context, trace } from "@opentelemetry/api" import type { EventSessionCreated, EventSessionIdle, EventSessionError, EventSessionStatus } from "@opencode-ai/sdk" import { errorSummary, setBoundedMap, isMetricEnabled } from "../util.ts" import type { HandlerContext } from "../types.ts" -/** Increments the session counter, records start time, and emits a `session.created` log event. */ +/** Increments the session counter, records start time, starts the root session span, and emits a `session.created` log event. */ export function handleSessionCreated(e: EventSessionCreated, ctx: HandlerContext) { const { id: sessionID, time, parentID } = e.properties.info const createdAt = time.created @@ -12,6 +13,26 @@ export function handleSessionCreated(e: EventSessionCreated, ctx: HandlerContext ctx.instruments.sessionCounter.add(1, { ...ctx.commonAttrs, "session.id": sessionID, is_subagent: isSubagent }) } setBoundedMap(ctx.sessionTotals, sessionID, { startMs: createdAt, tokens: 0, cost: 0, messages: 0, agent: "unknown" }) + + const parentSpan = parentID ? ctx.sessionSpans.get(parentID) : undefined + const spanCtx = parentSpan + ? trace.setSpan(context.active(), parentSpan) + : context.active() + + const sessionSpan = ctx.tracer.startSpan( + "opencode.session", + { + startTime: createdAt, + attributes: { + "session.id": sessionID, + "session.is_subagent": isSubagent, + ...ctx.commonAttrs, + }, + }, + spanCtx, + ) + setBoundedMap(ctx.sessionSpans, sessionID, sessionSpan) + ctx.logger.emit({ severityNumber: SeverityNumber.INFO, severityText: "INFO", @@ -28,11 +49,23 @@ function sweepSession(sessionID: string, ctx: HandlerContext) { if (perm.sessionID === sessionID) ctx.pendingPermissions.delete(id) } for (const [key, span] of ctx.pendingToolSpans) { - if (span.sessionID === sessionID) ctx.pendingToolSpans.delete(key) + if (span.sessionID === sessionID) { + span.span.setStatus({ code: SpanStatusCode.ERROR, message: "session ended before tool completed" }) + span.span.end() + ctx.pendingToolSpans.delete(key) + } + } + for (const [msgID, span] of ctx.messageSpans) { + const attrs = (span as unknown as { attributes?: Record }).attributes + if (attrs?.["session.id"] === sessionID) { + span.setStatus({ code: SpanStatusCode.ERROR, message: "session ended before message completed" }) + span.end() + ctx.messageSpans.delete(msgID) + } } } -/** Emits a `session.idle` log event, records duration and session total histograms, and clears pending state. */ +/** Emits a `session.idle` log event, records duration and session total histograms, ends the session span, and clears pending state. */ export function handleSessionIdle(e: EventSessionIdle, ctx: HandlerContext) { const sessionID = e.properties.sessionID const totals = ctx.sessionTotals.get(sessionID) @@ -55,6 +88,20 @@ export function handleSessionIdle(e: EventSessionIdle, ctx: HandlerContext) { } } + const sessionSpan = ctx.sessionSpans.get(sessionID) + if (sessionSpan) { + if (totals) { + sessionSpan.setAttributes({ + "session.total_tokens": totals.tokens, + "session.total_cost_usd": totals.cost, + "session.total_messages": totals.messages, + }) + } + sessionSpan.setStatus({ code: SpanStatusCode.OK }) + sessionSpan.end() + ctx.sessionSpans.delete(sessionID) + } + ctx.logger.emit({ severityNumber: SeverityNumber.INFO, severityText: "INFO", @@ -76,13 +123,24 @@ export function handleSessionIdle(e: EventSessionIdle, ctx: HandlerContext) { }) } -/** Emits a `session.error` log event and clears any pending tool spans and permissions for the session. */ +/** Emits a `session.error` log event, ends the session span with error status, and clears any pending state for the session. */ export function handleSessionError(e: EventSessionError, ctx: HandlerContext) { const rawID = e.properties.sessionID const sessionID = rawID ?? "unknown" const error = errorSummary(e.properties.error) if (rawID) ctx.sessionTotals.delete(rawID) sweepSession(sessionID, ctx) + + if (rawID) { + const sessionSpan = ctx.sessionSpans.get(rawID) + if (sessionSpan) { + sessionSpan.setStatus({ code: SpanStatusCode.ERROR, message: error }) + sessionSpan.setAttribute("error", error) + sessionSpan.end() + ctx.sessionSpans.delete(rawID) + } + } + ctx.logger.emit({ severityNumber: SeverityNumber.ERROR, severityText: "ERROR", diff --git a/src/index.ts b/src/index.ts index 775d04a..84f1bac 100644 --- a/src/index.ts +++ b/src/index.ts @@ -1,6 +1,7 @@ import type { Plugin } from "@opencode-ai/plugin" import { SeverityNumber } from "@opentelemetry/api-logs" import { logs } from "@opentelemetry/api-logs" +import { trace } from "@opentelemetry/api" import pkg from "../package.json" with { type: "json" } import type { EventSessionCreated, @@ -19,7 +20,7 @@ import { loadConfig, resolveLogLevel } from "./config.ts" import { probeEndpoint } from "./probe.ts" import { setupOtel, createInstruments } from "./otel.ts" import { handleSessionCreated, handleSessionIdle, handleSessionError, handleSessionStatus } from "./handlers/session.ts" -import { handleMessageUpdated, handleMessagePartUpdated } from "./handlers/message.ts" +import { handleMessageUpdated, handleMessagePartUpdated, startMessageSpan } from "./handlers/message.ts" import { handlePermissionUpdated, handlePermissionReplied } from "./handlers/permission.ts" import { handleSessionDiff, handleCommandExecuted } from "./handlers/activity.ts" @@ -67,7 +68,7 @@ export const OtelPlugin: Plugin = async ({ project, client }) => { }) } - const { meterProvider, loggerProvider } = setupOtel( + const { meterProvider, loggerProvider, tracerProvider } = setupOtel( config.endpoint, config.metricsInterval, config.logsInterval, @@ -77,9 +78,12 @@ export const OtelPlugin: Plugin = async ({ project, client }) => { const instruments = createInstruments(config.metricPrefix) const logger = logs.getLogger("com.opencode") + const tracer = trace.getTracer("com.opencode") const pendingToolSpans = new Map() const pendingPermissions = new Map() const sessionTotals = new Map() + const sessionSpans = new Map() + const messageSpans = new Map() const { disabledMetrics } = config const commonAttrs = { "project.id": project.id } as const @@ -96,10 +100,13 @@ export const OtelPlugin: Plugin = async ({ project, client }) => { pendingPermissions, sessionTotals, disabledMetrics, + tracer, + sessionSpans, + messageSpans, } async function shutdown() { - await Promise.allSettled([meterProvider.shutdown(), loggerProvider.shutdown()]) + await Promise.allSettled([meterProvider.shutdown(), loggerProvider.shutdown(), tracerProvider.shutdown()]) } process.on("SIGTERM", () => { shutdown().then(() => process.exit(0)).catch(() => process.exit(1)) }) @@ -187,9 +194,22 @@ export const OtelPlugin: Plugin = async ({ project, client }) => { case "permission.replied": handlePermissionReplied(event as EventPermissionReplied, ctx) break - case "message.updated": - await handleMessageUpdated(event as EventMessageUpdated, ctx) + case "message.updated": { + const msgEvt = event as EventMessageUpdated + const info = msgEvt.properties.info + if (info.role === "assistant" && !info.time?.completed) { + startMessageSpan( + info.sessionID, + info.id, + info.modelID ?? "unknown", + info.providerID ?? "unknown", + info.time?.created ?? Date.now(), + ctx, + ) + } + await handleMessageUpdated(msgEvt, ctx) break + } case "message.part.updated": await handleMessagePartUpdated(event as EventMessagePartUpdated, ctx) break diff --git a/src/otel.ts b/src/otel.ts index ed3f7c7..661f820 100644 --- a/src/otel.ts +++ b/src/otel.ts @@ -1,9 +1,11 @@ import { logs } from "@opentelemetry/api-logs" -import { metrics } from "@opentelemetry/api" +import { metrics, trace } from "@opentelemetry/api" import { LoggerProvider, BatchLogRecordProcessor } from "@opentelemetry/sdk-logs" import { MeterProvider, PeriodicExportingMetricReader } from "@opentelemetry/sdk-metrics" +import { BasicTracerProvider, BatchSpanProcessor } from "@opentelemetry/sdk-trace-base" import { OTLPLogExporter } from "@opentelemetry/exporter-logs-otlp-grpc" import { OTLPMetricExporter } from "@opentelemetry/exporter-metrics-otlp-grpc" +import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-grpc" import { resourceFromAttributes } from "@opentelemetry/resources" import { ATTR_SERVICE_NAME } from "@opentelemetry/semantic-conventions" import { ATTR_HOST_ARCH } from "@opentelemetry/semantic-conventions/incubating" @@ -39,11 +41,13 @@ export function buildResource(version: string) { export type OtelProviders = { meterProvider: MeterProvider loggerProvider: LoggerProvider + tracerProvider: BasicTracerProvider } /** - * Initialises the OTel SDK — creates a `MeterProvider` and `LoggerProvider` backed by - * OTLP/gRPC exporters pointed at `endpoint`, and registers them as the global providers. + * Initialises the OTel SDK — creates a `MeterProvider`, `LoggerProvider`, and + * `BasicTracerProvider` backed by OTLP/gRPC exporters pointed at `endpoint`, and + * registers them as the global providers. */ export function setupOtel( endpoint: string, @@ -74,7 +78,13 @@ export function setupOtel( }) logs.setGlobalLoggerProvider(loggerProvider) - return { meterProvider, loggerProvider } + const tracerProvider = new BasicTracerProvider({ + resource, + spanProcessors: [new BatchSpanProcessor(new OTLPTraceExporter({ url: endpoint }))], + }) + trace.setGlobalTracerProvider(tracerProvider) + + return { meterProvider, loggerProvider, tracerProvider } } /** Creates all metric instruments using the global `MeterProvider`. Metric names are prefixed with `prefix`. */ diff --git a/src/types.ts b/src/types.ts index 92d8270..24d9443 100644 --- a/src/types.ts +++ b/src/types.ts @@ -1,4 +1,4 @@ -import type { Counter, Histogram } from "@opentelemetry/api" +import type { Counter, Histogram, Span, Tracer } from "@opentelemetry/api" import type { Logger as OtelLogger } from "@opentelemetry/api-logs" /** Numeric priority map for log levels; higher value = higher severity. */ @@ -25,6 +25,7 @@ export type PendingToolSpan = { tool: string sessionID: string startMs: number + span: Span } /** Permission prompt tracked between `permission.updated` and `permission.replied`. */ @@ -71,4 +72,7 @@ export type HandlerContext = { pendingPermissions: Map sessionTotals: Map disabledMetrics: Set + tracer: Tracer + sessionSpans: Map + messageSpans: Map } diff --git a/tests/handlers/session.test.ts b/tests/handlers/session.test.ts index 97ecadb..737a082 100644 --- a/tests/handlers/session.test.ts +++ b/tests/handlers/session.test.ts @@ -1,7 +1,8 @@ import { describe, test, expect } from "bun:test" import { handleSessionCreated, handleSessionIdle, handleSessionError, handleSessionStatus } from "../../src/handlers/session.ts" -import { makeCtx } from "../helpers.ts" +import { makeCtx, makeTracer } from "../helpers.ts" import type { EventSessionCreated, EventSessionIdle, EventSessionError, EventSessionStatus } from "@opencode-ai/sdk" +import type { Span } from "@opentelemetry/api" function makeSessionCreated(sessionID: string, createdAt = 1000, parentID?: string): EventSessionCreated { return { @@ -101,8 +102,11 @@ describe("handleSessionIdle", () => { test("sweeps pendingToolSpans for the session", () => { const { ctx } = makeCtx() - ctx.pendingToolSpans.set("ses_1:call_1", { tool: "bash", sessionID: "ses_1", startMs: 0 }) - ctx.pendingToolSpans.set("ses_other:call_2", { tool: "bash", sessionID: "ses_other", startMs: 0 }) + const t = makeTracer() + const span1 = t.startSpan("tool") as unknown as Span + const span2 = t.startSpan("tool") as unknown as Span + ctx.pendingToolSpans.set("ses_1:call_1", { tool: "bash", sessionID: "ses_1", startMs: 0, span: span1 }) + ctx.pendingToolSpans.set("ses_other:call_2", { tool: "bash", sessionID: "ses_other", startMs: 0, span: span2 }) handleSessionIdle(makeSessionIdle("ses_1"), ctx) expect(ctx.pendingToolSpans.has("ses_1:call_1")).toBe(false) expect(ctx.pendingToolSpans.has("ses_other:call_2")).toBe(true) @@ -174,8 +178,10 @@ describe("handleSessionError", () => { test("sweeps pending maps on error", () => { const { ctx } = makeCtx() + const t = makeTracer() + const span = t.startSpan("tool") as unknown as Span ctx.pendingPermissions.set("perm_1", { type: "tool", title: "Read", sessionID: "ses_1" }) - ctx.pendingToolSpans.set("ses_1:call_1", { tool: "bash", sessionID: "ses_1", startMs: 0 }) + ctx.pendingToolSpans.set("ses_1:call_1", { tool: "bash", sessionID: "ses_1", startMs: 0, span }) handleSessionError(makeSessionError("ses_1"), ctx) expect(ctx.pendingPermissions.size).toBe(0) expect(ctx.pendingToolSpans.size).toBe(0) diff --git a/tests/handlers/spans.test.ts b/tests/handlers/spans.test.ts new file mode 100644 index 0000000..5cb042c --- /dev/null +++ b/tests/handlers/spans.test.ts @@ -0,0 +1,375 @@ +import { describe, test, expect } from "bun:test" +import { SpanStatusCode } from "@opentelemetry/api" +import type { Span } from "@opentelemetry/api" +import { handleSessionCreated, handleSessionIdle, handleSessionError } from "../../src/handlers/session.ts" +import { handleMessageUpdated, handleMessagePartUpdated, startMessageSpan } from "../../src/handlers/message.ts" +import { makeCtx, makeTracer, type SpySpan } from "../helpers.ts" +import type { + EventSessionCreated, + EventSessionIdle, + EventSessionError, + EventMessageUpdated, + EventMessagePartUpdated, +} from "@opencode-ai/sdk" + +function makeSessionCreated(sessionID: string, createdAt = 1000, parentID?: string): EventSessionCreated { + return { + type: "session.created", + properties: { info: { id: sessionID, projectID: "proj_test", directory: "/tmp", parentID, time: { created: createdAt } } }, + } as unknown as EventSessionCreated +} + +function makeSessionIdle(sessionID: string): EventSessionIdle { + return { type: "session.idle", properties: { sessionID } } as EventSessionIdle +} + +function makeSessionError(sessionID: string, error?: { name: string }): EventSessionError { + return { type: "session.error", properties: { sessionID, error } } as unknown as EventSessionError +} + +function makeAssistantMessageUpdated(overrides: { + id?: string + sessionID?: string + modelID?: string + providerID?: string + cost?: number + tokens?: { input: number; output: number; reasoning: number; cache: { read: number; write: number } } + time?: { created: number; completed?: number } + error?: { name: string } +}): EventMessageUpdated { + return { + type: "message.updated", + properties: { + info: { + id: overrides.id ?? "msg_1", + role: "assistant", + sessionID: overrides.sessionID ?? "ses_1", + modelID: overrides.modelID ?? "claude-3-5-sonnet", + providerID: overrides.providerID ?? "anthropic", + cost: overrides.cost ?? 0.01, + tokens: overrides.tokens ?? { input: 100, output: 50, reasoning: 0, cache: { read: 0, write: 0 } }, + time: overrides.time ?? { created: 1000, completed: 2000 }, + error: overrides.error, + }, + }, + } as unknown as EventMessageUpdated +} + +function makeToolPartUpdated( + status: "running" | "completed" | "error", + overrides: { sessionID?: string; callID?: string; tool?: string; startMs?: number; endMs?: number } = {}, +): EventMessagePartUpdated { + const sessionID = overrides.sessionID ?? "ses_1" + const callID = overrides.callID ?? "call_1" + const start = overrides.startMs ?? 1000 + const end = overrides.endMs ?? 2000 + const state = + status === "running" + ? { status: "running", time: { start } } + : status === "completed" + ? { status: "completed", time: { start, end }, output: "ok" } + : { status: "error", time: { start, end }, error: "fail" } + return { + type: "message.part.updated", + properties: { part: { type: "tool", sessionID, callID, tool: overrides.tool ?? "bash", state } }, + } as unknown as EventMessagePartUpdated +} + +describe("session spans", () => { + test("starts a session span on session.created", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1", 5000), ctx) + expect(tracer.spans).toHaveLength(1) + expect(tracer.spans[0]!.name).toBe("opencode.session") + expect(tracer.spans[0]!.startTime).toBe(5000) + expect(ctx.sessionSpans.has("ses_1")).toBe(true) + }) + + test("session span carries session.id attribute", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + expect(tracer.spans[0]!.attributes["session.id"]).toBe("ses_1") + }) + + test("session span carries is_subagent=false for root session", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_root"), ctx) + expect(tracer.spans[0]!.attributes["session.is_subagent"]).toBe(false) + }) + + test("session span carries is_subagent=true for subagent session", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_child", 1000, "ses_parent"), ctx) + expect(tracer.spans[0]!.attributes["session.is_subagent"]).toBe(true) + }) + + test("ends session span with OK status on session.idle", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + handleSessionIdle(makeSessionIdle("ses_1"), ctx) + const span = tracer.spans[0]! + expect(span.ended).toBe(true) + expect(span.status.code).toBe(SpanStatusCode.OK) + expect(ctx.sessionSpans.has("ses_1")).toBe(false) + }) + + test("sets session total attributes before ending on idle", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + ctx.sessionTotals.set("ses_1", { startMs: Date.now() - 100, tokens: 250, cost: 0.05, messages: 3, agent: "build" }) + handleSessionIdle(makeSessionIdle("ses_1"), ctx) + const span = tracer.spans[0]! + expect(span.attributes["session.total_tokens"]).toBe(250) + expect(span.attributes["session.total_cost_usd"]).toBe(0.05) + expect(span.attributes["session.total_messages"]).toBe(3) + }) + + test("ends session span with ERROR status on session.error", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + handleSessionError(makeSessionError("ses_1", { name: "NetworkError" }), ctx) + const span = tracer.spans[0]! + expect(span.ended).toBe(true) + expect(span.status.code).toBe(SpanStatusCode.ERROR) + expect(ctx.sessionSpans.has("ses_1")).toBe(false) + }) + + test("error message is propagated to session span status", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + handleSessionError(makeSessionError("ses_1", { name: "TimeoutError" }), ctx) + expect(tracer.spans[0]!.status.message).toBe("TimeoutError") + }) + + test("idle on unknown session does not throw and creates no span", () => { + const { ctx, tracer } = makeCtx() + expect(() => handleSessionIdle(makeSessionIdle("ses_unknown"), ctx)).not.toThrow() + expect(tracer.spans).toHaveLength(0) + }) + + test("subagent span — parent session span is in sessionSpans before child is created", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_parent"), ctx) + handleSessionCreated(makeSessionCreated("ses_child", 2000, "ses_parent"), ctx) + expect(tracer.spans).toHaveLength(2) + expect(tracer.spans[1]!.name).toBe("opencode.session") + }) + + test("subagent span — no error when parent session span is absent", () => { + const { ctx, tracer } = makeCtx() + expect(() => handleSessionCreated(makeSessionCreated("ses_child", 1000, "ses_missing_parent"), ctx)).not.toThrow() + expect(tracer.spans).toHaveLength(1) + }) +}) + +describe("tool spans", () => { + test("starts a tool span on running status", () => { + const { ctx, tracer } = makeCtx() + handleMessagePartUpdated(makeToolPartUpdated("running", { startMs: 1000 }), ctx) + expect(tracer.spans).toHaveLength(1) + expect(tracer.spans[0]!.name).toBe("opencode.tool bash") + expect(tracer.spans[0]!.startTime).toBe(1000) + expect(ctx.pendingToolSpans.has("ses_1:call_1")).toBe(true) + }) + + test("tool span carries tool.name attribute", () => { + const { ctx, tracer } = makeCtx() + handleMessagePartUpdated(makeToolPartUpdated("running", { tool: "read_file" }), ctx) + expect(tracer.spans[0]!.attributes["tool.name"]).toBe("read_file") + }) + + test("ends tool span with OK status on completion", () => { + const { ctx, tracer } = makeCtx() + handleMessagePartUpdated(makeToolPartUpdated("running"), ctx) + handleMessagePartUpdated(makeToolPartUpdated("completed", { endMs: 2000 }), ctx) + const span = tracer.spans[0]! + expect(span.ended).toBe(true) + expect(span.status.code).toBe(SpanStatusCode.OK) + expect(span.endTime).toBe(2000) + }) + + test("ends tool span with ERROR status on error", () => { + const { ctx, tracer } = makeCtx() + handleMessagePartUpdated(makeToolPartUpdated("running"), ctx) + handleMessagePartUpdated(makeToolPartUpdated("error"), ctx) + const span = tracer.spans[0]! + expect(span.ended).toBe(true) + expect(span.status.code).toBe(SpanStatusCode.ERROR) + }) + + test("tool span result_size_bytes set on success", () => { + const { ctx, tracer } = makeCtx() + handleMessagePartUpdated(makeToolPartUpdated("running"), ctx) + handleMessagePartUpdated(makeToolPartUpdated("completed"), ctx) + expect(typeof tracer.spans[0]!.attributes["tool.result_size_bytes"]).toBe("number") + }) + + test("tool span error attr set on error status", () => { + const { ctx, tracer } = makeCtx() + handleMessagePartUpdated(makeToolPartUpdated("running"), ctx) + handleMessagePartUpdated(makeToolPartUpdated("error"), ctx) + expect(tracer.spans[0]!.attributes["tool.error"]).toBe("fail") + }) + + test("tool span removed from pendingToolSpans after completion", () => { + const { ctx } = makeCtx() + handleMessagePartUpdated(makeToolPartUpdated("running"), ctx) + handleMessagePartUpdated(makeToolPartUpdated("completed"), ctx) + expect(ctx.pendingToolSpans.size).toBe(0) + }) + + test("tool span started even when completed arrives without prior running (out-of-order)", () => { + const { ctx, tracer } = makeCtx() + handleMessagePartUpdated(makeToolPartUpdated("completed", { startMs: 500, endMs: 1500 }), ctx) + expect(tracer.spans).toHaveLength(1) + expect(tracer.spans[0]!.ended).toBe(true) + expect(tracer.spans[0]!.status.code).toBe(SpanStatusCode.OK) + }) + + test("tool span is parented to session span when available", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + handleMessagePartUpdated(makeToolPartUpdated("running", { sessionID: "ses_1" }), ctx) + expect(tracer.spans).toHaveLength(2) + expect(tracer.spans[1]!.name).toBe("opencode.tool bash") + }) +}) + +describe("message (LLM) spans", () => { + test("startMessageSpan creates a gen_ai.chat span", () => { + const { ctx, tracer } = makeCtx() + startMessageSpan("ses_1", "msg_1", "claude-3-5-sonnet", "anthropic", 1000, ctx) + expect(tracer.spans).toHaveLength(1) + expect(tracer.spans[0]!.name).toBe("gen_ai.chat") + expect(ctx.messageSpans.has("msg_1")).toBe(true) + }) + + test("startMessageSpan sets gen_ai.* attributes", () => { + const { ctx, tracer } = makeCtx() + startMessageSpan("ses_1", "msg_1", "gpt-4o", "openai", 1000, ctx) + expect(tracer.spans[0]!.attributes["gen_ai.system"]).toBe("openai") + expect(tracer.spans[0]!.attributes["gen_ai.request.model"]).toBe("gpt-4o") + }) + + test("startMessageSpan is a no-op when span already exists for messageID", () => { + const { ctx, tracer } = makeCtx() + startMessageSpan("ses_1", "msg_1", "claude", "anthropic", 1000, ctx) + startMessageSpan("ses_1", "msg_1", "claude", "anthropic", 1000, ctx) + expect(tracer.spans).toHaveLength(1) + }) + + test("handleMessageUpdated ends message span on completion", () => { + const { ctx, tracer } = makeCtx() + startMessageSpan("ses_1", "msg_1", "claude-3-5-sonnet", "anthropic", 1000, ctx) + handleMessageUpdated(makeAssistantMessageUpdated({ id: "msg_1", time: { created: 1000, completed: 2000 } }), ctx) + const span = tracer.spans[0]! + expect(span.ended).toBe(true) + expect(span.endTime).toBe(2000) + expect(ctx.messageSpans.has("msg_1")).toBe(false) + }) + + test("handleMessageUpdated sets OK status on success", () => { + const { ctx, tracer } = makeCtx() + startMessageSpan("ses_1", "msg_1", "claude-3-5-sonnet", "anthropic", 1000, ctx) + handleMessageUpdated(makeAssistantMessageUpdated({ id: "msg_1" }), ctx) + expect(tracer.spans[0]!.status.code).toBe(SpanStatusCode.OK) + }) + + test("handleMessageUpdated sets ERROR status on api error", () => { + const { ctx, tracer } = makeCtx() + startMessageSpan("ses_1", "msg_1", "claude-3-5-sonnet", "anthropic", 1000, ctx) + handleMessageUpdated(makeAssistantMessageUpdated({ id: "msg_1", error: { name: "RateLimitError" } }), ctx) + expect(tracer.spans[0]!.status.code).toBe(SpanStatusCode.ERROR) + expect(tracer.spans[0]!.status.message).toBe("RateLimitError") + }) + + test("handleMessageUpdated sets gen_ai.usage token attributes on span", () => { + const { ctx, tracer } = makeCtx() + startMessageSpan("ses_1", "msg_1", "claude-3-5-sonnet", "anthropic", 1000, ctx) + handleMessageUpdated( + makeAssistantMessageUpdated({ + id: "msg_1", + tokens: { input: 200, output: 80, reasoning: 10, cache: { read: 30, write: 5 } }, + }), + ctx, + ) + const span = tracer.spans[0]! + expect(span.attributes["gen_ai.usage.input_tokens"]).toBe(200) + expect(span.attributes["gen_ai.usage.output_tokens"]).toBe(80) + expect(span.attributes["gen_ai.usage.reasoning_tokens"]).toBe(10) + expect(span.attributes["gen_ai.usage.cache_read_tokens"]).toBe(30) + expect(span.attributes["gen_ai.usage.cache_creation_tokens"]).toBe(5) + }) + + test("handleMessageUpdated no-ops span handling when no span exists for messageID", () => { + const { ctx } = makeCtx() + expect(() => + handleMessageUpdated(makeAssistantMessageUpdated({ id: "msg_no_span" }), ctx) + ).not.toThrow() + }) + + test("message span is parented to session span when available", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + startMessageSpan("ses_1", "msg_1", "claude", "anthropic", 1000, ctx) + expect(tracer.spans).toHaveLength(2) + expect(tracer.spans[1]!.name).toBe("gen_ai.chat") + }) +}) + +describe("orphaned span cleanup", () => { + test("pending tool spans are ended with ERROR on session.idle", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + handleMessagePartUpdated(makeToolPartUpdated("running", { sessionID: "ses_1" }), ctx) + expect(ctx.pendingToolSpans.size).toBe(1) + handleSessionIdle(makeSessionIdle("ses_1"), ctx) + expect(ctx.pendingToolSpans.size).toBe(0) + const toolSpan = tracer.spans.find(s => s.name.startsWith("opencode.tool"))! + expect(toolSpan.ended).toBe(true) + expect(toolSpan.status.code).toBe(SpanStatusCode.ERROR) + }) + + test("pending tool spans for other sessions are not swept", () => { + const { ctx } = makeCtx() + const t = makeTracer() + const span = t.startSpan("tool") as unknown as Span + ctx.pendingToolSpans.set("ses_other:call_1", { tool: "bash", sessionID: "ses_other", startMs: 0, span }) + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + handleSessionIdle(makeSessionIdle("ses_1"), ctx) + expect(ctx.pendingToolSpans.has("ses_other:call_1")).toBe(true) + }) + + test("pending tool spans are ended with ERROR on session.error", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + handleMessagePartUpdated(makeToolPartUpdated("running", { sessionID: "ses_1" }), ctx) + handleSessionError(makeSessionError("ses_1"), ctx) + expect(ctx.pendingToolSpans.size).toBe(0) + const toolSpan = tracer.spans.find(s => s.name.startsWith("opencode.tool"))! + expect(toolSpan.ended).toBe(true) + expect(toolSpan.status.code).toBe(SpanStatusCode.ERROR) + }) + + test("pending message spans are ended with ERROR on session.idle", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + startMessageSpan("ses_1", "msg_orphan", "claude", "anthropic", 1000, ctx) + handleSessionIdle(makeSessionIdle("ses_1"), ctx) + expect(ctx.messageSpans.has("msg_orphan")).toBe(false) + const msgSpan = tracer.spans.find(s => s.name === "gen_ai.chat")! + expect(msgSpan.ended).toBe(true) + expect(msgSpan.status.code).toBe(SpanStatusCode.ERROR) + }) + + test("pending message spans are ended with ERROR on session.error", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + startMessageSpan("ses_1", "msg_orphan", "claude", "anthropic", 1000, ctx) + handleSessionError(makeSessionError("ses_1"), ctx) + expect(ctx.messageSpans.has("msg_orphan")).toBe(false) + const msgSpan = tracer.spans.find(s => s.name === "gen_ai.chat")! + expect(msgSpan.ended).toBe(true) + expect(msgSpan.status.code).toBe(SpanStatusCode.ERROR) + }) +}) diff --git a/tests/helpers.ts b/tests/helpers.ts index 807f266..9f613a3 100644 --- a/tests/helpers.ts +++ b/tests/helpers.ts @@ -1,6 +1,7 @@ import type { HandlerContext, Instruments } from "../src/types.ts" import type { Logger as OtelLogger, LogRecord } from "@opentelemetry/api-logs" -import type { Counter, Histogram } from "@opentelemetry/api" +import type { Counter, Histogram, Span, SpanOptions, Tracer, Context, SpanContext, SpanStatus, Attributes } from "@opentelemetry/api" +import { SpanStatusCode } from "@opentelemetry/api" export type SpyCounter = { calls: Array<{ value: number; attrs: Record }> @@ -22,6 +23,29 @@ export type SpyPluginLog = { fn: HandlerContext["log"] } +export type SpySpan = { + name: string + startTime?: number + endTime?: number | undefined + ended: boolean + status: SpanStatus + attributes: Record + setStatus(status: SpanStatus): SpySpan + setAttribute(key: string, value: unknown): SpySpan + setAttributes(attrs: Attributes): SpySpan + end(endTime?: number): void + isRecording(): boolean + spanContext(): SpanContext + addEvent(name: string): SpySpan + recordException(): SpySpan + updateName(name: string): SpySpan +} + +export type SpyTracer = { + spans: SpySpan[] + startSpan(name: string, options?: SpanOptions, ctx?: Context): SpySpan +} + function makeCounter(): SpyCounter { const spy: SpyCounter = { calls: [], add(v, a = {}) { spy.calls.push({ value: v, attrs: a }) } } return spy @@ -45,6 +69,40 @@ function makePluginLog(): SpyPluginLog { return spy } +function makeSpan(name: string, startTime?: number): SpySpan { + const span: SpySpan = { + name, + startTime, + endTime: undefined, + ended: false, + status: { code: SpanStatusCode.UNSET }, + attributes: {}, + setStatus(s) { span.status = s; return span }, + setAttribute(k, v) { span.attributes[k] = v; return span }, + setAttributes(attrs) { Object.assign(span.attributes, attrs); return span }, + end(t) { span.ended = true; span.endTime = t }, + isRecording() { return !span.ended }, + spanContext() { return { traceId: "00000000000000000000000000000001", spanId: "0000000000000001", traceFlags: 1 } }, + addEvent() { return span }, + recordException() { return span }, + updateName(n) { span.name = n; return span }, + } + return span +} + +export function makeTracer(): SpyTracer { + const tracer: SpyTracer = { + spans: [], + startSpan(name, options) { + const span = makeSpan(name, typeof options?.startTime === "number" ? options.startTime : undefined) + if (options?.attributes) Object.assign(span.attributes, options.attributes) + tracer.spans.push(span) + return span + }, + } + return tracer +} + export type MockContext = { ctx: HandlerContext counters: { @@ -69,6 +127,7 @@ export type MockContext = { } logger: SpyLogger pluginLog: SpyPluginLog + tracer: SpyTracer } export function makeCtx(projectID = "proj_test", disabledMetrics: string[] = []): MockContext { @@ -88,6 +147,7 @@ export function makeCtx(projectID = "proj_test", disabledMetrics: string[] = []) const sessionCostGauge = makeHistogram() const logger = makeLogger() const pluginLog = makePluginLog() + const tracer = makeTracer() const instruments: Instruments = { sessionCounter: session as unknown as Counter, @@ -115,6 +175,9 @@ export function makeCtx(projectID = "proj_test", disabledMetrics: string[] = []) pendingPermissions: new Map(), sessionTotals: new Map(), disabledMetrics: new Set(disabledMetrics), + tracer: tracer as unknown as Tracer, + sessionSpans: new Map(), + messageSpans: new Map(), } return { @@ -124,5 +187,6 @@ export function makeCtx(projectID = "proj_test", disabledMetrics: string[] = []) gauges: { sessionToken: sessionTokenGauge, sessionCost: sessionCostGauge }, logger, pluginLog, + tracer, } } From 89cb9b9b9b1f79559f3930a2017ca16f513785b3 Mon Sep 17 00:00:00 2001 From: Marc Seiler Date: Tue, 24 Mar 2026 14:31:45 -0400 Subject: [PATCH 2/4] feat(config): add OPENCODE_DISABLE_TRACES for per-type trace suppression Introduces OPENCODE_DISABLE_TRACES, a comma-separated env var accepting 'session', 'llm', and 'tool' to independently suppress each trace type. Mirrors the existing OPENCODE_DISABLE_METRICS pattern. - PendingToolSpan.span is now optional so the pendingToolSpans entry (needed for histogram timing) is still created when tool traces are disabled; span creation is skipped - isTraceEnabled() added to util.ts as a direct parallel of isMetricEnabled() - session.ts gates opencode.session span creation behind isTraceEnabled('session'); a prominent comment documents that disabling 'session' while 'llm' or 'tool' remain enabled will cause those spans to emit as unlinked root spans with no parent - message.ts gates gen_ai.chat spans behind isTraceEnabled('llm') and tool spans (both running and completion paths) behind isTraceEnabled('tool'); metrics and logs are unaffected in all cases - Startup log emitted when any traces are disabled Adds 32 new tests (config parsing, isTraceEnabled, per-type disable behaviour); all 217 tests pass. --- src/config.ts | 9 +++ src/handlers/message.ts | 86 +++++++++++++----------- src/handlers/session.ts | 44 +++++++------ src/index.ts | 7 +- src/types.ts | 3 +- src/util.ts | 8 +++ tests/config.test.ts | 45 +++++++++++++ tests/handlers/spans.test.ts | 124 +++++++++++++++++++++++++++++++++++ tests/helpers.ts | 3 +- tests/util.test.ts | 32 ++++++++- 10 files changed, 298 insertions(+), 63 deletions(-) diff --git a/src/config.ts b/src/config.ts index 971f08b..4c06247 100644 --- a/src/config.ts +++ b/src/config.ts @@ -10,6 +10,7 @@ export type PluginConfig = { otlpHeaders: string | undefined resourceAttributes: string | undefined disabledMetrics: Set + disabledTraces: Set } /** Parses a positive integer from an environment variable, returning `fallback` if absent or invalid. */ @@ -41,6 +42,13 @@ export function loadConfig(): PluginConfig { .filter(Boolean), ) + const disabledTraces = new Set( + (process.env["OPENCODE_DISABLE_TRACES"] ?? "") + .split(",") + .map(s => s.trim()) + .filter(Boolean), + ) + return { enabled: !!process.env["OPENCODE_ENABLE_TELEMETRY"], endpoint: process.env["OPENCODE_OTLP_ENDPOINT"] ?? "http://localhost:4317", @@ -50,6 +58,7 @@ export function loadConfig(): PluginConfig { otlpHeaders, resourceAttributes, disabledMetrics, + disabledTraces, } } diff --git a/src/handlers/message.ts b/src/handlers/message.ts index 1ae2af7..283f79d 100644 --- a/src/handlers/message.ts +++ b/src/handlers/message.ts @@ -1,7 +1,7 @@ import { SeverityNumber } from "@opentelemetry/api-logs" import { SpanStatusCode, SpanKind, context, trace } from "@opentelemetry/api" import type { AssistantMessage, EventMessageUpdated, EventMessagePartUpdated, ToolPart } from "@opencode-ai/sdk" -import { errorSummary, setBoundedMap, accumulateSessionTotals, isMetricEnabled } from "../util.ts" +import { errorSummary, setBoundedMap, accumulateSessionTotals, isMetricEnabled, isTraceEnabled } from "../util.ts" import type { HandlerContext } from "../types.ts" type SubtaskPart = { @@ -206,24 +206,27 @@ export function handleMessagePartUpdated(e: EventMessagePartUpdated, ctx: Handle const key = `${toolPart.sessionID}:${toolPart.callID}` if (toolPart.state.status === "running") { - const sessionSpan = ctx.sessionSpans.get(toolPart.sessionID) - const parentCtx = sessionSpan - ? trace.setSpan(context.active(), sessionSpan) - : context.active() - - const toolSpan = ctx.tracer.startSpan( - `opencode.tool ${toolPart.tool}`, - { - startTime: toolPart.state.time.start, - kind: SpanKind.INTERNAL, - attributes: { - "session.id": toolPart.sessionID, - "tool.name": toolPart.tool, - ...ctx.commonAttrs, - }, - }, - parentCtx, - ) + const toolSpan = isTraceEnabled("tool", ctx) + ? (() => { + const sessionSpan = ctx.sessionSpans.get(toolPart.sessionID) + const parentCtx = sessionSpan + ? trace.setSpan(context.active(), sessionSpan) + : context.active() + return ctx.tracer.startSpan( + `opencode.tool ${toolPart.tool}`, + { + startTime: toolPart.state.time.start, + kind: SpanKind.INTERNAL, + attributes: { + "session.id": toolPart.sessionID, + "tool.name": toolPart.tool, + ...ctx.commonAttrs, + }, + }, + parentCtx, + ) + })() + : undefined setBoundedMap(ctx.pendingToolSpans, key, { tool: toolPart.tool, sessionID: toolPart.sessionID, @@ -253,29 +256,31 @@ export function handleMessagePartUpdated(e: EventMessagePartUpdated, ctx: Handle }) } - const toolSpan = pending?.span ?? ctx.tracer.startSpan( - `opencode.tool ${toolPart.tool}`, - { - startTime: start, - kind: SpanKind.INTERNAL, - attributes: { - "session.id": toolPart.sessionID, - "tool.name": toolPart.tool, - ...ctx.commonAttrs, + if (isTraceEnabled("tool", ctx)) { + const toolSpan = pending?.span ?? ctx.tracer.startSpan( + `opencode.tool ${toolPart.tool}`, + { + startTime: start, + kind: SpanKind.INTERNAL, + attributes: { + "session.id": toolPart.sessionID, + "tool.name": toolPart.tool, + ...ctx.commonAttrs, + }, }, - }, - ) - toolSpan.setAttribute("tool.success", success) - if (success) { - const output = (toolPart.state as { output: string }).output - toolSpan.setAttribute("tool.result_size_bytes", Buffer.byteLength(output, "utf8")) - toolSpan.setStatus({ code: SpanStatusCode.OK }) - } else { - const err = (toolPart.state as { error: string }).error - toolSpan.setAttribute("tool.error", err) - toolSpan.setStatus({ code: SpanStatusCode.ERROR, message: err }) + ) + toolSpan.setAttribute("tool.success", success) + if (success) { + const output = (toolPart.state as { output: string }).output + toolSpan.setAttribute("tool.result_size_bytes", Buffer.byteLength(output, "utf8")) + toolSpan.setStatus({ code: SpanStatusCode.OK }) + } else { + const err = (toolPart.state as { error: string }).error + toolSpan.setAttribute("tool.error", err) + toolSpan.setStatus({ code: SpanStatusCode.ERROR, message: err }) + } + toolSpan.end(end) } - toolSpan.end(end) const sizeAttr = success ? { tool_result_size_bytes: Buffer.byteLength((toolPart.state as { output: string }).output, "utf8") } @@ -327,6 +332,7 @@ export function startMessageSpan( startTime: number, ctx: HandlerContext, ) { + if (!isTraceEnabled("llm", ctx)) return if (ctx.messageSpans.has(messageID)) return const sessionSpan = ctx.sessionSpans.get(sessionID) const parentCtx = sessionSpan diff --git a/src/handlers/session.ts b/src/handlers/session.ts index 1c4d823..bb6c99b 100644 --- a/src/handlers/session.ts +++ b/src/handlers/session.ts @@ -1,7 +1,7 @@ import { SeverityNumber } from "@opentelemetry/api-logs" import { SpanStatusCode, context, trace } from "@opentelemetry/api" import type { EventSessionCreated, EventSessionIdle, EventSessionError, EventSessionStatus } from "@opencode-ai/sdk" -import { errorSummary, setBoundedMap, isMetricEnabled } from "../util.ts" +import { errorSummary, setBoundedMap, isMetricEnabled, isTraceEnabled } from "../util.ts" import type { HandlerContext } from "../types.ts" /** Increments the session counter, records start time, starts the root session span, and emits a `session.created` log event. */ @@ -14,24 +14,30 @@ export function handleSessionCreated(e: EventSessionCreated, ctx: HandlerContext } setBoundedMap(ctx.sessionTotals, sessionID, { startMs: createdAt, tokens: 0, cost: 0, messages: 0, agent: "unknown" }) - const parentSpan = parentID ? ctx.sessionSpans.get(parentID) : undefined - const spanCtx = parentSpan - ? trace.setSpan(context.active(), parentSpan) - : context.active() + // WARNING: disabling "session" traces while "llm" or "tool" traces remain enabled + // will cause those child spans to be emitted as unlinked root spans with no parent. + // There is no session span to parent them to. If you need a connected trace hierarchy, + // either enable all three trace types or disable all of them together. + if (isTraceEnabled("session", ctx)) { + const parentSpan = parentID ? ctx.sessionSpans.get(parentID) : undefined + const spanCtx = parentSpan + ? trace.setSpan(context.active(), parentSpan) + : context.active() - const sessionSpan = ctx.tracer.startSpan( - "opencode.session", - { - startTime: createdAt, - attributes: { - "session.id": sessionID, - "session.is_subagent": isSubagent, - ...ctx.commonAttrs, + const sessionSpan = ctx.tracer.startSpan( + "opencode.session", + { + startTime: createdAt, + attributes: { + "session.id": sessionID, + "session.is_subagent": isSubagent, + ...ctx.commonAttrs, + }, }, - }, - spanCtx, - ) - setBoundedMap(ctx.sessionSpans, sessionID, sessionSpan) + spanCtx, + ) + setBoundedMap(ctx.sessionSpans, sessionID, sessionSpan) + } ctx.logger.emit({ severityNumber: SeverityNumber.INFO, @@ -50,8 +56,8 @@ function sweepSession(sessionID: string, ctx: HandlerContext) { } for (const [key, span] of ctx.pendingToolSpans) { if (span.sessionID === sessionID) { - span.span.setStatus({ code: SpanStatusCode.ERROR, message: "session ended before tool completed" }) - span.span.end() + span.span?.setStatus({ code: SpanStatusCode.ERROR, message: "session ended before tool completed" }) + span.span?.end() ctx.pendingToolSpans.delete(key) } } diff --git a/src/index.ts b/src/index.ts index 84f1bac..12bdb15 100644 --- a/src/index.ts +++ b/src/index.ts @@ -84,13 +84,17 @@ export const OtelPlugin: Plugin = async ({ project, client }) => { const sessionTotals = new Map() const sessionSpans = new Map() const messageSpans = new Map() - const { disabledMetrics } = config + const { disabledMetrics, disabledTraces } = config const commonAttrs = { "project.id": project.id } as const if (disabledMetrics.size > 0) { await log("info", "metrics disabled", { disabled: [...disabledMetrics] }) } + if (disabledTraces.size > 0) { + await log("info", "traces disabled", { disabled: [...disabledTraces] }) + } + const ctx: HandlerContext = { logger, log, @@ -100,6 +104,7 @@ export const OtelPlugin: Plugin = async ({ project, client }) => { pendingPermissions, sessionTotals, disabledMetrics, + disabledTraces, tracer, sessionSpans, messageSpans, diff --git a/src/types.ts b/src/types.ts index 24d9443..2b44919 100644 --- a/src/types.ts +++ b/src/types.ts @@ -25,7 +25,7 @@ export type PendingToolSpan = { tool: string sessionID: string startMs: number - span: Span + span?: Span } /** Permission prompt tracked between `permission.updated` and `permission.replied`. */ @@ -72,6 +72,7 @@ export type HandlerContext = { pendingPermissions: Map sessionTotals: Map disabledMetrics: Set + disabledTraces: Set tracer: Tracer sessionSpans: Map messageSpans: Map diff --git a/src/util.ts b/src/util.ts index 65190f7..32548bc 100644 --- a/src/util.ts +++ b/src/util.ts @@ -30,6 +30,14 @@ export function isMetricEnabled(name: string, ctx: { disabledMetrics: Set }): boolean { + return !ctx.disabledTraces.has(name) +} + /** * Accumulates token and cost totals for a session, and increments the message count. * Uses `setBoundedMap` to produce a new object rather than mutating in-place. diff --git a/tests/config.test.ts b/tests/config.test.ts index a718c93..6ac4b79 100644 --- a/tests/config.test.ts +++ b/tests/config.test.ts @@ -49,6 +49,7 @@ describe("loadConfig", () => { "OPENCODE_OTLP_HEADERS", "OPENCODE_RESOURCE_ATTRIBUTES", "OPENCODE_DISABLE_METRICS", + "OPENCODE_DISABLE_TRACES", "OTEL_EXPORTER_OTLP_HEADERS", "OTEL_RESOURCE_ATTRIBUTES", ] @@ -157,6 +158,50 @@ describe("loadConfig", () => { process.env["OPENCODE_DISABLE_METRICS"] = "session.count," expect(loadConfig().disabledMetrics.size).toBe(1) }) + + test("disabledTraces is empty set when OPENCODE_DISABLE_TRACES is unset", () => { + expect(loadConfig().disabledTraces.size).toBe(0) + }) + + test("disabledTraces parses a single trace type", () => { + process.env["OPENCODE_DISABLE_TRACES"] = "session" + expect(loadConfig().disabledTraces).toEqual(new Set(["session"])) + }) + + test("disabledTraces parses a comma-separated list", () => { + process.env["OPENCODE_DISABLE_TRACES"] = "llm,tool" + const { disabledTraces } = loadConfig() + expect(disabledTraces.has("llm")).toBe(true) + expect(disabledTraces.has("tool")).toBe(true) + }) + + test("disabledTraces parses all three types together", () => { + process.env["OPENCODE_DISABLE_TRACES"] = "session,llm,tool" + const { disabledTraces } = loadConfig() + expect(disabledTraces.has("session")).toBe(true) + expect(disabledTraces.has("llm")).toBe(true) + expect(disabledTraces.has("tool")).toBe(true) + }) + + test("disabledTraces trims whitespace around names", () => { + process.env["OPENCODE_DISABLE_TRACES"] = " llm , tool " + const { disabledTraces } = loadConfig() + expect(disabledTraces.has("llm")).toBe(true) + expect(disabledTraces.has("tool")).toBe(true) + }) + + test("disabledTraces ignores empty segments from trailing commas", () => { + process.env["OPENCODE_DISABLE_TRACES"] = "session," + expect(loadConfig().disabledTraces.size).toBe(1) + }) + + test("disabledTraces passes unknown values through silently", () => { + process.env["OPENCODE_DISABLE_TRACES"] = "session,unknown_type" + const { disabledTraces } = loadConfig() + expect(disabledTraces.has("session")).toBe(true) + expect(disabledTraces.has("unknown_type")).toBe(true) + expect(disabledTraces.size).toBe(2) + }) }) describe("resolveLogLevel", () => { diff --git a/tests/handlers/spans.test.ts b/tests/handlers/spans.test.ts index 5cb042c..22af048 100644 --- a/tests/handlers/spans.test.ts +++ b/tests/handlers/spans.test.ts @@ -373,3 +373,127 @@ describe("orphaned span cleanup", () => { expect(msgSpan.status.code).toBe(SpanStatusCode.ERROR) }) }) + +describe("OPENCODE_DISABLE_TRACES=session", () => { + test("no session span is started", () => { + const { ctx, tracer } = makeCtx("proj_test", [], ["session"]) + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + expect(tracer.spans).toHaveLength(0) + expect(ctx.sessionSpans.has("ses_1")).toBe(false) + }) + + test("session counter metric still fires", () => { + const { ctx, counters } = makeCtx("proj_test", [], ["session"]) + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + expect(counters.session.calls).toHaveLength(1) + }) + + test("session.created log record still emitted", () => { + const { ctx, logger } = makeCtx("proj_test", [], ["session"]) + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + expect(logger.records.find(r => r.body === "session.created")).toBeDefined() + }) + + test("session.idle does not throw when no session span exists", () => { + const { ctx } = makeCtx("proj_test", [], ["session"]) + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + expect(() => handleSessionIdle(makeSessionIdle("ses_1"), ctx)).not.toThrow() + }) + + test("session.error does not throw when no session span exists", () => { + const { ctx } = makeCtx("proj_test", [], ["session"]) + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + expect(() => handleSessionError(makeSessionError("ses_1"), ctx)).not.toThrow() + }) + + test("llm spans become root spans (no parent) when session traces disabled but llm enabled", () => { + const { ctx, tracer } = makeCtx("proj_test", [], ["session"]) + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + startMessageSpan("ses_1", "msg_1", "claude", "anthropic", 1000, ctx) + expect(tracer.spans).toHaveLength(1) + expect(tracer.spans[0]!.name).toBe("gen_ai.chat") + }) +}) + +describe("OPENCODE_DISABLE_TRACES=llm", () => { + test("startMessageSpan is a no-op", () => { + const { ctx, tracer } = makeCtx("proj_test", [], ["llm"]) + startMessageSpan("ses_1", "msg_1", "claude", "anthropic", 1000, ctx) + expect(tracer.spans).toHaveLength(0) + expect(ctx.messageSpans.has("msg_1")).toBe(false) + }) + + test("token counter metrics still fire", () => { + const { ctx, counters } = makeCtx("proj_test", [], ["llm"]) + handleMessageUpdated(makeAssistantMessageUpdated({ id: "msg_1" }), ctx) + expect(counters.token.calls.length).toBeGreaterThan(0) + }) + + test("cost counter metric still fires", () => { + const { ctx, counters } = makeCtx("proj_test", [], ["llm"]) + handleMessageUpdated(makeAssistantMessageUpdated({ id: "msg_1", cost: 0.05 }), ctx) + expect(counters.cost.calls).toHaveLength(1) + }) + + test("api_request log record still emitted", () => { + const { ctx, logger } = makeCtx("proj_test", [], ["llm"]) + handleMessageUpdated(makeAssistantMessageUpdated({ id: "msg_1" }), ctx) + expect(logger.records.find(r => r.body === "api_request")).toBeDefined() + }) + + test("handleMessageUpdated does not throw when no message span exists", () => { + const { ctx } = makeCtx("proj_test", [], ["llm"]) + expect(() => handleMessageUpdated(makeAssistantMessageUpdated({ id: "msg_1" }), ctx)).not.toThrow() + }) + + test("session spans still created when only llm disabled", () => { + const { ctx, tracer } = makeCtx("proj_test", [], ["llm"]) + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + expect(tracer.spans).toHaveLength(1) + expect(tracer.spans[0]!.name).toBe("opencode.session") + }) +}) + +describe("OPENCODE_DISABLE_TRACES=tool", () => { + test("no tool span started on running status", () => { + const { ctx, tracer } = makeCtx("proj_test", [], ["tool"]) + handleMessagePartUpdated(makeToolPartUpdated("running"), ctx) + expect(tracer.spans).toHaveLength(0) + }) + + test("pendingToolSpans entry still stored for histogram timing", () => { + const { ctx } = makeCtx("proj_test", [], ["tool"]) + handleMessagePartUpdated(makeToolPartUpdated("running", { startMs: 1000 }), ctx) + expect(ctx.pendingToolSpans.has("ses_1:call_1")).toBe(true) + expect(ctx.pendingToolSpans.get("ses_1:call_1")!.startMs).toBe(1000) + expect(ctx.pendingToolSpans.get("ses_1:call_1")!.span).toBeUndefined() + }) + + test("tool.duration histogram still records on completion", () => { + const { ctx, histograms } = makeCtx("proj_test", [], ["tool"]) + handleMessagePartUpdated(makeToolPartUpdated("running", { startMs: 1000 }), ctx) + handleMessagePartUpdated(makeToolPartUpdated("completed", { startMs: 1000, endMs: 1500 }), ctx) + expect(histograms.tool.calls).toHaveLength(1) + expect(histograms.tool.calls[0]!.value).toBe(500) + }) + + test("tool_result log record still emitted on completion", () => { + const { ctx, logger } = makeCtx("proj_test", [], ["tool"]) + handleMessagePartUpdated(makeToolPartUpdated("running"), ctx) + handleMessagePartUpdated(makeToolPartUpdated("completed"), ctx) + expect(logger.records.find(r => r.body === "tool_result")).toBeDefined() + }) + + test("no tool span created for out-of-order completed event", () => { + const { ctx, tracer } = makeCtx("proj_test", [], ["tool"]) + handleMessagePartUpdated(makeToolPartUpdated("completed", { startMs: 500, endMs: 1500 }), ctx) + expect(tracer.spans).toHaveLength(0) + }) + + test("session spans still created when only tool disabled", () => { + const { ctx, tracer } = makeCtx("proj_test", [], ["tool"]) + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + expect(tracer.spans).toHaveLength(1) + expect(tracer.spans[0]!.name).toBe("opencode.session") + }) +}) diff --git a/tests/helpers.ts b/tests/helpers.ts index 9f613a3..476040e 100644 --- a/tests/helpers.ts +++ b/tests/helpers.ts @@ -130,7 +130,7 @@ export type MockContext = { tracer: SpyTracer } -export function makeCtx(projectID = "proj_test", disabledMetrics: string[] = []): MockContext { +export function makeCtx(projectID = "proj_test", disabledMetrics: string[] = [], disabledTraces: string[] = []): MockContext { const session = makeCounter() const token = makeCounter() const cost = makeCounter() @@ -175,6 +175,7 @@ export function makeCtx(projectID = "proj_test", disabledMetrics: string[] = []) pendingPermissions: new Map(), sessionTotals: new Map(), disabledMetrics: new Set(disabledMetrics), + disabledTraces: new Set(disabledTraces), tracer: tracer as unknown as Tracer, sessionSpans: new Map(), messageSpans: new Map(), diff --git a/tests/util.test.ts b/tests/util.test.ts index 7880765..72c0103 100644 --- a/tests/util.test.ts +++ b/tests/util.test.ts @@ -1,5 +1,5 @@ import { describe, test, expect } from "bun:test" -import { errorSummary, setBoundedMap, isMetricEnabled } from "../src/util.ts" +import { errorSummary, setBoundedMap, isMetricEnabled, isTraceEnabled } from "../src/util.ts" import { MAX_PENDING } from "../src/types.ts" describe("errorSummary", () => { @@ -85,3 +85,33 @@ describe("isMetricEnabled", () => { expect(isMetricEnabled("retry.count", { disabledMetrics: new Set(["does.not.exist"]) })).toBe(true) }) }) + +describe("isTraceEnabled", () => { + test("returns true when disabled set is empty", () => { + expect(isTraceEnabled("session", { disabledTraces: new Set() })).toBe(true) + }) + + test("returns false when trace type is in the disabled set", () => { + expect(isTraceEnabled("session", { disabledTraces: new Set(["session"]) })).toBe(false) + }) + + test("returns false for llm when llm is disabled", () => { + expect(isTraceEnabled("llm", { disabledTraces: new Set(["llm"]) })).toBe(false) + }) + + test("returns false for tool when tool is disabled", () => { + expect(isTraceEnabled("tool", { disabledTraces: new Set(["tool"]) })).toBe(false) + }) + + test("returns true when a different trace type is disabled", () => { + expect(isTraceEnabled("session", { disabledTraces: new Set(["tool"]) })).toBe(true) + }) + + test("is case-sensitive — does not match mismatched case", () => { + expect(isTraceEnabled("session", { disabledTraces: new Set(["Session"]) })).toBe(true) + }) + + test("unknown trace names in disabled set do not affect known types", () => { + expect(isTraceEnabled("llm", { disabledTraces: new Set(["does_not_exist"]) })).toBe(true) + }) +}) From 29bd7e65e703e72ee41e7a8ac249d85929dd7481 Mon Sep 17 00:00:00 2001 From: Marc Seiler Date: Tue, 24 Mar 2026 14:40:36 -0400 Subject: [PATCH 3/4] refactor(tests): address CodeRabbit review feedback on span tests MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - SpyTracer now captures parent span linkage by extracting the active span from the Context passed to startSpan; SpySpan gains a parentSpan field enabling direct parent/child assertions in tests - Assert tracer.spans[n].parentSpan === tracer.spans[0] in the subagent session, tool-parenting, and message-parenting tests — previously these only verified a second span existed, not that it was actually nested under the correct parent - messageSpans re-keyed from messageID to sessionID:messageID; sweepSession now matches entries by key prefix (sessionID:) rather than casting into span attributes; startMessageSpan and handleMessageUpdated updated to use the composite key - tool.result_size_bytes assertion uses a known multibyte Japanese string with Buffer.byteLength for exact byte-vs-character correctness; same fix applied to tool_result_size_bytes log assertion in message.test.ts - handleMessageUpdated no-op test asserts tracer.spans length and ctx.messageSpans size are unchanged after the call - makeSessionError accepts optional sessionID; new test asserts that session.error with undefined sessionID does not end any session span --- src/handlers/message.ts | 10 ++++--- src/handlers/session.ts | 8 +++--- tests/handlers/message.test.ts | 4 +-- tests/handlers/spans.test.ts | 50 +++++++++++++++++++++++----------- tests/helpers.ts | 15 +++++++--- 5 files changed, 57 insertions(+), 30 deletions(-) diff --git a/src/handlers/message.ts b/src/handlers/message.ts index 283f79d..9d49fa4 100644 --- a/src/handlers/message.ts +++ b/src/handlers/message.ts @@ -76,7 +76,8 @@ export function handleMessageUpdated(e: EventMessageUpdated, ctx: HandlerContext cost_usd: assistant.cost, }) - const msgSpan = ctx.messageSpans.get(assistant.id) + const msgKey = `${sessionID}:${assistant.id}` + const msgSpan = ctx.messageSpans.get(msgKey) if (msgSpan) { msgSpan.setAttributes({ "gen_ai.usage.input_tokens": assistant.tokens.input, @@ -94,7 +95,7 @@ export function handleMessageUpdated(e: EventMessageUpdated, ctx: HandlerContext msgSpan.setStatus({ code: SpanStatusCode.OK }) } msgSpan.end(assistant.time.completed) - ctx.messageSpans.delete(assistant.id) + ctx.messageSpans.delete(msgKey) } if (assistant.error) { @@ -333,7 +334,8 @@ export function startMessageSpan( ctx: HandlerContext, ) { if (!isTraceEnabled("llm", ctx)) return - if (ctx.messageSpans.has(messageID)) return + const msgKey = `${sessionID}:${messageID}` + if (ctx.messageSpans.has(msgKey)) return const sessionSpan = ctx.sessionSpans.get(sessionID) const parentCtx = sessionSpan ? trace.setSpan(context.active(), sessionSpan) @@ -353,5 +355,5 @@ export function startMessageSpan( }, parentCtx, ) - setBoundedMap(ctx.messageSpans, messageID, msgSpan) + setBoundedMap(ctx.messageSpans, msgKey, msgSpan) } diff --git a/src/handlers/session.ts b/src/handlers/session.ts index bb6c99b..ee9fc0c 100644 --- a/src/handlers/session.ts +++ b/src/handlers/session.ts @@ -61,12 +61,12 @@ function sweepSession(sessionID: string, ctx: HandlerContext) { ctx.pendingToolSpans.delete(key) } } - for (const [msgID, span] of ctx.messageSpans) { - const attrs = (span as unknown as { attributes?: Record }).attributes - if (attrs?.["session.id"] === sessionID) { + const msgPrefix = `${sessionID}:` + for (const [key, span] of ctx.messageSpans) { + if (key.startsWith(msgPrefix)) { span.setStatus({ code: SpanStatusCode.ERROR, message: "session ended before message completed" }) span.end() - ctx.messageSpans.delete(msgID) + ctx.messageSpans.delete(key) } } } diff --git a/tests/handlers/message.test.ts b/tests/handlers/message.test.ts index b454b51..8c58746 100644 --- a/tests/handlers/message.test.ts +++ b/tests/handlers/message.test.ts @@ -272,14 +272,14 @@ describe("handleMessagePartUpdated", () => { expect(histograms.tool.calls.at(0)!.value).toBe(1000) }) - test("emits tool_result log on success", async () => { + test("emits tool_result log on success with exact byte length", async () => { const { ctx, logger } = makeCtx() await handleMessagePartUpdated(makeToolPartUpdated("running"), ctx) await handleMessagePartUpdated(makeToolPartUpdated("completed"), ctx) const record = logger.records.at(0)! expect(record.body).toBe("tool_result") expect(record.attributes?.["success"]).toBe(true) - expect(record.attributes?.["tool_result_size_bytes"]).toBeGreaterThan(0) + expect(record.attributes?.["tool_result_size_bytes"]).toBe(Buffer.byteLength("result output", "utf8")) }) test("emits error-severity log on tool error", async () => { diff --git a/tests/handlers/spans.test.ts b/tests/handlers/spans.test.ts index 22af048..35a089e 100644 --- a/tests/handlers/spans.test.ts +++ b/tests/handlers/spans.test.ts @@ -23,8 +23,11 @@ function makeSessionIdle(sessionID: string): EventSessionIdle { return { type: "session.idle", properties: { sessionID } } as EventSessionIdle } -function makeSessionError(sessionID: string, error?: { name: string }): EventSessionError { - return { type: "session.error", properties: { sessionID, error } } as unknown as EventSessionError +function makeSessionError(sessionID?: string, error?: { name: string }): EventSessionError { + return { + type: "session.error", + properties: { ...(sessionID !== undefined ? { sessionID } : {}), error }, + } as unknown as EventSessionError } function makeAssistantMessageUpdated(overrides: { @@ -57,7 +60,7 @@ function makeAssistantMessageUpdated(overrides: { function makeToolPartUpdated( status: "running" | "completed" | "error", - overrides: { sessionID?: string; callID?: string; tool?: string; startMs?: number; endMs?: number } = {}, + overrides: { sessionID?: string; callID?: string; tool?: string; startMs?: number; endMs?: number; output?: string } = {}, ): EventMessagePartUpdated { const sessionID = overrides.sessionID ?? "ses_1" const callID = overrides.callID ?? "call_1" @@ -67,7 +70,7 @@ function makeToolPartUpdated( status === "running" ? { status: "running", time: { start } } : status === "completed" - ? { status: "completed", time: { start, end }, output: "ok" } + ? { status: "completed", time: { start, end }, output: overrides.output ?? "ok" } : { status: "error", time: { start, end }, error: "fail" } return { type: "message.part.updated", @@ -147,12 +150,21 @@ describe("session spans", () => { expect(tracer.spans).toHaveLength(0) }) + test("session.error with undefined sessionID does not end any span", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + handleSessionError(makeSessionError(undefined, { name: "UnknownError" }), ctx) + expect(ctx.sessionSpans.has("ses_1")).toBe(true) + expect(tracer.spans[0]!.ended).toBe(false) + }) + test("subagent span — parent session span is in sessionSpans before child is created", () => { const { ctx, tracer } = makeCtx() handleSessionCreated(makeSessionCreated("ses_parent"), ctx) handleSessionCreated(makeSessionCreated("ses_child", 2000, "ses_parent"), ctx) expect(tracer.spans).toHaveLength(2) expect(tracer.spans[1]!.name).toBe("opencode.session") + expect(tracer.spans[1]!.parentSpan).toBe(tracer.spans[0]) }) test("subagent span — no error when parent session span is absent", () => { @@ -197,11 +209,13 @@ describe("tool spans", () => { expect(span.status.code).toBe(SpanStatusCode.ERROR) }) - test("tool span result_size_bytes set on success", () => { + test("tool span result_size_bytes matches exact byte length of multibyte output", () => { const { ctx, tracer } = makeCtx() + const multibyte = "こんにちは" + const expectedBytes = Buffer.byteLength(multibyte, "utf8") handleMessagePartUpdated(makeToolPartUpdated("running"), ctx) - handleMessagePartUpdated(makeToolPartUpdated("completed"), ctx) - expect(typeof tracer.spans[0]!.attributes["tool.result_size_bytes"]).toBe("number") + handleMessagePartUpdated(makeToolPartUpdated("completed", { output: multibyte }), ctx) + expect(tracer.spans[0]!.attributes["tool.result_size_bytes"]).toBe(expectedBytes) }) test("tool span error attr set on error status", () => { @@ -232,6 +246,7 @@ describe("tool spans", () => { handleMessagePartUpdated(makeToolPartUpdated("running", { sessionID: "ses_1" }), ctx) expect(tracer.spans).toHaveLength(2) expect(tracer.spans[1]!.name).toBe("opencode.tool bash") + expect(tracer.spans[1]!.parentSpan).toBe(tracer.spans[0]) }) }) @@ -241,7 +256,7 @@ describe("message (LLM) spans", () => { startMessageSpan("ses_1", "msg_1", "claude-3-5-sonnet", "anthropic", 1000, ctx) expect(tracer.spans).toHaveLength(1) expect(tracer.spans[0]!.name).toBe("gen_ai.chat") - expect(ctx.messageSpans.has("msg_1")).toBe(true) + expect(ctx.messageSpans.has("ses_1:msg_1")).toBe(true) }) test("startMessageSpan sets gen_ai.* attributes", () => { @@ -251,7 +266,7 @@ describe("message (LLM) spans", () => { expect(tracer.spans[0]!.attributes["gen_ai.request.model"]).toBe("gpt-4o") }) - test("startMessageSpan is a no-op when span already exists for messageID", () => { + test("startMessageSpan is a no-op when span already exists for sessionID:messageID", () => { const { ctx, tracer } = makeCtx() startMessageSpan("ses_1", "msg_1", "claude", "anthropic", 1000, ctx) startMessageSpan("ses_1", "msg_1", "claude", "anthropic", 1000, ctx) @@ -265,7 +280,7 @@ describe("message (LLM) spans", () => { const span = tracer.spans[0]! expect(span.ended).toBe(true) expect(span.endTime).toBe(2000) - expect(ctx.messageSpans.has("msg_1")).toBe(false) + expect(ctx.messageSpans.has("ses_1:msg_1")).toBe(false) }) test("handleMessageUpdated sets OK status on success", () => { @@ -302,10 +317,12 @@ describe("message (LLM) spans", () => { }) test("handleMessageUpdated no-ops span handling when no span exists for messageID", () => { - const { ctx } = makeCtx() - expect(() => - handleMessageUpdated(makeAssistantMessageUpdated({ id: "msg_no_span" }), ctx) - ).not.toThrow() + const { ctx, tracer } = makeCtx() + const spansBefore = tracer.spans.length + const mapSizeBefore = ctx.messageSpans.size + handleMessageUpdated(makeAssistantMessageUpdated({ id: "msg_no_span" }), ctx) + expect(tracer.spans).toHaveLength(spansBefore) + expect(ctx.messageSpans.size).toBe(mapSizeBefore) }) test("message span is parented to session span when available", () => { @@ -314,6 +331,7 @@ describe("message (LLM) spans", () => { startMessageSpan("ses_1", "msg_1", "claude", "anthropic", 1000, ctx) expect(tracer.spans).toHaveLength(2) expect(tracer.spans[1]!.name).toBe("gen_ai.chat") + expect(tracer.spans[1]!.parentSpan).toBe(tracer.spans[0]) }) }) @@ -356,7 +374,7 @@ describe("orphaned span cleanup", () => { handleSessionCreated(makeSessionCreated("ses_1"), ctx) startMessageSpan("ses_1", "msg_orphan", "claude", "anthropic", 1000, ctx) handleSessionIdle(makeSessionIdle("ses_1"), ctx) - expect(ctx.messageSpans.has("msg_orphan")).toBe(false) + expect(ctx.messageSpans.has("ses_1:msg_orphan")).toBe(false) const msgSpan = tracer.spans.find(s => s.name === "gen_ai.chat")! expect(msgSpan.ended).toBe(true) expect(msgSpan.status.code).toBe(SpanStatusCode.ERROR) @@ -367,7 +385,7 @@ describe("orphaned span cleanup", () => { handleSessionCreated(makeSessionCreated("ses_1"), ctx) startMessageSpan("ses_1", "msg_orphan", "claude", "anthropic", 1000, ctx) handleSessionError(makeSessionError("ses_1"), ctx) - expect(ctx.messageSpans.has("msg_orphan")).toBe(false) + expect(ctx.messageSpans.has("ses_1:msg_orphan")).toBe(false) const msgSpan = tracer.spans.find(s => s.name === "gen_ai.chat")! expect(msgSpan.ended).toBe(true) expect(msgSpan.status.code).toBe(SpanStatusCode.ERROR) diff --git a/tests/helpers.ts b/tests/helpers.ts index 476040e..12527d8 100644 --- a/tests/helpers.ts +++ b/tests/helpers.ts @@ -1,7 +1,7 @@ import type { HandlerContext, Instruments } from "../src/types.ts" import type { Logger as OtelLogger, LogRecord } from "@opentelemetry/api-logs" import type { Counter, Histogram, Span, SpanOptions, Tracer, Context, SpanContext, SpanStatus, Attributes } from "@opentelemetry/api" -import { SpanStatusCode } from "@opentelemetry/api" +import { SpanStatusCode, trace } from "@opentelemetry/api" export type SpyCounter = { calls: Array<{ value: number; attrs: Record }> @@ -30,6 +30,7 @@ export type SpySpan = { ended: boolean status: SpanStatus attributes: Record + parentSpan: SpySpan | undefined setStatus(status: SpanStatus): SpySpan setAttribute(key: string, value: unknown): SpySpan setAttributes(attrs: Attributes): SpySpan @@ -69,7 +70,7 @@ function makePluginLog(): SpyPluginLog { return spy } -function makeSpan(name: string, startTime?: number): SpySpan { +function makeSpan(name: string, startTime?: number, parentSpan?: SpySpan): SpySpan { const span: SpySpan = { name, startTime, @@ -77,6 +78,7 @@ function makeSpan(name: string, startTime?: number): SpySpan { ended: false, status: { code: SpanStatusCode.UNSET }, attributes: {}, + parentSpan, setStatus(s) { span.status = s; return span }, setAttribute(k, v) { span.attributes[k] = v; return span }, setAttributes(attrs) { Object.assign(span.attributes, attrs); return span }, @@ -93,8 +95,13 @@ function makeSpan(name: string, startTime?: number): SpySpan { export function makeTracer(): SpyTracer { const tracer: SpyTracer = { spans: [], - startSpan(name, options) { - const span = makeSpan(name, typeof options?.startTime === "number" ? options.startTime : undefined) + startSpan(name, options, ctx) { + const parentFromCtx = ctx ? trace.getSpan(ctx) as SpySpan | undefined : undefined + const span = makeSpan( + name, + typeof options?.startTime === "number" ? options.startTime : undefined, + parentFromCtx, + ) if (options?.attributes) Object.assign(span.attributes, options.attributes) tracer.spans.push(span) return span From 65f1e70ec592a571dd5fd410769920cc5c6e1142 Mon Sep 17 00:00:00 2001 From: Marc Seiler Date: Tue, 24 Mar 2026 15:02:38 -0400 Subject: [PATCH 4/4] fix(traces): apply metricPrefix to opencode span names and fix out-of-order parentage - Applies OPENCODE_METRIC_PREFIX (default 'opencode.') to session and tool spans so they respect user configuration, matching the behaviour of metrics. gen_ai.chat remains unprefixed as it is an OpenLLMetry standard semantic convention. - Fixes the out-of-order tool fallback path (where completed arrives before running) to correctly parent the fallback span to the active session span, rather than starting an unlinked root span. - Fixes a typo in tool span names (was 'opencode.tool bash', is now 'opencode.tool.bash'). --- src/handlers/message.ts | 31 +++++++++++++++++++------------ src/handlers/session.ts | 2 +- src/index.ts | 1 + src/types.ts | 1 + tests/handlers/spans.test.ts | 13 +++++++++++-- tests/helpers.ts | 1 + 6 files changed, 34 insertions(+), 15 deletions(-) diff --git a/src/handlers/message.ts b/src/handlers/message.ts index 9d49fa4..13e3d99 100644 --- a/src/handlers/message.ts +++ b/src/handlers/message.ts @@ -214,7 +214,7 @@ export function handleMessagePartUpdated(e: EventMessagePartUpdated, ctx: Handle ? trace.setSpan(context.active(), sessionSpan) : context.active() return ctx.tracer.startSpan( - `opencode.tool ${toolPart.tool}`, + `${ctx.tracePrefix}tool.${toolPart.tool}`, { startTime: toolPart.state.time.start, kind: SpanKind.INTERNAL, @@ -258,18 +258,25 @@ export function handleMessagePartUpdated(e: EventMessagePartUpdated, ctx: Handle } if (isTraceEnabled("tool", ctx)) { - const toolSpan = pending?.span ?? ctx.tracer.startSpan( - `opencode.tool ${toolPart.tool}`, - { - startTime: start, - kind: SpanKind.INTERNAL, - attributes: { - "session.id": toolPart.sessionID, - "tool.name": toolPart.tool, - ...ctx.commonAttrs, + const toolSpan = pending?.span ?? (() => { + const sessionSpan = ctx.sessionSpans.get(toolPart.sessionID) + const parentCtx = sessionSpan + ? trace.setSpan(context.active(), sessionSpan) + : context.active() + return ctx.tracer.startSpan( + `${ctx.tracePrefix}tool.${toolPart.tool}`, + { + startTime: start, + kind: SpanKind.INTERNAL, + attributes: { + "session.id": toolPart.sessionID, + "tool.name": toolPart.tool, + ...ctx.commonAttrs, + }, }, - }, - ) + parentCtx, + ) + })() toolSpan.setAttribute("tool.success", success) if (success) { const output = (toolPart.state as { output: string }).output diff --git a/src/handlers/session.ts b/src/handlers/session.ts index ee9fc0c..393e631 100644 --- a/src/handlers/session.ts +++ b/src/handlers/session.ts @@ -25,7 +25,7 @@ export function handleSessionCreated(e: EventSessionCreated, ctx: HandlerContext : context.active() const sessionSpan = ctx.tracer.startSpan( - "opencode.session", + `${ctx.tracePrefix}session`, { startTime: createdAt, attributes: { diff --git a/src/index.ts b/src/index.ts index 12bdb15..8675d16 100644 --- a/src/index.ts +++ b/src/index.ts @@ -106,6 +106,7 @@ export const OtelPlugin: Plugin = async ({ project, client }) => { disabledMetrics, disabledTraces, tracer, + tracePrefix: config.metricPrefix, sessionSpans, messageSpans, } diff --git a/src/types.ts b/src/types.ts index 2b44919..8d21c3e 100644 --- a/src/types.ts +++ b/src/types.ts @@ -74,6 +74,7 @@ export type HandlerContext = { disabledMetrics: Set disabledTraces: Set tracer: Tracer + tracePrefix: string sessionSpans: Map messageSpans: Map } diff --git a/tests/handlers/spans.test.ts b/tests/handlers/spans.test.ts index 35a089e..15429dd 100644 --- a/tests/handlers/spans.test.ts +++ b/tests/handlers/spans.test.ts @@ -179,7 +179,7 @@ describe("tool spans", () => { const { ctx, tracer } = makeCtx() handleMessagePartUpdated(makeToolPartUpdated("running", { startMs: 1000 }), ctx) expect(tracer.spans).toHaveLength(1) - expect(tracer.spans[0]!.name).toBe("opencode.tool bash") + expect(tracer.spans[0]!.name).toBe("opencode.tool.bash") expect(tracer.spans[0]!.startTime).toBe(1000) expect(ctx.pendingToolSpans.has("ses_1:call_1")).toBe(true) }) @@ -245,7 +245,16 @@ describe("tool spans", () => { handleSessionCreated(makeSessionCreated("ses_1"), ctx) handleMessagePartUpdated(makeToolPartUpdated("running", { sessionID: "ses_1" }), ctx) expect(tracer.spans).toHaveLength(2) - expect(tracer.spans[1]!.name).toBe("opencode.tool bash") + expect(tracer.spans[1]!.name).toBe("opencode.tool.bash") + expect(tracer.spans[1]!.parentSpan).toBe(tracer.spans[0]) + }) + + test("out-of-order tool span is parented to session span when available", () => { + const { ctx, tracer } = makeCtx() + handleSessionCreated(makeSessionCreated("ses_1"), ctx) + handleMessagePartUpdated(makeToolPartUpdated("completed", { sessionID: "ses_1", startMs: 500, endMs: 1500 }), ctx) + expect(tracer.spans).toHaveLength(2) + expect(tracer.spans[1]!.name).toBe("opencode.tool.bash") expect(tracer.spans[1]!.parentSpan).toBe(tracer.spans[0]) }) }) diff --git a/tests/helpers.ts b/tests/helpers.ts index 12527d8..cc7ddbb 100644 --- a/tests/helpers.ts +++ b/tests/helpers.ts @@ -184,6 +184,7 @@ export function makeCtx(projectID = "proj_test", disabledMetrics: string[] = [], disabledMetrics: new Set(disabledMetrics), disabledTraces: new Set(disabledTraces), tracer: tracer as unknown as Tracer, + tracePrefix: "opencode.", sessionSpans: new Map(), messageSpans: new Map(), }