diff --git a/src/agents/pi-embedded-subscribe.handlers.tools.test.ts b/src/agents/pi-embedded-subscribe.handlers.tools.test.ts index 10a147d4c17c..1c80060a0c7d 100644 --- a/src/agents/pi-embedded-subscribe.handlers.tools.test.ts +++ b/src/agents/pi-embedded-subscribe.handlers.tools.test.ts @@ -24,14 +24,21 @@ function createTestContext(): { onBlockReplyFlush: ReturnType; onAgentEvent: ReturnType; onExecutionPhase: ReturnType; + trace: ReturnType; + isEnabled: ReturnType; } { const onBlockReplyFlush = vi.fn(); const onAgentEvent = vi.fn(); const onExecutionPhase = vi.fn(); const warn = vi.fn(); + const trace = vi.fn(); + const isEnabled = vi.fn(() => false); const ctx: ToolHandlerContext = { params: { runId: "run-test", + sessionKey: "agent:unit-session", + sessionId: "session-test-id", + agentId: "agent-test-id", onBlockReplyFlush, onAgentEvent, onExecutionPhase, @@ -41,6 +48,8 @@ function createTestContext(): { hookRunner: undefined, log: { debug: vi.fn(), + trace, + isEnabled, info: vi.fn(), warn, }, @@ -76,7 +85,7 @@ function createTestContext(): { trimMessagingToolSent: vi.fn(), }; - return { ctx, warn, onBlockReplyFlush, onAgentEvent, onExecutionPhase }; + return { ctx, warn, onBlockReplyFlush, onAgentEvent, onExecutionPhase, trace, isEnabled }; } type CapturedAgentEvent = { stream?: string; data?: Record }; @@ -153,8 +162,57 @@ function requireSingleMessagingTarget(ctx: ToolHandlerContext) { } describe("handleToolExecutionStart read path checks", () => { + it("emits trace-only tool start diagnostics when trace logging is enabled", async () => { + const { ctx, trace, isEnabled, warn } = createTestContext(); + isEnabled.mockImplementation((level: string) => level === "trace"); + + const evt: ToolExecutionStartEvent = { + type: "tool_execution_start", + toolName: "write", + toolCallId: "tool-trace", + args: { path: "notes.txt" }, + }; + + await handleToolExecutionStart(ctx, evt); + + expect(warn).not.toHaveBeenCalled(); + expect(trace).toHaveBeenCalledTimes(1); + expect(trace.mock.calls[0]?.[0]).toBe("embedded run tool start"); + expect(trace.mock.calls[0]?.[1]).toEqual({ + event: "embedded_tool_execution_start", + tags: ["tool_start", "embedded", "trace"], + runId: "run-test", + toolName: "write", + toolCallId: "tool-trace", + argsType: "object", + argsKeys: ["path"], + sessionKey: "agent:unit-session", + sessionId: "session-test-id", + agentId: "agent-test-id", + requiredParamsMissing: ["content"], + }); + }); + + it("does not build trace tool start diagnostics unless trace logging is enabled", async () => { + const { ctx, trace, isEnabled } = createTestContext(); + + const evt: ToolExecutionStartEvent = { + type: "tool_execution_start", + toolName: "write", + toolCallId: "tool-trace-disabled", + args: { path: "notes.txt" }, + }; + + await handleToolExecutionStart(ctx, evt); + + expect(isEnabled).toHaveBeenCalledWith("trace"); + expect(trace).not.toHaveBeenCalled(); + }); + it("does not warn when read tool uses file_path alias", async () => { - const { ctx, warn, onBlockReplyFlush, onExecutionPhase } = createTestContext(); + const { ctx, warn, trace, isEnabled, onBlockReplyFlush, onExecutionPhase } = + createTestContext(); + isEnabled.mockImplementation((level: string) => level === "trace"); const evt: ToolExecutionStartEvent = { type: "tool_execution_start", @@ -173,6 +231,8 @@ describe("handleToolExecutionStart read path checks", () => { source: "pi-embedded", }); expect(warn).not.toHaveBeenCalled(); + expect(trace).toHaveBeenCalledTimes(1); + expect(trace.mock.calls[0]?.[1]).not.toHaveProperty("requiredParamsMissing"); }); it("warns when read tool has neither path nor file_path", async () => { @@ -188,7 +248,42 @@ describe("handleToolExecutionStart read path checks", () => { await handleToolExecutionStart(ctx, evt); expect(warn).toHaveBeenCalledTimes(1); - expect(String(warn.mock.calls[0]?.[0] ?? "")).toContain("read tool called without path"); + const warnMessage = String(warn.mock.calls[0]?.[0] ?? ""); + const warnMeta = warn.mock.calls[0]?.[1] as Record | undefined; + expect(warnMessage).toContain("read tool called without path"); + expect(warnMeta).toBeTypeOf("object"); + expect(warnMeta?.event).toBe("embedded_read_tool_start_warning"); + expect(warnMeta?.tags).toEqual(["tool_start", "read", "embedded", "validation"]); + expect(warnMeta?.runId).toBe("run-test"); + expect(warnMeta?.sessionKey).toBe("agent:unit-session"); + expect(warnMeta?.sessionId).toBe("session-test-id"); + expect(warnMeta?.agentId).toBe("agent-test-id"); + expect(warnMeta?.toolCallId).toBe("tool-2"); + expect(warnMeta?.argsType).toBe("object"); + expect(warnMeta?.consoleMessage).toContain("runId=run-test"); + expect(warnMeta?.consoleMessage).toContain("sessionKey=agent:unit-session"); + expect(warnMeta?.consoleMessage).toContain("sessionId=session-test-id"); + expect(warnMeta?.consoleMessage).toContain("agentId=agent-test-id"); + expect(warnMeta?.consoleMessage).toContain("toolCallId=tool-2"); + expect(warnMeta?.consoleMessage).toContain("argsType=object"); + expect(warnMeta?.consoleMessage).toContain("read tool called without path"); + expect(warnMeta).not.toHaveProperty("argsPreview"); + }); + + it("bounds string args before adding read warning preview", async () => { + const { ctx, warn } = createTestContext(); + + const evt: ToolExecutionStartEvent = { + type: "tool_execution_start", + toolName: "read", + toolCallId: "tool-string-args", + args: "x".repeat(500), + }; + + await handleToolExecutionStart(ctx, evt); + + const warnMeta = warn.mock.calls[0]?.[1] as Record | undefined; + expect(warnMeta?.argsPreview).toBe(`${"x".repeat(200)}…`); }); it("awaits onBlockReplyFlush before continuing tool start processing", async () => { diff --git a/src/agents/pi-embedded-subscribe.handlers.tools.ts b/src/agents/pi-embedded-subscribe.handlers.tools.ts index 10f9e8052ca6..4f2c654bcef8 100644 --- a/src/agents/pi-embedded-subscribe.handlers.tools.ts +++ b/src/agents/pi-embedded-subscribe.handlers.tools.ts @@ -29,6 +29,7 @@ import { truncateUtf16Safe } from "../utils.js"; import { normalizeAcceptedSessionSpawnResult } from "./accepted-session-spawn.js"; import type { ApplyPatchSummary } from "./apply-patch.js"; import type { ExecToolDetails } from "./bash-tools.exec-types.js"; +import { sanitizeForConsole } from "./console-sanitize.js"; import { parseExecApprovalResultText } from "./exec-approval-result.js"; import { normalizeTextForComparison } from "./pi-embedded-helpers.js"; import { isMessagingTool, isMessagingToolSendAction } from "./pi-embedded-messaging.js"; @@ -52,6 +53,7 @@ import { sanitizeToolResult, } from "./pi-embedded-subscribe.tools.js"; import { inferToolMetaFromArgs } from "./pi-embedded-utils.js"; +import { REQUIRED_PARAM_GROUPS, type RequiredParamGroup } from "./pi-tools.params.js"; import { buildToolMutationState, isSameToolMutationAction } from "./tool-mutation.js"; import { normalizeToolName } from "./tool-policy.js"; @@ -74,6 +76,11 @@ const beforeToolCallModuleLoader = createLazyImportLoader( ); const LIVE_EXEC_OUTPUT_MAX_CHARS = 8000; const LIVE_EXEC_UPDATE_MIN_INTERVAL_MS = 250; +const TRACE_REQUIRED_PARAM_GROUPS = { + read: [{ keys: ["path", "file_path"], label: "path" }], + write: REQUIRED_PARAM_GROUPS.write, + edit: REQUIRED_PARAM_GROUPS.edit, +} satisfies Record; function isMiddlewareToolResultError(result: unknown): boolean { if (!result || typeof result !== "object") { @@ -104,6 +111,85 @@ function loadBeforeToolCall(): Promise { return beforeToolCallModuleLoader.load(); } +function getRequiredParamGroupsForTool( + toolName: string, +): readonly RequiredParamGroup[] | undefined { + return TRACE_REQUIRED_PARAM_GROUPS[toolName as keyof typeof TRACE_REQUIRED_PARAM_GROUPS]; +} + +function collectMissingRequiredParamLabels(toolName: string, args: unknown): string[] { + const groups = getRequiredParamGroupsForTool(toolName); + if (!groups?.length) { + return []; + } + const record = args && typeof args === "object" ? (args as Record) : undefined; + if (!record) { + return groups.map((group) => group.label ?? group.keys.join(" or ")); + } + return groups + .filter((group) => { + const satisfied = + group.validator?.(record) ?? + group.keys.some((key) => { + const value = record[key]; + return typeof value === "string" && (group.allowEmpty || value.trim().length > 0); + }); + return !satisfied; + }) + .map((group) => group.label ?? group.keys.join(" or ")); +} + +function buildToolExecutionStartTraceMeta(params: { + ctx: ToolHandlerContext; + toolName: string; + toolCallId: string; + args: unknown; +}): Record { + const args = params.args; + const argsType = Array.isArray(args) ? "array" : typeof args; + const argsKeys = + args && typeof args === "object" && !Array.isArray(args) + ? Object.keys(args as Record).toSorted() + : undefined; + const requiredParamsMissing = collectMissingRequiredParamLabels(params.toolName, args); + return { + event: "embedded_tool_execution_start", + tags: ["tool_start", "embedded", "trace"], + runId: params.ctx.params.runId, + toolName: params.toolName, + toolCallId: params.toolCallId, + argsType, + ...(argsKeys?.length ? { argsKeys } : {}), + ...(params.ctx.params.sessionKey ? { sessionKey: params.ctx.params.sessionKey } : {}), + ...(params.ctx.params.sessionId ? { sessionId: params.ctx.params.sessionId } : {}), + ...(params.ctx.params.agentId ? { agentId: params.ctx.params.agentId } : {}), + ...(requiredParamsMissing.length ? { requiredParamsMissing } : {}), + }; +} + +function traceToolExecutionStart(params: { + ctx: ToolHandlerContext; + toolName: string; + toolCallId: string; + args: unknown; +}) { + if (!params.ctx.log.trace || params.ctx.log.isEnabled?.("trace") !== true) { + return; + } + params.ctx.log.trace( + "embedded run tool start", + buildToolExecutionStartTraceMeta({ + ctx: params.ctx, + toolName: params.toolName, + toolCallId: params.toolCallId, + args: params.args, + }), + ); +} + +const TOOL_START_WARNING_PREVIEW_MAX_CHARS = 200; +const TOOL_START_WARNING_RAW_PREVIEW_MAX_CHARS = TOOL_START_WARNING_PREVIEW_MAX_CHARS + 1; + type ToolStartRecord = { startTime: number; args: unknown; @@ -790,6 +876,7 @@ export function handleToolExecutionStart( // Track start time and args for after_tool_call hook. const startedAt = Date.now(); toolStartData.set(buildToolStartKey(runId, toolCallId), { startTime: startedAt, args }); + traceToolExecutionStart({ ctx, toolName, toolCallId, args }); if (toolName === "read") { const record = args && typeof args === "object" ? (args as Record) : {}; @@ -801,10 +888,50 @@ export function handleToolExecutionStart( : ""; const filePath = filePathValue.trim(); if (!filePath) { - const argsPreview = readStringValue(args)?.slice(0, 200); - ctx.log.warn( - `read tool called without path: toolCallId=${toolCallId} argsType=${typeof args}${argsPreview ? ` argsPreview=${argsPreview}` : ""}`, + const argsType = typeof args; + const rawArgsPreview = readStringValue(args); + const argsPreview = sanitizeForConsole( + rawArgsPreview?.slice(0, TOOL_START_WARNING_RAW_PREVIEW_MAX_CHARS), + TOOL_START_WARNING_PREVIEW_MAX_CHARS, ); + const safeRunId = sanitizeForConsole(runId) ?? "-"; + const safeSessionKey = sanitizeForConsole(ctx.params.sessionKey); + const safeSessionId = sanitizeForConsole(ctx.params.sessionId); + const safeAgentId = sanitizeForConsole(ctx.params.agentId); + const consoleMessageParts = [ + "read tool called without path:", + `runId=${safeRunId}`, + `toolCallId=${sanitizeForConsole(toolCallId) ?? "tool-call"}`, + `argsType=${argsType}`, + ]; + if (safeSessionKey) { + consoleMessageParts.push(`sessionKey=${safeSessionKey}`); + } + if (safeSessionId) { + consoleMessageParts.push(`sessionId=${safeSessionId}`); + } + if (safeAgentId) { + consoleMessageParts.push(`agentId=${safeAgentId}`); + } + if (argsPreview) { + consoleMessageParts.push(`argsPreview=${argsPreview}`); + } + const consoleMessage = consoleMessageParts.join(" "); + const message = `read tool called without path: toolCallId=${toolCallId} argsType=${argsType}${ + argsPreview ? ` argsPreview=${argsPreview}` : "" + }`; + ctx.log.warn(message, { + event: "embedded_read_tool_start_warning", + tags: ["tool_start", "read", "embedded", "validation"], + runId: ctx.params.runId, + toolCallId, + argsType, + ...(safeSessionKey ? { sessionKey: ctx.params.sessionKey } : {}), + ...(safeSessionId ? { sessionId: ctx.params.sessionId } : {}), + ...(safeAgentId ? { agentId: ctx.params.agentId } : {}), + ...(argsPreview ? { argsPreview } : {}), + consoleMessage, + }); } } diff --git a/src/agents/pi-embedded-subscribe.handlers.types.ts b/src/agents/pi-embedded-subscribe.handlers.types.ts index 7a5f6be26768..d921162bc669 100644 --- a/src/agents/pi-embedded-subscribe.handlers.types.ts +++ b/src/agents/pi-embedded-subscribe.handlers.types.ts @@ -24,6 +24,11 @@ import type { NormalizedUsage } from "./usage.js"; type EmbeddedSubscribeLogger = { debug: (message: string, meta?: Record) => void; + trace?: (message: string, meta?: Record) => void; + isEnabled?: ( + level: "trace" | "debug" | "info" | "warn" | "error" | "fatal", + target?: "any" | "console" | "file", + ) => boolean; info: (message: string, meta?: Record) => void; warn: (message: string, meta?: Record) => void; };