diff --git a/src/handlers/tool.ts b/src/handlers/tool.ts index ef39a34..07fe8f6 100644 --- a/src/handlers/tool.ts +++ b/src/handlers/tool.ts @@ -42,55 +42,61 @@ export function handleToolInputStarted(e: EventOf<"session.tool.input.started">, }) } -/** Attaches tool input to the span and retains the command for terminal commit detection. */ +/** Starts timing and tracing an observed tool call, and retains the command for commit detection. */ export function handleToolCalled(e: EventOf<"session.tool.called">, ctx: HandlerContext) { const d = e.data const meta = ctx.tracing.toolMeta.get(d.id) - const isSubagent = meta?.tool === "subagent" - const runs = d.executed - const { agentName, agentType } = getSessionAgentMeta(d.sessionID, ctx) - const inputJson = safeJson(d.input) - if (meta && (runs || isSubagent)) { - setBoundedMap(ctx.tracing.toolMeta, d.id, { - ...meta, - startMs: e.created, - executionStarted: runs, - ...(isSubagent && typeof d.input["agent"] === "string" ? { agent: d.input["agent"] } : {}), - }) - } + if (!meta) return + const isSubagent = meta.tool === "subagent" + setBoundedMap(ctx.tracing.toolMeta, d.id, { + ...meta, + startMs: e.created, + executionStarted: true, + ...(isSubagent && typeof d.input["agent"] === "string" ? { agent: d.input["agent"] } : {}), + ...(typeof d.input["command"] === "string" ? { command: d.input["command"] } : {}), + }) - const span = runs && meta && isTraceEnabled("tool", ctx) - ? ctx.tracer.startSpan( - `${ctx.tracePrefix}tool.${meta.tool}`, - { - startTime: e.created, - kind: SpanKind.INTERNAL, - attributes: { - [OPENINFERENCE_SPAN_KIND]: OpenInferenceSpanKind.TOOL, - [SESSION_ID]: d.sessionID, - [TOOL_ID]: d.id, - [TOOL_NAME]: meta.tool, - ...ctx.commonAttrs, - }, + if (!isTraceEnabled("tool", ctx)) return + if (isSubagent) startSubagentSpan(d.id, ctx) + else { + const span = ctx.tracer.startSpan( + `${ctx.tracePrefix}tool.${meta.tool}`, + { + startTime: e.created, + kind: SpanKind.INTERNAL, + attributes: { + [OPENINFERENCE_SPAN_KIND]: OpenInferenceSpanKind.TOOL, + [SESSION_ID]: d.sessionID, + [TOOL_ID]: d.id, + [TOOL_NAME]: meta.tool, + ...ctx.commonAttrs, }, - resolveStepContext(d.sessionID, d.assistantMessageID, ctx), - ) - : undefined - if (span) { + }, + resolveStepContext(d.sessionID, d.assistantMessageID, ctx), + ) setBoundedMap(ctx.tracing.toolSpans, d.id, span) setBoundedMap(ctx.tracing.toolSpanContexts, d.id, span.spanContext()) - span.setAttributes({ - [TOOL_PARAMETERS]: inputJson, - [INPUT_VALUE]: inputJson, - [INPUT_MIME_TYPE]: MimeType.JSON, - [AGENT_NAME]: agentName, - "agent.type": agentType, - }) } - if (meta && typeof d.input["command"] === "string") { - setBoundedMap(ctx.tracing.toolMeta, d.id, { ...ctx.tracing.toolMeta.get(d.id)!, command: d.input["command"] }) - } + const { agentName, agentType } = getSessionAgentMeta(d.sessionID, ctx) + const inputJson = safeJson(d.input) + ctx.tracing.toolSpans.get(d.id)?.setAttributes({ + [TOOL_PARAMETERS]: inputJson, + [INPUT_VALUE]: inputJson, + [INPUT_MIME_TYPE]: MimeType.JSON, + [AGENT_NAME]: agentName, + "agent.type": agentType, + "tool.provider_executed": isProviderExecuted(d), + }) +} + +type ProviderExecution = { + readonly executed?: boolean + readonly provider?: { readonly executed?: boolean } +} + +function isProviderExecuted(data: ProviderExecution): boolean { + return data.provider?.executed ?? data.executed ?? false } function startSubagentSpan(callID: string, ctx: HandlerContext) { @@ -140,14 +146,14 @@ export function handleToolProgress(e: EventOf<"session.tool.progress">, ctx: Han export function handleToolSuccess(e: EventOf<"session.tool.success">, ctx: HandlerContext) { linkSubagent(e.data.id, e.data.metadata?.["sessionID"], ctx) const output = contentText(e.data.content) - finishTool(e.data.id, e.data.sessionID, e.created, true, e.data.executed, output, undefined, ctx) + finishTool(e.data.id, e.data.sessionID, e.created, true, output, undefined, ctx) } /** Ends a failed tool call: records duration, sets error attributes, and emits `tool_result`. */ export function handleToolFailed(e: EventOf<"session.tool.failed">, ctx: HandlerContext) { linkSubagent(e.data.id, e.data.metadata?.["sessionID"], ctx) const output = contentText(e.data.content) - finishTool(e.data.id, e.data.sessionID, e.created, false, e.data.executed, output, errorSummary(e.data.error), ctx) + finishTool(e.data.id, e.data.sessionID, e.created, false, output, errorSummary(e.data.error), ctx) } function finishTool( @@ -155,7 +161,6 @@ function finishTool( sessionID: string, endMs: number, success: boolean, - executed: boolean, output: string, error: string | undefined, ctx: HandlerContext, @@ -163,13 +168,13 @@ function finishTool( const meta = ctx.tracing.toolMeta.get(callID) ctx.tracing.toolMeta.delete(callID) const tool = meta?.tool ?? "unknown" - const observedExecution = executed || (tool === "subagent" && meta?.executionStarted === true) - const start = observedExecution && meta?.executionStarted ? meta.startMs : endMs + const observedExecution = meta?.executionStarted === true + const start = observedExecution ? meta.startMs : endMs const durationMs = Math.max(0, endMs - start) const { agentName, agentType } = getSessionAgentMeta(sessionID, ctx) const sizeBytes = output ? Buffer.byteLength(output, "utf8") : 0 - if (success && executed && meta?.command && SHELL_TOOL_RE.test(tool) && GIT_COMMIT_RE.test(meta.command)) { + if (success && observedExecution && meta.command && SHELL_TOOL_RE.test(tool) && GIT_COMMIT_RE.test(meta.command)) { if (isMetricEnabled("commit.count", ctx)) { ctx.instruments.commitCounter.add(1, { ...ctx.commonAttrs, "session.id": sessionID }) } diff --git a/tests/handlers/disabled.test.ts b/tests/handlers/disabled.test.ts index 754e0dc..62df498 100644 --- a/tests/handlers/disabled.test.ts +++ b/tests/handlers/disabled.test.ts @@ -1,7 +1,7 @@ import { describe, test, expect } from "bun:test" import { handleExecutionStarted, handleSessionCreated, handleSessionStatus, handleUsageUpdated, finalizeSession } from "../../src/handlers/session.ts" import { handleStepEnded, handleStepStarted } from "../../src/handlers/step.ts" -import { handleToolInputStarted } from "../../src/handlers/tool.ts" +import { handleToolCalled, handleToolInputStarted, handleToolSuccess } from "../../src/handlers/tool.ts" import { makeCtx, evt, tokens } from "../helpers.ts" describe("disabled metrics", () => { @@ -49,11 +49,26 @@ describe("disabled traces", () => { expect(tracer.spans.map((s) => s.name)).toEqual(["opencode.session"]) }) - test("tool spans can be disabled", () => { - const { ctx, tracer } = makeCtx("proj_test", [], ["tool"]) + test("tool spans can be disabled without disabling tool metrics or commit detection", () => { + const { ctx, tracer, counters, histograms, logger } = makeCtx("proj_test", [], ["tool"]) handleSessionCreated(evt("session.created", { sessionID: "ses_1" }), ctx) handleExecutionStarted(evt("session.execution.started", { sessionID: "ses_1" }), ctx) - handleToolInputStarted(evt("session.tool.input.started", { sessionID: "ses_1", assistantMessageID: "m", id: "c", name: "read" }), ctx) + const call = { sessionID: "ses_1", assistantMessageID: "m", id: "c", executed: false } + handleToolInputStarted(evt("session.tool.input.started", { ...call, name: "shell" }, 1000), ctx) + handleToolCalled(evt("session.tool.called", { ...call, input: { command: "git commit -m 'test'" } }, 2000), ctx) expect(tracer.spans.map((s) => s.name)).toEqual(["opencode.session"]) + expect(counters.commit.calls).toHaveLength(0) + expect(logger.records.filter((record) => record.body === "commit")).toHaveLength(0) + handleToolSuccess(evt("session.tool.success", { ...call, content: [{ type: "text", text: "committed" }] }, 2250), ctx) + expect(tracer.spans.map((s) => s.name)).toEqual(["opencode.session"]) + expect(histograms.tool.calls).toHaveLength(1) + expect(histograms.tool.calls[0]!.value).toBe(250) + expect(histograms.tool.calls[0]!.attrs).toMatchObject({ tool_name: "shell", success: true }) + const toolResults = logger.records.filter((record) => record.body === "tool_result") + expect(toolResults).toHaveLength(1) + expect(toolResults[0]!.attributes?.["duration_ms"]).toBe(250) + expect(counters.commit.calls).toHaveLength(1) + expect(counters.commit.calls[0]!.value).toBe(1) + expect(logger.records.filter((record) => record.body === "commit")).toHaveLength(1) }) }) diff --git a/tests/handlers/spans.test.ts b/tests/handlers/spans.test.ts index 44ae196..e63fad3 100644 --- a/tests/handlers/spans.test.ts +++ b/tests/handlers/spans.test.ts @@ -16,7 +16,7 @@ describe("trace nesting", () => { ctx, ) handleToolInputStarted(evt("session.tool.input.started", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", name: "read" }), ctx) - handleToolCalled(evt("session.tool.called", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", input: {}, executed: true }), ctx) + handleToolCalled(evt("session.tool.called", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", input: {}, executed: false }), ctx) const run = tracer.spans.find((s) => s.name === "opencode.session")! const step = tracer.spans.find((s) => s.name === "opencode.llm")! diff --git a/tests/handlers/tool.test.ts b/tests/handlers/tool.test.ts index cd31e66..b7c10b3 100644 --- a/tests/handlers/tool.test.ts +++ b/tests/handlers/tool.test.ts @@ -13,6 +13,23 @@ function inputStarted(id = "call_1", name = "bash", sessionID = "ses_1", created return evt("session.tool.input.started", { sessionID, assistantMessageID: "msg_1", id, name }, created) } +type Execution = { executed: boolean } | { provider: { executed: boolean } } + +const local: Execution = { executed: false } +const hosted: Execution = { executed: true } + +function called(id: string, input: Record, execution: Execution, created = 1000) { + return evt("session.tool.called", { sessionID: "ses_1", assistantMessageID: "msg_1", id, input, ...execution }, created) +} + +function succeeded(id: string, text: string, execution: Execution, created = 1000) { + return evt("session.tool.success", { sessionID: "ses_1", assistantMessageID: "msg_1", id, content: [{ type: "text", text }], ...execution }, created) +} + +function failed(id: string, error: { type: string; message: string }, execution: Execution, created = 1000) { + return evt("session.tool.failed", { sessionID: "ses_1", assistantMessageID: "msg_1", id, error, ...execution }, created) +} + describe("handleToolInputStarted", () => { test("stores the tool name without counting model input streaming as execution", () => { const { ctx, tracer } = makeCtx() @@ -24,89 +41,154 @@ describe("handleToolInputStarted", () => { }) describe("handleToolCalled", () => { - test("attaches parameters and detects a git commit", () => { + test("attaches parameters and detects a local git commit", () => { const { ctx, counters, logger, tracer } = makeCtx() seed(ctx) - handleToolInputStarted(inputStarted(), ctx) - handleToolCalled(evt("session.tool.called", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", input: { command: "git commit -m 'x'" }, executed: true }), ctx) + handleToolInputStarted(inputStarted("call_1", "shell"), ctx) + handleToolCalled(called("call_1", { command: "git commit -m 'x'" }, local), ctx) expect(counters.commit.calls).toHaveLength(0) - handleToolSuccess(evt("session.tool.success", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", content: [{ type: "text", text: "commit made" }], executed: true }), ctx) + handleToolSuccess(succeeded("call_1", "commit made", local), ctx) expect(counters.commit.calls).toHaveLength(1) expect(logger.records.some((record) => record.body === "commit")).toBe(true) - const span = tracer.spans.find((s) => s.name === "opencode.tool.bash")! + const span = tracer.spans.find((s) => s.name === "opencode.tool.shell")! expect(span.attributes["input.value"]).toContain("git commit") + expect(span.attributes["tool.provider_executed"]).toBe(false) }) test("ignores non-commit shell commands", () => { const { ctx, counters } = makeCtx() seed(ctx) handleToolInputStarted(inputStarted(), ctx) - handleToolCalled(evt("session.tool.called", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", input: { command: "ls -la" }, executed: true }), ctx) + handleToolCalled(called("call_1", { command: "ls -la" }, local), ctx) + handleToolSuccess(succeeded("call_1", "listing", local), ctx) expect(counters.commit.calls).toHaveLength(0) }) - test("does not count unexecuted or failed git commits", () => { + test("does not count failed git commits", () => { const { ctx, counters } = makeCtx() seed(ctx) handleToolInputStarted(inputStarted(), ctx) - handleToolCalled(evt("session.tool.called", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", input: { command: "git commit -m test" }, executed: false }), ctx) - handleToolSuccess(evt("session.tool.success", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", content: [{ type: "text", text: "skipped" }], executed: false }), ctx) - handleToolInputStarted(inputStarted("call_2"), ctx) - handleToolCalled(evt("session.tool.called", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_2", input: { command: "git commit -m test" }, executed: true }), ctx) - handleToolFailed(evt("session.tool.failed", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_2", error: { type: "ToolError", message: "failed" }, executed: true }), ctx) + handleToolCalled(called("call_1", { command: "git commit -m test" }, local), ctx) + handleToolFailed(failed("call_1", { type: "tool.execution", message: "failed" }, local), ctx) expect(counters.commit.calls).toHaveLength(0) }) }) describe("handleToolSuccess", () => { - test("records duration, sets output, and emits tool_result", () => { + test("records a locally executed tool", () => { const { ctx, histograms, logger, tracer } = makeCtx() seed(ctx) handleToolInputStarted(inputStarted("call_1", "read", "ses_1", 1000), ctx) - handleToolCalled(evt("session.tool.called", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", input: {}, executed: true }, 1000), ctx) - handleToolSuccess(evt("session.tool.success", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", content: [{ type: "text", text: "file body" }], executed: true }, 1250), ctx) + handleToolCalled(called("call_1", {}, local, 1000), ctx) + handleToolSuccess(succeeded("call_1", "file body", local, 1250), ctx) + expect(histograms.tool.calls).toHaveLength(1) expect(histograms.tool.calls[0]!.value).toBe(250) expect(histograms.tool.calls[0]!.attrs["success"]).toBe(true) const record = logger.records.at(-1)! expect(record.body).toBe("tool_result") expect(record.attributes?.["duration_ms"]).toBe(250) const span = tracer.spans.find((s) => s.name === "opencode.tool.read")! - expect(span.ended).toBe(true) + expect(span.startTime).toBe(1000) + expect(span.endTime).toBe(1250) expect(span.status.code).toBe(SpanStatusCode.OK) expect(span.attributes["output.value"]).toBe("file body") }) + + test("records a provider-executed tool", () => { + const { ctx, histograms, tracer } = makeCtx() + seed(ctx) + handleToolInputStarted(inputStarted("call_1", "web_search", "ses_1", 1000), ctx) + handleToolCalled(called("call_1", { query: "otel" }, hosted, 1000), ctx) + handleToolSuccess(succeeded("call_1", "results", hosted, 1040), ctx) + expect(histograms.tool.calls[0]!.value).toBe(40) + const span = tracer.spans.find((s) => s.name === "opencode.tool.web_search")! + expect(span.ended).toBe(true) + expect(span.attributes["tool.provider_executed"]).toBe(true) + }) + + test("accepts the nested provider execution shape", () => { + const { ctx, histograms, tracer } = makeCtx() + seed(ctx) + for (const [id, executed] of [["call_1", false], ["call_2", true]] as const) { + handleToolInputStarted(inputStarted(id, "read", "ses_1", 1000), ctx) + handleToolCalled(called(id, {}, { provider: { executed } }, 1000), ctx) + handleToolSuccess(succeeded(id, "ok", { provider: { executed } }, 1100), ctx) + } + expect(histograms.tool.calls.map((call) => call.value)).toEqual([100, 100]) + expect(tracer.spans.filter((s) => s.name === "opencode.tool.read").map((s) => s.attributes["tool.provider_executed"])).toEqual([false, true]) + }) }) describe("handleToolFailed", () => { - test("records an error result and ends the span with error", () => { + test("records a failed local tool and ends the span with error", () => { const { ctx, histograms, logger, tracer } = makeCtx() seed(ctx) handleToolInputStarted(inputStarted(), ctx) - handleToolCalled(evt("session.tool.called", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", input: {}, executed: true }, 1000), ctx) - handleToolFailed(evt("session.tool.failed", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", error: { type: "ToolError", message: "nope" }, executed: true }, 1200), ctx) + handleToolCalled(called("call_1", {}, local, 1000), ctx) + handleToolFailed(failed("call_1", { type: "tool.execution", message: "nope" }, local, 1200), ctx) + expect(histograms.tool.calls).toHaveLength(1) + expect(histograms.tool.calls[0]!.value).toBe(200) expect(histograms.tool.calls[0]!.attrs["success"]).toBe(false) - expect(logger.records.at(-1)!.attributes?.["error"]).toBe("ToolError: nope") + expect(logger.records.at(-1)!.attributes?.["duration_ms"]).toBe(200) + expect(logger.records.at(-1)!.attributes?.["error"]).toBe("tool.execution: nope") const span = tracer.spans.find((s) => s.name === "opencode.tool.bash")! + expect(span.ended).toBe(true) expect(span.status.code).toBe(SpanStatusCode.ERROR) }) + test("records a failed provider-executed tool", () => { + const { ctx, histograms, tracer } = makeCtx() + seed(ctx) + handleToolInputStarted(inputStarted("call_1", "web_search"), ctx) + handleToolCalled(called("call_1", {}, hosted, 1000), ctx) + handleToolFailed(failed("call_1", { type: "tool.execution", message: "nope" }, hosted, 1010), ctx) + expect(histograms.tool.calls[0]!.value).toBe(10) + expect(histograms.tool.calls[0]!.attrs["success"]).toBe(false) + expect(tracer.spans.find((s) => s.name === "opencode.tool.web_search")!.status.code).toBe(SpanStatusCode.ERROR) + }) + + test("records a permission rejection after the call as a failed execution", () => { + const { ctx, histograms, tracer } = makeCtx() + seed(ctx) + handleToolInputStarted(inputStarted("call_1", "shell"), ctx) + handleToolCalled(called("call_1", { command: "git commit -m x" }, local, 1000), ctx) + handleToolFailed(failed("call_1", { type: "permission.rejected", message: "denied" }, local, 1500), ctx) + expect(histograms.tool.calls[0]!.value).toBe(500) + expect(histograms.tool.calls[0]!.attrs["success"]).toBe(false) + expect(tracer.spans.find((s) => s.name === "opencode.tool.shell")!.attributes["tool.error"]).toBe("permission.rejected: denied") + }) + + test("does not record malformed input that was never called", () => { + const { ctx, histograms, logger, tracer } = makeCtx() + seed(ctx) + handleToolInputStarted(inputStarted("call_1", "shell"), ctx) + handleToolFailed(failed("call_1", { type: "tool.input-json", message: "malformed" }, local, 1200), ctx) + expect(histograms.tool.calls).toHaveLength(0) + expect(tracer.spans.some((s) => s.name.startsWith("opencode.tool."))).toBe(false) + expect(logger.records.at(-1)!.attributes?.["duration_ms"]).toBe(0) + expect(ctx.tracing.toolMeta.has("call_1")).toBe(false) + }) + test("measures execution from called, excluding slow argument streaming", () => { const { ctx, histograms, tracer } = makeCtx() seed(ctx) handleToolInputStarted(inputStarted("call_1", "read", "ses_1", 1000), ctx) - handleToolCalled(evt("session.tool.called", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", input: {}, executed: true }, 5000), ctx) - handleToolSuccess(evt("session.tool.success", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_1", content: [{ type: "text", text: "ok" }], executed: true }, 5300), ctx) + handleToolCalled(called("call_1", {}, local, 5000), ctx) + handleToolSuccess(succeeded("call_1", "ok", local, 5300), ctx) expect(histograms.tool.calls[0]!.value).toBe(300) expect(tracer.spans.find((span) => span.name === "opencode.tool.read")?.startTime).toBe(5000) }) - test("does not create a dispatch span for an invalid subagent call without a child", () => { + test("records a subagent call that fails before creating a child", () => { const { ctx, tracer, histograms } = makeCtx() seed(ctx) handleToolInputStarted(inputStarted("call_2", "subagent"), ctx) - handleToolCalled(evt("session.tool.called", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_2", input: { agent: "explore" }, executed: false }), ctx) - handleToolFailed(evt("session.tool.failed", { sessionID: "ses_1", assistantMessageID: "msg_1", id: "call_2", error: { type: "invalid", message: "missing input" }, executed: false }), ctx) - expect(tracer.spans.some((span) => span.name === "opencode.tool.subagent")).toBe(false) - expect(histograms.tool.calls).toHaveLength(0) + handleToolCalled(called("call_2", { agent: "explore" }, local, 1000), ctx) + handleToolFailed(failed("call_2", { type: "invalid", message: "missing input" }, local, 1100), ctx) + const span = tracer.spans.find((s) => s.name === "opencode.tool.subagent")! + expect(span.attributes["subagent.agent"]).toBe("explore") + expect(span.status.code).toBe(SpanStatusCode.ERROR) + expect(histograms.tool.calls[0]!.value).toBe(100) + expect(histograms.tool.calls[0]!.attrs["success"]).toBe(false) }) }) diff --git a/tests/integration/opencode.test.ts b/tests/integration/opencode.test.ts index 8af118a..31ac8c3 100644 --- a/tests/integration/opencode.test.ts +++ b/tests/integration/opencode.test.ts @@ -56,7 +56,7 @@ for (const disabled of [false, true]) { .some(span => String(span["name"]).startsWith("opencode.tool."))).toBe(false) }) } else { - test.failing("#134: exports a locally executed tool span under its LLM span", () => { + test("#134: exports a locally executed tool span under its LLM span", () => { const spans = signalRecords(scenario.received["traces"]!, "Spans") const tool = spans.find(span => span["name"] === "opencode.tool.read") expect(tool).toBeDefined() @@ -67,7 +67,7 @@ for (const disabled of [false, true]) { }) } - test.failing("#134: exports a duration sample for the locally executed tool", () => { + test("#134: exports a duration sample for the locally executed tool", () => { const metrics = signalRecords(scenario.received["metrics"]!, "Metrics") const points = metricPoints(metrics, "opencode.tool.duration", "histogram") .filter(point => attributes(point)["tool_name"] === "read")