diff --git a/doc/observability.md b/doc/observability.md index 31f5f7335c8..9d054b2ff8e 100644 --- a/doc/observability.md +++ b/doc/observability.md @@ -985,6 +985,17 @@ pending, `acpPendingToolKinds` lists their ACP tool kinds as a sorted, comma-sep string drawn only from the closed ACP `ToolKind` enum plus `unknown`; the server drops the field if any other value appears. +Claude ACP turns also run a stalled-tool watchdog. A pending tool call that gets +no ACP update for 30 minutes (`stalledToolTimeoutSec`; kept at least 15 minutes +above `MCP_TOOL_TIMEOUT` and `BASH_MAX_TIMEOUT_MS`) ends the turn through the +same cancel and fail-fast deadline as a duplex channel loss. The run fails with +`acpx_tool_stalled` instead of waiting for the wall-clock timeout, and records +`acpStalledToolKind` (one closed `ToolKind` label or `unknown`) and +`acpStalledToolSilentMs`. The stop-time fields above are measured when the +watchdog fired. A live subagent's Task call keeps receiving heartbeats, so only +a call that itself went silent trips the watchdog. Other ACP agents are watched +only when `stalledToolTimeoutSec` is set. + ACP and legacy OpenCode results retain the adapter's resolved wall-clock timeout as `adapterExecutionTimeout` in the instance run result. Finalization uses it for `effectiveTimeoutSec`, `timeoutSource`, and `timeoutConfigured`. Sources are diff --git a/packages/adapter-utils/src/acpx-engine/constants.ts b/packages/adapter-utils/src/acpx-engine/constants.ts index a3330c29a2d..47a67eb143f 100644 --- a/packages/adapter-utils/src/acpx-engine/constants.ts +++ b/packages/adapter-utils/src/acpx-engine/constants.ts @@ -36,6 +36,20 @@ export const ACPX_DUPLEX_LOSS_CANCEL_DEADLINE_MS = 30_000; // A user-configured `MCP_TOOL_TIMEOUT` still wins. export const ACPX_CLAUDE_MCP_TOOL_TIMEOUT_MS = 15 * 60 * 1000; +// The bound on how long a pending Claude tool call may go without any ACP +// update before the host ends the turn. `MCP_TOOL_TIMEOUT` only bounds an MCP +// call that reached its server. A call that stalls before that point (for +// example, a permission round trip or a subagent tool call that never +// executes) otherwise holds the turn until the 4h sandbox backstop, while a +// live subagent's periodic heartbeats keep the turn looking active. Claude's +// own tool bounds (MCP and Bash) end every healthy call well before this. The +// resolved bound always stays at least `ACPX_STALLED_TOOL_MARGIN_MS` above an +// `MCP_TOOL_TIMEOUT` or `BASH_MAX_TIMEOUT_MS` set in the launch environment. +export const ACPX_STALLED_TOOL_TIMEOUT_MS = 30 * 60 * 1000; +export const ACPX_STALLED_TOOL_MARGIN_MS = 15 * 60 * 1000; +export const ACPX_STALLED_TOOL_CHECK_INTERVAL_MS = 60_000; +export const ACPX_TOOL_STALLED_ERROR_CODE = "acpx_tool_stalled"; + // The closed ACP `ToolKind` enum. Run diagnostics may report these labels for // pending tool calls; tool titles, names, and inputs never leave the run. // Any other reported kind is collapsed to "unknown". diff --git a/packages/adapter-utils/src/acpx-engine/execute.test.ts b/packages/adapter-utils/src/acpx-engine/execute.test.ts index fe6021cc385..28dacdf508a 100644 --- a/packages/adapter-utils/src/acpx-engine/execute.test.ts +++ b/packages/adapter-utils/src/acpx-engine/execute.test.ts @@ -32,12 +32,18 @@ import { geminiVersionSupportsNativeAcpFlag, parseGeminiVersionParts, referencedSourceContentSignature, + resolveStalledToolTimeoutMs, rewriteGeminiAcpFlagForVersion, summarizeAcpStopActivity, summarizeAcpxTurnUsage, type AcpxEngineExecutorOptions, } from "./execute.js"; -import { ACPX_CLAUDE_MCP_TOOL_TIMEOUT_MS, ACPX_HANDSHAKE_TIMEOUT_MS } from "./constants.js"; +import { + ACPX_CLAUDE_MCP_TOOL_TIMEOUT_MS, + ACPX_HANDSHAKE_TIMEOUT_MS, + ACPX_STALLED_TOOL_MARGIN_MS, + ACPX_STALLED_TOOL_TIMEOUT_MS, +} from "./constants.js"; import { sessionCodec } from "./session-codec.js"; import { runChildProcess } from "../server-utils.js"; import { createPromptContextFixture } from "../test-fixtures/prompt-context.js"; @@ -3505,6 +3511,259 @@ describe("ACP activity diagnostics", () => { const diagnostics = Object.fromEntries(Object.entries(result.resultJson ?? {}).filter(([key]) => key.startsWith("acp"))); expect(JSON.stringify(diagnostics)).not.toContain("private"); }, 15_000); + + it("ends the turn as a failure when a pending tool call stops receiving updates", async () => { + const root = await makeTempRoot(); + const cwd = path.join(root, "worktree"); + await fs.mkdir(cwd, { recursive: true }); + let currentNow = 1000; + let releaseTurn: (() => void) | null = null; + const turnCancelled = new Promise((resolve) => { releaseTurn = resolve; }); + const cancelReasons: Array = []; + const logs: string[] = []; + const execute = createAcpxEngineExecutor({ + now: () => currentNow, + stalledToolTimeoutMs: 5000, + stalledToolCheckIntervalMs: 5, + createRuntime: () => ({ + ...buildRuntime(), + startTurn: () => ({ + events: (async function* () { + // A live subagent keeps its Task call fresh, but one of its tool + // calls never gets another update. + yield { type: "tool_call", toolCallId: "private-task", title: "private task", kind: "think", status: "in_progress" }; + yield { type: "tool_call", toolCallId: "private-call", title: "private lookup", kind: "other", status: "pending" }; + currentNow = 7000; + yield { type: "tool_call", tag: "tool_call_update", toolCallId: "private-task", status: "in_progress" }; + await turnCancelled; + yield { type: "tool_call", tag: "tool_call_update", toolCallId: "private-call", status: "cancelled" }; + })(), + result: turnCancelled.then(() => ({ status: "cancelled", stopReason: "cancelled" })), + cancel: async ({ reason }: { reason?: string }) => { + cancelReasons.push(reason); + releaseTurn?.(); + }, + }), + }) as never, + }); + const result = await execute({ + runId: "stalled-tool", agent: { id: "agent-1", companyId: "company-1" }, runtime: {}, + config: { agent: "custom", agentCommand: "node ./fake-acp.js", stateDir: path.join(root, "state"), cwd }, + context: {}, onMeta: async () => {}, onLog: async (_stream: string, text: string) => { logs.push(text); }, + } as never); + expect(cancelReasons).toEqual(["paperclip stalled tool watchdog"]); + expect(result.timedOut).toBe(false); + expect(result.exitCode).toBe(1); + expect(result.errorCode).toBe("acpx_tool_stalled"); + expect(result.errorMessage).toContain("kind other"); + expect(result.resultJson).toMatchObject({ + status: "failed", + acpStalledToolKind: "other", + acpStalledToolSilentMs: 6000, + acpLastEventAgeAtStopMs: 0, + acpOldestPendingToolAgeAtStopMs: 6000, + acpPendingToolKinds: "other,think", + }); + expect(logs.join("")).toContain("[paperclip] A pending tool call (kind other) had no update for 6s"); + const diagnostics = Object.fromEntries(Object.entries(result.resultJson ?? {}).filter(([key]) => key.startsWith("acp"))); + expect(JSON.stringify(diagnostics)).not.toContain("private"); + expect(result.errorMessage).not.toContain("private"); + }, 15_000); + + it("ends a stalled turn within the cancel deadline when the agent ignores the cancel", async () => { + const root = await makeTempRoot(); + const cwd = path.join(root, "worktree"); + await fs.mkdir(cwd, { recursive: true }); + let currentNow = 1000; + const closeStreamReasons: Array = []; + let endEvents: (() => void) | null = null; + const eventsEnded = new Promise((resolve) => { endEvents = resolve; }); + const execute = createAcpxEngineExecutor({ + now: () => currentNow, + stalledToolTimeoutMs: 5000, + stalledToolCheckIntervalMs: 5, + duplexLossCancelDeadlineMs: 25, + createRuntime: () => ({ + ...buildRuntime(), + startTurn: () => ({ + events: (async function* () { + yield { type: "tool_call", toolCallId: "call-1", kind: "other", status: "pending" }; + currentNow = 9000; + await eventsEnded; + })(), + // The agent never answers: neither the cancel nor the result settles. + result: new Promise(() => {}), + cancel: async () => {}, + closeStream: async ({ reason }: { reason?: string }) => { + closeStreamReasons.push(reason); + endEvents?.(); + }, + }), + }) as never, + }); + const result = await execute({ + runId: "stalled-tool-silent-agent", agent: { id: "agent-1", companyId: "company-1" }, runtime: {}, + config: { agent: "custom", agentCommand: "node ./fake-acp.js", stateDir: path.join(root, "state"), cwd }, + context: {}, onMeta: async () => {}, onLog: async () => {}, + } as never); + expect(closeStreamReasons).toEqual(["paperclip stalled tool cancel deadline"]); + expect(result.errorCode).toBe("acpx_tool_stalled"); + expect(result.resultJson).toMatchObject({ + status: "failed", + stopReason: "paperclip_stalled_tool_deadline", + acpStalledToolKind: "other", + }); + }, 15_000); + + it("leaves a turn alone while its long-running tool keeps receiving updates", async () => { + const root = await makeTempRoot(); + const cwd = path.join(root, "worktree"); + await fs.mkdir(cwd, { recursive: true }); + let currentNow = 1000; + const cancelReasons: Array = []; + const tick = () => new Promise((resolve) => setTimeout(resolve, 20)); + const execute = createAcpxEngineExecutor({ + now: () => currentNow, + stalledToolTimeoutMs: 5000, + stalledToolCheckIntervalMs: 5, + createRuntime: () => ({ + ...buildRuntime(), + startTurn: () => ({ + events: (async function* () { + yield { type: "tool_call", toolCallId: "task-1", kind: "think", status: "in_progress" }; + // The tool runs far past the bound in total, but each heartbeat + // arrives within it, and the watchdog checks between them. + for (let step = 0; step < 4; step += 1) { + currentNow += 4000; + await tick(); + yield { type: "tool_call", tag: "tool_call_update", toolCallId: "task-1", status: "in_progress" }; + } + yield { type: "tool_call", tag: "tool_call_update", toolCallId: "task-1", status: "completed" }; + yield { type: "done", stopReason: "end_turn" }; + })(), + result: Promise.resolve({ status: "completed", stopReason: "end_turn" }), + cancel: async ({ reason }: { reason?: string }) => { cancelReasons.push(reason); }, + }), + }) as never, + }); + const result = await execute({ + runId: "live-tool", agent: { id: "agent-1", companyId: "company-1" }, runtime: {}, + config: { agent: "custom", agentCommand: "node ./fake-acp.js", stateDir: path.join(root, "state"), cwd }, + context: {}, onMeta: async () => {}, onLog: async () => {}, + } as never); + expect(cancelReasons).toEqual([]); + expect(result.exitCode).toBe(0); + expect(result.errorCode).toBeNull(); + expect(result.resultJson).not.toHaveProperty("acpStalledToolKind"); + }, 15_000); + + it("leaves a queued tool call alone while earlier tool calls keep finishing", async () => { + const root = await makeTempRoot(); + const cwd = path.join(root, "worktree"); + await fs.mkdir(cwd, { recursive: true }); + let currentNow = 1000; + const cancelReasons: Array = []; + const tick = () => new Promise((resolve) => setTimeout(resolve, 20)); + const execute = createAcpxEngineExecutor({ + now: () => currentNow, + stalledToolTimeoutMs: 5000, + stalledToolCheckIntervalMs: 5, + createRuntime: () => ({ + ...buildRuntime(), + startTurn: () => ({ + events: (async function* () { + // The queued call gets no update until the slow calls ahead of it + // finish, one by one, each within the bound. + yield { type: "tool_call", toolCallId: "queued", kind: "edit", status: "pending" }; + for (let step = 0; step < 4; step += 1) { + yield { type: "tool_call", toolCallId: `slow-${step}`, kind: "execute", status: "in_progress" }; + currentNow += 4000; + await tick(); + yield { type: "tool_call", tag: "tool_call_update", toolCallId: `slow-${step}`, status: "completed" }; + } + yield { type: "tool_call", tag: "tool_call_update", toolCallId: "queued", status: "completed" }; + yield { type: "done", stopReason: "end_turn" }; + })(), + result: Promise.resolve({ status: "completed", stopReason: "end_turn" }), + cancel: async ({ reason }: { reason?: string }) => { cancelReasons.push(reason); }, + }), + }) as never, + }); + const result = await execute({ + runId: "queued-tool", agent: { id: "agent-1", companyId: "company-1" }, runtime: {}, + config: { agent: "custom", agentCommand: "node ./fake-acp.js", stateDir: path.join(root, "state"), cwd }, + context: {}, onMeta: async () => {}, onLog: async () => {}, + } as never); + expect(cancelReasons).toEqual([]); + expect(result.exitCode).toBe(0); + expect(result.errorCode).toBeNull(); + }, 15_000); + + it("does not watch tool calls when the stalled-tool bound is disabled", async () => { + const root = await makeTempRoot(); + const cwd = path.join(root, "worktree"); + await fs.mkdir(cwd, { recursive: true }); + let currentNow = 1000; + let releaseTurn: (() => void) | null = null; + const turnCancelled = new Promise((resolve) => { releaseTurn = resolve; }); + const cancelReasons: Array = []; + const execute = createAcpxEngineExecutor({ + now: () => currentNow, + stalledToolCheckIntervalMs: 5, + createRuntime: () => ({ + ...buildRuntime(), + startTurn: () => ({ + events: (async function* () { + yield { type: "tool_call", toolCallId: "call-1", kind: "other", status: "pending" }; + currentNow = 10_000_000; + await turnCancelled; + })(), + result: turnCancelled.then(() => ({ status: "cancelled", stopReason: "cancelled" })), + cancel: async ({ reason }: { reason?: string }) => { + cancelReasons.push(reason); + releaseTurn?.(); + }, + }), + }) as never, + }); + const result = await execute({ + runId: "stall-watchdog-off", agent: { id: "agent-1", companyId: "company-1" }, runtime: {}, + config: { + agent: "claude", agentCommand: "node ./fake-acp.js", stateDir: path.join(root, "state"), cwd, + stalledToolTimeoutSec: 0, timeoutSec: 1, + }, + context: {}, onMeta: async () => {}, onLog: async () => {}, + } as never); + // Only the wall-clock timeout ended this turn. + expect(cancelReasons).toHaveLength(1); + expect(cancelReasons[0]).not.toBe("paperclip stalled tool watchdog"); + expect(result.timedOut).toBe(true); + expect(result.errorCode).toBe("acpx_timeout"); + }, 15_000); +}); + +describe("resolveStalledToolTimeoutMs", () => { + it("watches Claude turns with a bound above Claude's own tool bounds", () => { + expect(resolveStalledToolTimeoutMs({}, {}, "claude")).toBe(ACPX_STALLED_TOOL_TIMEOUT_MS); + expect(resolveStalledToolTimeoutMs({}, { MCP_TOOL_TIMEOUT: String(ACPX_CLAUDE_MCP_TOOL_TIMEOUT_MS) }, "claude")) + .toBe(ACPX_STALLED_TOOL_TIMEOUT_MS); + expect(resolveStalledToolTimeoutMs({}, { MCP_TOOL_TIMEOUT: "3600000" }, "claude")) + .toBe(3_600_000 + ACPX_STALLED_TOOL_MARGIN_MS); + expect(resolveStalledToolTimeoutMs({}, { BASH_MAX_TIMEOUT_MS: "7200000", MCP_TOOL_TIMEOUT: "not-a-number" }, "claude")) + .toBe(7_200_000 + ACPX_STALLED_TOOL_MARGIN_MS); + }); + + it("leaves other agents unwatched unless the adapter config sets a bound", () => { + expect(resolveStalledToolTimeoutMs({}, {}, "codex")).toBe(0); + expect(resolveStalledToolTimeoutMs({ stalledToolTimeoutSec: 600 }, {}, "codex")).toBe(600_000); + }); + + it("lets the adapter config override or disable the bound", () => { + expect(resolveStalledToolTimeoutMs({ stalledToolTimeoutSec: 120 }, { MCP_TOOL_TIMEOUT: "3600000" }, "claude")).toBe(120_000); + expect(resolveStalledToolTimeoutMs({ stalledToolTimeoutSec: 0 }, {}, "claude")).toBe(0); + expect(resolveStalledToolTimeoutMs({ stalledToolTimeoutSec: -1 }, {}, "claude")).toBe(0); + expect(resolveStalledToolTimeoutMs({ stalledToolTimeoutSec: "120" }, {}, "claude")).toBe(ACPX_STALLED_TOOL_TIMEOUT_MS); + }); }); describe("summarizeAcpStopActivity", () => { diff --git a/packages/adapter-utils/src/acpx-engine/execute.ts b/packages/adapter-utils/src/acpx-engine/execute.ts index e052d04ace0..1047805363f 100644 --- a/packages/adapter-utils/src/acpx-engine/execute.ts +++ b/packages/adapter-utils/src/acpx-engine/execute.ts @@ -110,6 +110,10 @@ import { ACPX_DUPLEX_LOSS_CANCEL_DEADLINE_MS, ACPX_HANDSHAKE_TIMEOUT_MS, ACPX_HANDSHAKE_TRANSPORT_POLL_MS, + ACPX_STALLED_TOOL_CHECK_INTERVAL_MS, + ACPX_STALLED_TOOL_MARGIN_MS, + ACPX_STALLED_TOOL_TIMEOUT_MS, + ACPX_TOOL_STALLED_ERROR_CODE, DEFAULT_ACP_ENGINE_AGENT, DEFAULT_ACP_ENGINE_MODE, DEFAULT_ACP_ENGINE_NON_INTERACTIVE_PERMISSIONS, @@ -390,6 +394,13 @@ export interface AcpxEngineExecutorOptions { * to drive the deadline without real time. */ duplexLossCancelDeadlineMs?: number; + /** + * Overrides {@link resolveStalledToolTimeoutMs} and the interval at which + * the stalled-tool watchdog checks pending tool calls. Tests inject small + * values to drive the watchdog without real time. + */ + stalledToolTimeoutMs?: number; + stalledToolCheckIntervalMs?: number; warmHandles?: Map; /** * Per-session staged-runtime cache for the remote runner-backed lane (PR 3). @@ -1480,6 +1491,28 @@ function normalizeNonInteractivePermissions(config: Record): "d : "deny"; } +/** + * How long a pending tool call may go without any ACP update before the host + * ends the turn; 0 disables the watchdog. `stalledToolTimeoutSec` in the + * adapter config wins (0 or less disables it). Otherwise only Claude turns are + * watched, with a bound kept above Claude's own tool bounds in `env`. + */ +export function resolveStalledToolTimeoutMs( + config: Record, + env: Record, + acpxAgent: string, +): number { + const configured = config.stalledToolTimeoutSec; + if (typeof configured === "number" && Number.isFinite(configured)) { + return configured > 0 ? Math.round(configured * 1000) : 0; + } + if (acpxAgent !== "claude") return 0; + const toolBounds = [env.MCP_TOOL_TIMEOUT, env.BASH_MAX_TIMEOUT_MS] + .map((value) => Number(value)) + .filter((value) => Number.isFinite(value) && value > 0); + return Math.max(ACPX_STALLED_TOOL_TIMEOUT_MS, ...toolBounds.map((value) => value + ACPX_STALLED_TOOL_MARGIN_MS)); +} + function normalizeRequestedThinkingEffort(config: Record): string { return ( asString(config.modelReasoningEffort, "") || @@ -3974,6 +4007,7 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { const createRuntime = deps.createRuntime ?? createAcpRuntime; const now = deps.now ?? (() => Date.now()); const duplexLossCancelDeadlineMs = deps.duplexLossCancelDeadlineMs ?? ACPX_DUPLEX_LOSS_CANCEL_DEADLINE_MS; + const stalledToolCheckIntervalMs = deps.stalledToolCheckIntervalMs ?? ACPX_STALLED_TOOL_CHECK_INTERVAL_MS; const warmHandles = deps.warmHandles ?? defaultWarmHandles; const stagedRuntimes = deps.stagedRuntimes ?? defaultStagedRuntimes; const stagingLocks = deps.stagingLocks ?? defaultStagingLocks; @@ -4089,11 +4123,17 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { const lossDeadline = new Promise((resolve) => { resolveLossDeadline = resolve; }); + // Set when the stalled-tool watchdog (armed in `stepTurnStart`) ends the + // turn: the closed ACP kind of the silent tool call and how long it went + // without an update. The watchdog cancels the turn and arms the same + // fail-fast deadline as a duplex loss. + let stalledTool: { kind: string; silentMs: number } | null = null; + let stalledToolTimer: ReturnType | undefined; let forcedStop = false; let runtimeStopConfirmed = false; let safeInterruptedSession = false; let preserveInterruptedSession = false; - const interruptionTools = new Map(); + const interruptionTools = new Map(); let incompleteToolInventory = false; try { await ctx.onCancellationReady?.(); @@ -4814,6 +4854,10 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { let turnStopRequestedAt: number | null = null; let lastRuntimeEventBeforeStopAt: number | null = null; let pendingToolsAtStop: Array<{ kind?: string; firstSeenAt?: number }> | null = null; + // When a tool call last reached a final status (or the turn started). + // A call queued behind slow sequential calls gets no update until they + // finish, so the stalled-tool watchdog also needs this to be old. + let lastToolSettledAt: number | null = null; let turnDispatchAttempted = false; // The turn-local state the sequence steps share. `promptBuild` sets the // prompt, `preTurnUsage` sets the pre-turn status, `turnStart` sets the @@ -4939,25 +4983,70 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { // before this turn started — so the turn returns a terminal result // right away. `turnFinalize` reads the same latch and builds the // failure from the typed loss reason alone. + // `cancel()` only asks the agent to end the turn; it does not end the + // turn by itself. Start the fail-fast deadline the moment the host + // cancels, so the run does not wait past this bound for an agent that + // stopped answering. + const armCancelDeadline = () => { + if (!lossDeadlineTimer && !lossDeadlineTripped) { + lossDeadlineTimer = setTimeout(() => { + lossDeadlineTripped = true; + resolveLossDeadline?.(); + }, duplexLossCancelDeadlineMs); + } + }; const bridge = prepared.paperclipBridge; if (bridge?.onLoss) { const cancelForLoss = (reason: DuplexLossReason) => { void turn.cancel({ reason: `paperclip sandbox duplex channel lost (${reason})` }).catch(() => {}); - // `cancel()` only asks the agent to end the turn; it does not end - // the turn by itself. Start the fail-fast deadline the moment the - // loss latches, so the run does not wait past this bound for an - // agent that stopped answering. - if (!lossDeadlineTimer && !lossDeadlineTripped) { - lossDeadlineTimer = setTimeout(() => { - lossDeadlineTripped = true; - resolveLossDeadline?.(); - }, duplexLossCancelDeadlineMs); - } + armCancelDeadline(); }; removeLossListener = bridge.onLoss(cancelForLoss); const alreadyLatched = bridge.readRunDisposition?.(); if (alreadyLatched?.failed) cancelForLoss(alreadyLatched.lossReason ?? "other"); } + // A pending tool call that gets no ACP update for this long, while no + // other tool call finishes either, is stalled: Claude's own tool + // bounds end every healthy call sooner, and a live subagent's Task + // call keeps receiving heartbeats. A call that stalls before it runs + // (for example, a lost permission round trip) is outside those + // bounds and would otherwise hold the turn until the wall-clock + // backstop. End the turn instead, through the same cancel and + // fail-fast deadline as a duplex loss. + const stalledToolTimeoutMs = deps.stalledToolTimeoutMs + ?? resolveStalledToolTimeoutMs(ctx.config, prepared.env, prepared.acpxAgent); + if (stalledToolTimeoutMs > 0) { + lastToolSettledAt = now(); + stalledToolTimer = setInterval(() => { + if (stalledTool !== null || turnStopRequestedAt !== null) return; + const checkedAt = now(); + if (lastToolSettledAt !== null && checkedAt - lastToolSettledAt < stalledToolTimeoutMs) return; + let oldest: { kind?: string; silentMs: number } | null = null; + for (const tool of interruptionTools.values()) { + if (!isPendingAcpTool(tool) || tool.lastUpdateAt === undefined) continue; + const silentMs = checkedAt - tool.lastUpdateAt; + if (silentMs >= stalledToolTimeoutMs && (!oldest || silentMs > oldest.silentMs)) { + oldest = { kind: tool.kind, silentMs }; + } + } + if (!oldest) return; + clearInterval(stalledToolTimer); + const knownKinds: readonly string[] = ACP_TOOL_KINDS; + stalledTool = { + kind: oldest.kind && knownKinds.includes(oldest.kind) ? oldest.kind : "unknown", + silentMs: oldest.silentMs, + }; + turnStopRequestedAt = checkedAt; + pendingToolsAtStop = [...interruptionTools.values()].filter(isPendingAcpTool); + void ctx.onLog( + "stderr", + `[paperclip] A pending tool call (kind ${stalledTool.kind}) had no update for ${Math.round(stalledTool.silentMs / 1000)}s; ending the turn.\n`, + ).catch(() => {}); + void turn.cancel({ reason: "paperclip stalled tool watchdog" }).catch(() => {}); + armCancelDeadline(); + }, stalledToolCheckIntervalMs); + stalledToolTimer.unref?.(); + } // ACP can resolve the turn before its provider exits. Keep the Stop // deadline armed through settlement, including provider cleanup. const armStopDeadline = () => { @@ -4987,12 +5076,12 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { // the fail-fast deadline fires with no agent-supplied terminal. Its // `status` mirrors the shape a real cooperative cancel already // produces, so `turnFinalize` needs no change: it reads the latched - // loss disposition, not this `stopReason`, to build the reported - // failure and its message. - const LOSS_DEADLINE_TERMINAL: AcpRuntimeTurnResult = { + // loss disposition or the stalled-tool record, not this `stopReason`, + // to build the reported failure and its message. + const cancelDeadlineTerminal = (): AcpRuntimeTurnResult => ({ status: "cancelled", - stopReason: "paperclip_duplex_loss_deadline", - }; + stopReason: stalledTool ? "paperclip_stalled_tool_deadline" : "paperclip_duplex_loss_deadline", + }); const stepEventRelay = async (): Promise => { const turn = activeTurn as AcpRuntimeTurn; const toolTitles = new Map(); @@ -5012,7 +5101,9 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { kind: event.kind ?? previous?.kind, status: event.status ?? previous?.status, firstSeenAt: previous?.firstSeenAt ?? lastRuntimeEventAt, + lastUpdateAt: lastRuntimeEventAt, }); + if (event.status && !isPendingAcpTool({ status: event.status })) lastToolSettledAt = lastRuntimeEventAt; } } if (event.type === "text_delta" && event.stream !== "thought") { @@ -5049,20 +5140,22 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { // both the close call and the drain it unblocks before this step // returns, so no late runtime event can still mutate shared state // (output segments, tool inventory) after finalization reads it. - await turn.closeStream({ reason: "paperclip duplex loss cancel deadline" }).catch(() => {}); + await turn.closeStream({ reason: stalledTool ? "paperclip stalled tool cancel deadline" : "paperclip duplex loss cancel deadline" }).catch(() => {}); await drainEvents.catch(() => {}); flushOutputSegment(); - return LOSS_DEADLINE_TERMINAL; + return cancelDeadlineTerminal(); } flushOutputSegment(); // `turn.result` settles only when the agent's provider process // returns or rejects; a latched loss that armed the deadline after // the event drain already ended must still bound this wait. - return await Promise.race([turn.result, lossDeadline.then(() => LOSS_DEADLINE_TERMINAL)]); + return await Promise.race([turn.result, lossDeadline.then(cancelDeadlineTerminal)]); }; const stepTurnFinalize = async ( input: TurnFinalizeInput, ): Promise => { + // The turn has ended; tools left pending now cannot stall it. + clearInterval(stalledToolTimer); // Capture runtime activity before usage reads, error logs, or cleanup // make an otherwise silent turn look active at its execution deadline. const lastEventAgeMs = lastRuntimeEventAt === null ? undefined : now() - lastRuntimeEventAt; @@ -5105,6 +5198,14 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { const channelLostMessage = duplexLossReason ? `The sandbox duplex control channel was lost (${duplexLossReason}) before the run completed.` : null; + // The stalled-tool watchdog ended the turn. A timeout or channel loss + // explains the outcome first, and a turn that completed anyway (its + // completion raced the cancel) keeps its success. The message carries + // only the closed ACP tool kind and the silent time. + const toolStalled = stalledTool !== null && !timedOut && !channelLost && terminal.status !== "completed"; + const toolStalledMessage = stalledTool + ? `A pending tool call (kind ${stalledTool.kind}) received no update for ${Math.round(stalledTool.silentMs / 60_000)} minutes, so Paperclip ended the turn instead of waiting for the execution timeout.` + : null; // A completed, non-timed-out turn whose channel stayed live is the one // success path. Every other outcome — a failed, cancelled, or timed-out // terminal, or a completed terminal with a lost channel — is a failure. @@ -5155,9 +5256,11 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { ? "paperclip timeout cleanup" : channelLost ? "paperclip duplex channel lost cleanup" - : failedTurn - ? `paperclip turn ${terminal.status}` - : "paperclip completed turn cleanup", + : toolStalled + ? "paperclip stalled tool cleanup" + : failedTurn + ? `paperclip turn ${terminal.status}` + : "paperclip completed turn cleanup", discardPersistentState: sessionUnavailable || (terminal.status === "cancelled" && !preserveInterruptedSession) || timedOut || channelLost, dropWarmEntry: false, recordCloseError: false, @@ -5165,21 +5268,23 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { skipRemoteClose: channelLost, }; - const failureDiagnostic = !timedOut && !channelLost && terminal.status === "failed" + const failureDiagnostic = !timedOut && !channelLost && !toolStalled && terminal.status === "failed" ? terminalSessionFailure : null; const errorMessage = timedOut ? formatAdapterExecutionTimeoutErrorMessage(prepared.timeoutResolution) : channelLost ? channelLostMessage - : formatTerminalSessionFailure(resultErrorMessage(terminal), failureDiagnostic); + : toolStalled + ? toolStalledMessage + : formatTerminalSessionFailure(resultErrorMessage(terminal), failureDiagnostic); const terminalStopReason = terminal.status === "failed" ? terminal.error.message : terminal.stopReason; - const classifiedFailure = !timedOut && !channelLost && terminal.status === "failed" + const classifiedFailure = !timedOut && !channelLost && !toolStalled && terminal.status === "failed" ? terminalFailureClassification : null; await emitAcpxLog(ctx, { type: turnSucceeded ? "acpx.result" : "acpx.error", - summary: channelLost ? "duplex_channel_lost" : terminal.status, + summary: channelLost ? "duplex_channel_lost" : toolStalled ? "tool_stalled" : terminal.status, stopReason: terminalStopReason, message: errorMessage, }); @@ -5196,9 +5301,11 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { ? "acpx_timeout" : channelLost ? DUPLEX_CHANNEL_LOST_ERROR_CODE - : terminal.status === "failed" - ? classifiedFailure?.errorCode ?? "acpx_turn_failed" - : null, + : toolStalled + ? ACPX_TOOL_STALLED_ERROR_CODE + : terminal.status === "failed" + ? classifiedFailure?.errorCode ?? "acpx_turn_failed" + : null, ...(classifiedFailure?.errorFamily ? { errorFamily: classifiedFailure.errorFamily } : {}), ...(classifiedFailure?.retryNotBefore ? { retryNotBefore: classifiedFailure.retryNotBefore } : {}), sessionId: sessionHandle.backendSessionId ?? sessionHandle.runtimeSessionName, @@ -5211,8 +5318,11 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { costUsd: turnUsage.costUsd, usageComplete, resultJson: { - status: channelLost ? "failed" : terminal.status, + status: channelLost || toolStalled ? "failed" : terminal.status, ...activityDiagnostics, + ...(toolStalled && stalledTool + ? { acpStalledToolKind: stalledTool.kind, acpStalledToolSilentMs: stalledTool.silentMs } + : {}), ...(failureDiagnostic ? { terminalSessionFailure: failureDiagnostic } : {}), ...(classifiedFailure?.errorFamily ? { errorFamily: classifiedFailure.errorFamily } : {}), ...(classifiedFailure?.retryNotBefore @@ -5259,6 +5369,15 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { resources: emptyConsumed, }; } + // The host cancelled a stalled turn. That is a failure, not a stop + // anyone requested, so it must not settle as a cancellation. + if (toolStalled) { + return { + kind: "failed", + cause: { kind: "turn_failed", error: new Error(toolStalledMessage ?? "A pending tool call stalled.") }, + resources: emptyConsumed, + }; + } if (terminal.status === "cancelled") { return { kind: "cancelled", @@ -5652,6 +5771,7 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { removeStopListener?.(); removeLossListener?.(); clearTimeout(lossDeadlineTimer); + clearInterval(stalledToolTimer); // End the run root span exactly once, on every return and on a throw. runRootSpan.end(runFailed); // Release the per-session staging lease as the run's final act, AFTER the diff --git a/packages/adapters/claude-local/src/index.ts b/packages/adapters/claude-local/src/index.ts index 9268c47f959..ea33b500210 100644 --- a/packages/adapters/claude-local/src/index.ts +++ b/packages/adapters/claude-local/src/index.ts @@ -86,6 +86,7 @@ ACP fields (only when engine="acp"): - stateDir (string, optional): ACP session state directory; defaults to Paperclip-managed company/agent scoped storage - nonInteractivePermissions (string, optional, default "deny"): fallback when the ACP agent asks for input outside an interactive session - warmHandleIdleMs (number, optional, default 0): keep the ACP process warm for this many ms after a successful run +- stalledToolTimeoutSec (number, optional, default 1800): end the turn as failed ("acpx_tool_stalled") when a pending tool call gets no ACP update for this many seconds; 0 disables it. The default stays at least 15 minutes above MCP_TOOL_TIMEOUT and BASH_MAX_TIMEOUT_MS Operational fields: - timeoutSec (number, optional): run timeout in seconds diff --git a/server/src/services/__tests__/run-failure-diagnostics.test.ts b/server/src/services/__tests__/run-failure-diagnostics.test.ts index da5f8228b1a..fae5b5e5957 100644 --- a/server/src/services/__tests__/run-failure-diagnostics.test.ts +++ b/server/src/services/__tests__/run-failure-diagnostics.test.ts @@ -458,6 +458,21 @@ describe("run failure diagnostics", () => { }); }); + it("includes the stalled tool's closed kind label and silent time", () => { + const result = sanitizeRunFailureDiagnostics(collectRunFailureDiagnostics(run({ resultJson: { + acpStalledToolKind: "other", acpStalledToolSilentMs: 1_800_000, acpStalledToolTitle: "private lookup", + } }), {})); + expect(result.execution).toEqual({ acpStalledToolKind: "other", acpStalledToolSilentMs: 1_800_000 }); + expect(JSON.stringify(result)).not.toContain("private"); + }); + + it.each(["other,execute", "private lookup", "", "Other", ["other"], 1])( + "omits a stalled tool kind that is not one closed label (%j)", (value) => { + const result = collectRunFailureDiagnostics(run({ resultJson: { acpStalledToolKind: value } }), {}); + expect(result.execution).toEqual({}); + }, + ); + it.each(["execute,private command", "", "execute,", "Execute", ["execute"], 1])( "omits pending tool kinds that are not closed labels (%j)", (value) => { const result = collectRunFailureDiagnostics(run({ resultJson: { acpPendingToolKinds: value } }), {}); @@ -470,6 +485,7 @@ describe("run failure diagnostics", () => { const result = collectRunFailureDiagnostics(run({ resultJson: { acpLastEventAgeMs: value, acpObservedEventCount: value, acpPendingToolCount: value, acpToolInventoryComplete: value, acpLastEventAgeAtStopMs: value, acpOldestPendingToolAgeAtStopMs: value, + acpStalledToolSilentMs: value, } }), {}); expect(result.execution).toEqual({}); }, diff --git a/server/src/services/run-failure-diagnostics.ts b/server/src/services/run-failure-diagnostics.ts index 3b331168f76..627a9206de8 100644 --- a/server/src/services/run-failure-diagnostics.ts +++ b/server/src/services/run-failure-diagnostics.ts @@ -57,6 +57,11 @@ function readAcpPendingToolKinds(value: unknown): string | null { return kinds.every((kind) => ACP_PENDING_TOOL_KIND_LABELS.has(kind)) ? value : null; } +/** One closed ACP tool-kind label, or nothing. */ +function readAcpToolKind(value: unknown): string | null { + return typeof value === "string" && ACP_PENDING_TOOL_KIND_LABELS.has(value) ? value : null; +} + function read(value: unknown, key: string): unknown { if (!value || typeof value !== "object") return undefined; try { @@ -308,7 +313,7 @@ export function collectRunFailureDiagnostics(run: Run, options: RunFailureReport ])); for (const field of [ "acpLastEventAgeMs", "acpObservedEventCount", "acpPendingToolCount", - "acpLastEventAgeAtStopMs", "acpOldestPendingToolAgeAtStopMs", + "acpLastEventAgeAtStopMs", "acpOldestPendingToolAgeAtStopMs", "acpStalledToolSilentMs", ]) { const value = read(result, field); if (typeof value === "number" && Number.isSafeInteger(value) && value >= 0) execution[field] = value; @@ -317,6 +322,8 @@ export function collectRunFailureDiagnostics(run: Run, options: RunFailureReport if (closeSettlement) Object.assign(execution, closeSettlement); const pendingToolKinds = readAcpPendingToolKinds(read(result, "acpPendingToolKinds")); if (pendingToolKinds) execution.acpPendingToolKinds = pendingToolKinds; + const stalledToolKind = readAcpToolKind(read(result, "acpStalledToolKind")); + if (stalledToolKind) execution.acpStalledToolKind = stalledToolKind; const toolInventoryComplete = read(result, "acpToolInventoryComplete"); if (typeof toolInventoryComplete === "boolean") execution.acpToolInventoryComplete = toolInventoryComplete; const restoreFailure = read(result, "workspaceRestoreFailure");