fix(agents): correlate pathless read diagnostics (#86977)

* fix(agents): correlate pathless read diagnostics * fix(agents): trace embedded tool starts * fix(agents): honor read aliases in trace diagnostics --------- Co-authored-by: Peter Steinberger <steipete@gmail.com>
2026-08-27 21:07:01 -06:00 · 2026-05-26 22:23:55 -04:00
parent cdfb1b4bf1
commit cecb07655a
3 changed files with 233 additions and 6 deletions
@@ -24,14 +24,21 @@ function createTestContext(): {
  onBlockReplyFlush: ReturnType<typeof vi.fn>;
  onAgentEvent: ReturnType<typeof vi.fn>;
  onExecutionPhase: ReturnType<typeof vi.fn>;
+  trace: ReturnType<typeof vi.fn>;
+  isEnabled: ReturnType<typeof vi.fn>;
 } {
  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<string, unknown> };
@@ -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<string, unknown> | 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<string, unknown> | undefined;
+    expect(warnMeta?.argsPreview).toBe(`${"x".repeat(200)}…`);
  });

  it("awaits onBlockReplyFlush before continuing tool start processing", async () => {
@@ -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<BeforeToolCallModule>(
 );
 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<string, readonly RequiredParamGroup[]>;

 function isMiddlewareToolResultError(result: unknown): boolean {
  if (!result || typeof result !== "object") {
@@ -104,6 +111,85 @@ function loadBeforeToolCall(): Promise<BeforeToolCallModule> {
  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<string, unknown>) : 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<string, unknown> {
+  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<string, unknown>).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<string, unknown>) : {};
@@ -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,
+        });
      }
    }

@@ -24,6 +24,11 @@ import type { NormalizedUsage } from "./usage.js";

 type EmbeddedSubscribeLogger = {
  debug: (message: string, meta?: Record<string, unknown>) => void;
+  trace?: (message: string, meta?: Record<string, unknown>) => void;
+  isEnabled?: (
+    level: "trace" | "debug" | "info" | "warn" | "error" | "fatal",
+    target?: "any" | "console" | "file",
+  ) => boolean;
  info: (message: string, meta?: Record<string, unknown>) => void;
  warn: (message: string, meta?: Record<string, unknown>) => void;
 };