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/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 6315c4a..13e3d99 100644 --- a/src/handlers/message.ts +++ b/src/handlers/message.ts @@ -1,6 +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 = { @@ -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,28 @@ export function handleMessageUpdated(e: EventMessageUpdated, ctx: HandlerContext cost_usd: assistant.cost, }) + const msgKey = `${sessionID}:${assistant.id}` + const msgSpan = ctx.messageSpans.get(msgKey) + 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(msgKey) + } + if (assistant.error) { ctx.logger.emit({ severityNumber: SeverityNumber.ERROR, @@ -137,9 +160,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 +202,165 @@ 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 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( + `${ctx.tracePrefix}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, + 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 === "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 - } + if (toolPart.state.status !== "completed" && toolPart.state.status !== "error") return + + 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 (toolPart.state.status !== "completed" && toolPart.state.status !== "error") return + if (isMetricEnabled("tool.duration", ctx)) { + ctx.instruments.toolDurationHistogram.record(duration_ms, { + ...ctx.commonAttrs, + "session.id": toolPart.sessionID, + tool_name: toolPart.tool, + success, + }) + } - 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" + if (isTraceEnabled("tool", ctx)) { + 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 + 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) + } - if (isMetricEnabled("tool.duration", ctx)) { - ctx.instruments.toolDurationHistogram.record(duration_ms, { - ...ctx.commonAttrs, - "session.id": toolPart.sessionID, + 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 (!isTraceEnabled("llm", ctx)) 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) + : 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, msgKey, msgSpan) } diff --git a/src/handlers/session.ts b/src/handlers/session.ts index 7fc69c9..393e631 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 { errorSummary, setBoundedMap, isMetricEnabled, isTraceEnabled } 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,32 @@ 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" }) + + // 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( + `${ctx.tracePrefix}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 +55,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) + } + } + 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(key) + } } } -/** 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 +94,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 +129,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..8675d16 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,16 +78,23 @@ 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 { disabledMetrics } = config + const sessionSpans = new Map() + const messageSpans = new Map() + 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, @@ -96,10 +104,15 @@ export const OtelPlugin: Plugin = async ({ project, client }) => { pendingPermissions, sessionTotals, disabledMetrics, + disabledTraces, + tracer, + tracePrefix: config.metricPrefix, + 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 +200,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..8d21c3e 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,9 @@ export type HandlerContext = { pendingPermissions: Map sessionTotals: Map disabledMetrics: Set + disabledTraces: Set + tracer: Tracer + tracePrefix: string + 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/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/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..15429dd --- /dev/null +++ b/tests/handlers/spans.test.ts @@ -0,0 +1,526 @@ +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 !== undefined ? { 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; output?: string } = {}, +): 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: overrides.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("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", () => { + 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 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", { output: multibyte }), ctx) + expect(tracer.spans[0]!.attributes["tool.result_size_bytes"]).toBe(expectedBytes) + }) + + 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") + 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]) + }) +}) + +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("ses_1: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 sessionID: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("ses_1: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, 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", () => { + 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") + expect(tracer.spans[1]!.parentSpan).toBe(tracer.spans[0]) + }) +}) + +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("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) + }) + + 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("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) + }) +}) + +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 807f266..cc7ddbb 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, trace } from "@opentelemetry/api" export type SpyCounter = { calls: Array<{ value: number; attrs: Record }> @@ -22,6 +23,30 @@ export type SpyPluginLog = { fn: HandlerContext["log"] } +export type SpySpan = { + name: string + startTime?: number + endTime?: number | undefined + ended: boolean + status: SpanStatus + attributes: Record + parentSpan: SpySpan | undefined + 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 +70,46 @@ function makePluginLog(): SpyPluginLog { return spy } +function makeSpan(name: string, startTime?: number, parentSpan?: SpySpan): SpySpan { + const span: SpySpan = { + name, + startTime, + endTime: undefined, + 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 }, + 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, 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 + }, + } + return tracer +} + export type MockContext = { ctx: HandlerContext counters: { @@ -69,9 +134,10 @@ export type MockContext = { } logger: SpyLogger pluginLog: SpyPluginLog + 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() @@ -88,6 +154,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 +182,11 @@ 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, + tracePrefix: "opencode.", + sessionSpans: new Map(), + messageSpans: new Map(), } return { @@ -124,5 +196,6 @@ export function makeCtx(projectID = "proj_test", disabledMetrics: string[] = []) gauges: { sessionToken: sessionTokenGauge, sessionCost: sessionCostGauge }, logger, pluginLog, + tracer, } } 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) + }) +})