diff --git a/README.md b/README.md index 5b87b73..06352b8 100644 --- a/README.md +++ b/README.md @@ -100,6 +100,12 @@ the parent run span; a background child may outlive its already-ended dispatch t ## Installation +Log events associated with an observed LLM step, tool call, or failed execution carry that span's native OTel +trace and span IDs. Events without a matching span can remain uncorrelated. Disabling a span type uses its +available parent context; disabling logs still suppresses all log export. Trace IDs are not metric attributes. +Prompt admission logs use the current execution's context only when steering an active execution. Queued prompts +remain uncorrelated because their consuming execution has not started yet. + Add the plugin to your opencode config at `~/.config/opencode/opencode.json`: ```json diff --git a/src/handlers/permission.ts b/src/handlers/permission.ts index ba57fbe..eb6967a 100644 --- a/src/handlers/permission.ts +++ b/src/handlers/permission.ts @@ -1,6 +1,6 @@ import { SeverityNumber } from "@opentelemetry/api-logs" import type { EventOf, HandlerContext } from "../types.ts" -import { agentAttrs, getSessionAgentMeta, setBoundedMap } from "../util.ts" +import { agentAttrs, getSessionAgentMeta, resolveRunContext, setBoundedMap } from "../util.ts" /** Stores an answered permission prompt for correlation when the reply arrives. */ export function handlePermissionAsked(e: EventOf<"permission.asked">, ctx: HandlerContext) { @@ -31,6 +31,7 @@ export function handlePermissionReplied(e: EventOf<"permission.replied">, ctx: H timestamp: e.created, observedTimestamp: Date.now(), body: "tool_decision", + context: resolveRunContext(d.sessionID, ctx), attributes: { "event.name": "tool_decision", "session.id": d.sessionID, diff --git a/src/handlers/session.ts b/src/handlers/session.ts index 3d9c65a..62e516b 100644 --- a/src/handlers/session.ts +++ b/src/handlers/session.ts @@ -18,6 +18,7 @@ import { isTraceEnabled, markSeen, modelRef, + resolveRunContext, resolveSubagentTraceContext, setBoundedMap, totalTokens, @@ -33,7 +34,8 @@ export function handlePromptEnqueued(e: EventOf<"session.inbox.enqueued">, ctx: for (const agent of item.payload.agents ?? []) parts.push(agent.name) for (const skill of item.payload.skills ?? []) parts.push(skill.name) const text = parts.filter(Boolean).join("\n") - if (item.delivery === "steer" && ctx.tracing.activeExecutions.has(sessionID)) { + const steeringActiveExecution = item.delivery === "steer" && ctx.tracing.activeExecutions.has(sessionID) + if (steeringActiveExecution) { const active = ctx.tracing.activePrompts.get(sessionID) setBoundedMap(ctx.tracing.activePrompts, sessionID, { text: active?.text ? `${active.text}\n${text}` : text, @@ -51,6 +53,7 @@ export function handlePromptEnqueued(e: EventOf<"session.inbox.enqueued">, ctx: timestamp: e.created, observedTimestamp: Date.now(), body: "user_prompt", + ...(steeringActiveExecution ? { context: resolveRunContext(sessionID, ctx) } : {}), attributes: { "event.name": "user_prompt", "session.id": sessionID, @@ -236,6 +239,7 @@ export function handleExecutionEnded( ) { const sessionID = e.data.sessionID const totals = ctx.tracing.sessionTotals.get(sessionID) + const logContext = resolveRunContext(sessionID, ctx) ctx.tracing.activeExecutions.delete(sessionID) const pendingDispatch = ctx.tracing.subagentParents.get(sessionID) if (pendingDispatch) { @@ -279,6 +283,7 @@ export function handleExecutionEnded( timestamp: e.created, observedTimestamp: Date.now(), body: "session.error", + context: logContext, attributes: { "event.name": "session.error", "session.id": sessionID, diff --git a/src/handlers/step.ts b/src/handlers/step.ts index b87d11b..1e977f3 100644 --- a/src/handlers/step.ts +++ b/src/handlers/step.ts @@ -34,6 +34,7 @@ import { isTraceEnabled, markSeen, resolveRunContext, + resolveStepContext, setBoundedMap, } from "../util.ts" @@ -170,6 +171,7 @@ export function handleStepEnded(e: EventOf<"session.step.ended">, ctx: HandlerCo const providerID = meta?.providerID ?? "unknown" const durationMs = Math.max(0, e.created - (meta?.startMs ?? e.created)) + const logContext = resolveStepContext(d.sessionID, d.assistantMessageID, ctx) recordUsageMetrics(d.sessionID, modelID, agent, d.tokens, d.cost, ctx) const firstStep = countMessage(d.assistantMessageID, d.sessionID, modelID, providerID, agent, ctx) accumulateTotals(d.sessionID, allTokens(d.tokens), d.cost, firstStep, ctx) @@ -207,6 +209,7 @@ export function handleStepEnded(e: EventOf<"session.step.ended">, ctx: HandlerCo timestamp: e.created, observedTimestamp: Date.now(), body: "api_request", + context: logContext, attributes: { "event.name": "api_request", "session.id": d.sessionID, @@ -238,6 +241,7 @@ export function handleStepFailed(e: EventOf<"session.step.failed">, ctx: Handler const error = errorSummary(d.error) const durationMs = Math.max(0, e.created - (meta?.startMs ?? e.created)) + const logContext = resolveStepContext(d.sessionID, d.assistantMessageID, ctx) recordUsageMetrics(d.sessionID, modelID, agent, d.tokens, d.cost, ctx) const firstStep = countMessage(d.assistantMessageID, d.sessionID, modelID, providerID, agent, ctx) accumulateTotals(d.sessionID, allTokens(d.tokens), d.cost ?? 0, firstStep, ctx) @@ -272,6 +276,7 @@ export function handleStepFailed(e: EventOf<"session.step.failed">, ctx: Handler timestamp: e.created, observedTimestamp: Date.now(), body: "api_error", + context: logContext, attributes: { "event.name": "api_error", "session.id": d.sessionID, diff --git a/src/handlers/tool.ts b/src/handlers/tool.ts index 07fe8f6..cc3ca57 100644 --- a/src/handlers/tool.ts +++ b/src/handlers/tool.ts @@ -22,6 +22,7 @@ import { isMetricEnabled, isTraceEnabled, resolveStepContext, + resolveToolContext, setBoundedMap, } from "../util.ts" @@ -173,6 +174,7 @@ function finishTool( const durationMs = Math.max(0, endMs - start) const { agentName, agentType } = getSessionAgentMeta(sessionID, ctx) const sizeBytes = output ? Buffer.byteLength(output, "utf8") : 0 + const logContext = resolveToolContext(callID, sessionID, meta?.assistantMessageID ?? "", ctx) if (success && observedExecution && meta.command && SHELL_TOOL_RE.test(tool) && GIT_COMMIT_RE.test(meta.command)) { if (isMetricEnabled("commit.count", ctx)) { @@ -184,6 +186,7 @@ function finishTool( timestamp: endMs, observedTimestamp: Date.now(), body: "commit", + context: logContext, attributes: { "event.name": "commit", "session.id": sessionID, @@ -226,6 +229,7 @@ function finishTool( timestamp: start, observedTimestamp: Date.now(), body: "tool_result", + context: logContext, attributes: { "event.name": "tool_result", "session.id": sessionID, diff --git a/src/plugin.ts b/src/plugin.ts index a416d61..02cf9ad 100644 --- a/src/plugin.ts +++ b/src/plugin.ts @@ -88,7 +88,7 @@ export async function setup(ctx: OpenCodeContext): Promise<() => Promise> const emitLog: HandlerContext["emitLog"] = (record) => { if (!config.logsEnabled) return - shared.logger.emit(record) + shared.logger.emit({ ...record, context: record.context ?? ROOT_CONTEXT }) } const remoteContext = remoteParentContext(config.traceparent, config.tracestate) diff --git a/src/util.ts b/src/util.ts index 9a45d3b..be9d449 100644 --- a/src/util.ts +++ b/src/util.ts @@ -141,6 +141,14 @@ export function resolveStepContext(sessionID: string, assistantMessageID: string return spanContext ? trace.setSpanContext(parent, spanContext) : parent } +export function resolveToolContext(callID: string, sessionID: string, assistantMessageID: string, ctx: HandlerContext): Context { + const parent = resolveStepContext(sessionID, assistantMessageID, ctx) + const span = ctx.tracing.toolSpans.get(callID) + if (span) return trace.setSpan(parent, span) + const spanContext = ctx.tracing.toolSpanContexts.get(callID) + return spanContext ? trace.setSpanContext(parent, spanContext) : parent +} + /** Resolves a child run under its correlated dispatch tool, falling back to the parent run. */ export function resolveSubagentTraceContext(sessionID: string, parentID: string, agent: string, ctx: HandlerContext): Context { const exact = ctx.tracing.subagentParents.get(sessionID) diff --git a/tests/handlers/log-context.test.ts b/tests/handlers/log-context.test.ts new file mode 100644 index 0000000..04da5fe --- /dev/null +++ b/tests/handlers/log-context.test.ts @@ -0,0 +1,167 @@ +import { describe, expect, test } from "bun:test" +import { trace } from "@opentelemetry/api" +import { InMemoryLogRecordExporter, LoggerProvider, SimpleLogRecordProcessor } from "@opentelemetry/sdk-logs" +import { finalizeSession, handleExecutionEnded, handleExecutionStarted, handlePromptEnqueued, handleSessionCreated } from "../../src/handlers/session.ts" +import { handleStepEnded, handleStepFailed, handleStepStarted } from "../../src/handlers/step.ts" +import { handleToolCalled, handleToolFailed, handleToolInputStarted, handleToolSuccess } from "../../src/handlers/tool.ts" +import { evt, makeCtx, tokens } from "../helpers.ts" + +function seed(ctx: ReturnType["ctx"], sessionID = "session", messageID = "message") { + handleSessionCreated(evt("session.created", { sessionID, agent: "build" }), ctx) + handleExecutionStarted(evt("session.execution.started", { sessionID }), ctx) + handleStepStarted(evt("session.step.started", { + sessionID, + assistantMessageID: messageID, + agent: "build", + model: { id: "model", providerID: "provider" }, + }), ctx) +} + +describe("native log trace context", () => { + test("keeps a queued prompt uncorrelated with the preceding execution", () => { + const { ctx, logger, tracer } = makeCtx() + seed(ctx) + const previousRun = ctx.tracing.runSpans.get("session")! + handlePromptEnqueued(evt("session.inbox.enqueued", { + sessionID: "session", inboxID: "queued", + item: { type: "user", payload: { text: "next execution" }, delivery: "queue" }, + }), ctx, false) + const record = logger.records.at(-1)! + expect(record.body).toBe("user_prompt") + expect(record.context).toBeUndefined() + handleExecutionEnded(evt("session.execution.succeeded", { sessionID: "session" }), ctx, { type: "succeeded" }) + finalizeSession("session", ctx) + handleExecutionStarted(evt("session.execution.started", { sessionID: "session" }), ctx) + const nextRun = tracer.spans.at(-1)! + expect(nextRun.attributes["input.value"]).toBe("next execution") + expect(nextRun.spanContext().spanId).not.toBe(previousRun.spanContext().spanId) + expect(record.context).toBeUndefined() + }) + + test("correlates a steering prompt with its active execution", () => { + const { ctx, logger } = makeCtx() + seed(ctx) + handlePromptEnqueued(evt("session.inbox.enqueued", { + sessionID: "session", inboxID: "steering", + item: { type: "user", payload: { text: "adjust current execution" }, delivery: "steer" }, + }), ctx, false) + expect(trace.getSpanContext(logger.records.at(-1)!.context!)).toEqual( + ctx.tracing.runSpans.get("session")!.spanContext(), + ) + expect(ctx.tracing.activePrompts.get("session")?.text).toBe("adjust current execution") + expect(ctx.tracing.pendingPrompts.has("session")).toBe(false) + }) + + test("leaves a steering prompt without an active execution uncorrelated", () => { + const { ctx, logger } = makeCtx() + handleSessionCreated(evt("session.created", { sessionID: "session", agent: "build" }), ctx) + handlePromptEnqueued(evt("session.inbox.enqueued", { + sessionID: "session", inboxID: "initial", + item: { type: "user", payload: { text: "start execution" }, delivery: "steer" }, + }), ctx, false) + expect(logger.records.at(-1)!.context).toBeUndefined() + expect(ctx.tracing.pendingPrompts.get("session")?.[0]?.text).toBe("start execution") + }) + + for (const failed of [false, true]) { + test(`captures the completed LLM context before cleanup (${failed ? "failure" : "success"})`, () => { + const { ctx, logger, tracer } = makeCtx() + seed(ctx) + const data = { sessionID: "session", assistantMessageID: "message", finish: "stop", cost: 1, tokens: tokens() } + if (failed) handleStepFailed(evt("session.step.failed", { ...data, error: { type: "error", message: "failed" } }), ctx) + else handleStepEnded(evt("session.step.ended", data), ctx) + const span = tracer.spans.find(item => item.name === "opencode.llm")! + const record = logger.records.at(-1)! + expect(trace.getSpanContext(record.context!)).toEqual(span.spanContext()) + expect(span.ended).toBe(true) + expect(ctx.tracing.stepSpans.size).toBe(0) + expect(ctx.tracing.stepSpanContexts.size).toBe(0) + }) + + test(`uses the exact tool context with overlapping calls (${failed ? "failure" : "success"})`, () => { + const { ctx, logger, tracer } = makeCtx() + seed(ctx) + for (const id of ["first", "second"]) { + handleToolInputStarted(evt("session.tool.input.started", { sessionID: "session", assistantMessageID: "message", id, name: "shell" }), ctx) + handleToolCalled(evt("session.tool.called", { sessionID: "session", assistantMessageID: "message", id, input: { command: "git commit -m test" } }), ctx) + } + const data = { sessionID: "session", assistantMessageID: "message", id: "first", content: [{ type: "text", text: "result" }] } + if (failed) handleToolFailed(evt("session.tool.failed", { ...data, error: { type: "error", message: "failed" } }), ctx) + else handleToolSuccess(evt("session.tool.success", data), ctx) + const span = tracer.spans.find(item => item.attributes["tool.id"] === "first")! + const record = logger.records.at(-1)! + expect(trace.getSpanContext(record.context!)).toEqual(span.spanContext()) + expect(span.ended).toBe(true) + expect(ctx.tracing.toolSpans.has("first")).toBe(false) + expect(ctx.tracing.toolSpans.has("second")).toBe(true) + if (!failed) { + const commit = logger.records.find(item => item.body === "commit")! + expect(trace.getSpanContext(commit.context!)).toEqual(span.spanContext()) + } + }) + } + + test("uses the failed execution context after its run span ends", () => { + const { ctx, logger, tracer } = makeCtx() + seed(ctx) + handleExecutionEnded(evt("session.execution.failed", { sessionID: "session" }), ctx, { + type: "failed", error: { type: "error", message: "failed" }, + }) + const span = tracer.spans.find(item => item.name === "opencode.session")! + expect(trace.getSpanContext(logger.records.at(-1)!.context!)).toEqual(span.spanContext()) + expect(ctx.tracing.runSpans.size).toBe(0) + }) + + test("falls back to the run when LLM spans are disabled", () => { + const { ctx, logger, tracer } = makeCtx("project", [], ["llm"]) + seed(ctx) + handleStepEnded(evt("session.step.ended", { sessionID: "session", assistantMessageID: "message", finish: "stop", cost: 1, tokens: tokens() }), ctx) + const span = tracer.spans.find(item => item.name === "opencode.session")! + expect(trace.getSpanContext(logger.records.at(-1)!.context!)).toEqual(span.spanContext()) + }) + + test("does not invent context with tracing disabled or a missed start event", () => { + for (const disabled of [[], ["session", "llm", "tool"]]) { + const { ctx, logger, tracer } = makeCtx("project", [], disabled) + if (disabled.length) seed(ctx) + handleStepEnded(evt("session.step.ended", { sessionID: "session", assistantMessageID: "message", finish: "stop", cost: 1, tokens: tokens() }), ctx) + expect(trace.getSpanContext(logger.records.at(-1)!.context!)).toBeUndefined() + expect(tracer.spans).toHaveLength(0) + } + }) + + test("keeps contexts isolated between sessions", () => { + const { ctx, logger, tracer } = makeCtx() + seed(ctx, "first", "message-first") + seed(ctx, "second", "message-second") + handleStepEnded(evt("session.step.ended", { sessionID: "first", assistantMessageID: "message-first", finish: "stop", cost: 1, tokens: tokens() }), ctx) + const span = tracer.spans.find(item => item.name === "opencode.llm" && item.attributes["session.id"] === "first")! + expect(trace.getSpanContext(logger.records.at(-1)!.context!)).toEqual(span.spanContext()) + }) + + test("does not enable logs when the content policy disables them", () => { + const { ctx, logger } = makeCtx("project", [], [], false) + seed(ctx) + handleStepEnded(evt("session.step.ended", { sessionID: "session", assistantMessageID: "message", finish: "stop", cost: 1, tokens: tokens() }), ctx) + expect(logger.records).toHaveLength(0) + }) + + test("exports native traceId and spanId with the real logs SDK", async () => { + const { ctx, logger, tracer } = makeCtx() + const exporter = new InMemoryLogRecordExporter() + const provider = new LoggerProvider({ processors: [new SimpleLogRecordProcessor(exporter)] }) + try { + seed(ctx) + handleStepEnded(evt("session.step.ended", { sessionID: "session", assistantMessageID: "message", finish: "stop", cost: 1, tokens: tokens() }), ctx) + provider.getLogger("test").emit(logger.records.at(-1)!) + await provider.forceFlush() + const span = tracer.spans.find(item => item.name === "opencode.llm")! + const record = exporter.getFinishedLogRecords()[0]! + expect(record.spanContext?.traceId).toBe(span.spanContext().traceId) + expect(record.spanContext?.spanId).toBe(span.spanContext().spanId) + expect(record.attributes["trace_id"]).toBeUndefined() + } finally { + await provider.shutdown() + } + }) +}) diff --git a/tests/integration/opencode.test.ts b/tests/integration/opencode.test.ts index 31ac8c3..fd2dab8 100644 --- a/tests/integration/opencode.test.ts +++ b/tests/integration/opencode.test.ts @@ -24,7 +24,10 @@ test("exports real OpenCode session telemetry over OTLP/JSON", async () => { expect(Number(sessions["asDouble"] ?? sessions["asInt"])).toBe(1) expect(attributes(sessions)["session.id"]).toBe(result["sessionID"]) const logs = signalRecords(received["logs"]!, "Logs") - expect(logs.some(log => attributes(log)["event.name"] === "api_request")).toBe(true) + const apiLog = logs.find(log => attributes(log)["event.name"] === "api_request")! + expect(apiLog).toBeDefined() + expect(apiLog["traceId"]).toBe(llm["traceId"]) + expect(apiLog["spanId"]).toBe(llm["spanId"]) expect(logs.some(log => attributes(log)["event.name"] === "session.idle")).toBe(true) }, 40_000) @@ -64,6 +67,10 @@ for (const disabled of [false, true]) { expect(parent["name"]).toBe("opencode.llm") expect(tool!["traceId"]).toBe(parent["traceId"]) expect(attributes(tool!)["output.value"]).toContain("integration-fixture-contents") + const log = signalRecords(scenario.received["logs"]!, "Logs") + .find(record => attributes(record)["event.name"] === "tool_result")! + expect(log["traceId"]).toBe(tool!["traceId"]) + expect(log["spanId"]).toBe(tool!["spanId"]) }) }