From 4b766b872993045a2e787404f0475503683e5ded Mon Sep 17 00:00:00 2001 From: Devin Foley Date: Mon, 12 Oct 2026 12:33:59 -0700 Subject: [PATCH] fix(acpx): record turn activity at the moment a stop fires (#15962) Record stop-time ACP turn diagnostics (last-event age, oldest pending tool age, pending tool kinds) so wall-clock timeout events show whether the turn was stalled. Diagnostics only. Co-Authored-By: Paperclip Co-Authored-By: Claude Opus 5.5 --- doc/observability.md | 11 ++ .../src/acpx-engine/constants.ts | 7 ++ .../src/acpx-engine/execute.test.ts | 113 ++++++++++++++++++ .../adapter-utils/src/acpx-engine/execute.ts | 64 +++++++++- .../__tests__/run-failure-diagnostics.test.ts | 20 +++- .../src/services/run-failure-diagnostics.ts | 17 ++- 6 files changed, 226 insertions(+), 6 deletions(-) diff --git a/doc/observability.md b/doc/observability.md index cb6b75c1af3..807ad61c80a 100644 --- a/doc/observability.md +++ b/doc/observability.md @@ -638,6 +638,17 @@ pending. Recent events do not prove useful progress. These fields contain only numbers and a boolean, never tool names, IDs, arguments, or event content, and do not change the execution timeout, cancellation, or recovery policy. +A stopped turn (wall-clock timeout or operator stop) also records +`acpLastEventAgeAtStopMs` and `acpOldestPendingToolAgeAtStopMs`, measured at the +moment the stop fired. A cancel can make the agent emit closing events, so the +finalization age alone cannot separate a turn that went silent long before its +deadline from one that was still working. For a stopped turn, pending tools +means the tools pending when the stop fired, so a tool the cancel closes still +counts; `acpPendingToolCount` keeps its finalization-time meaning. When tools are +pending, `acpPendingToolKinds` lists their ACP tool kinds as a sorted, comma-separated +string drawn only from the closed ACP `ToolKind` enum plus `unknown`; the +server drops the field if any other value appears. + 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 663d19ec243..1c37dc958cd 100644 --- a/packages/adapter-utils/src/acpx-engine/constants.ts +++ b/packages/adapter-utils/src/acpx-engine/constants.ts @@ -26,6 +26,13 @@ export const ACPX_HANDSHAKE_TRANSPORT_POLL_MS = 250; // much smaller than the whole-adapter execution timeout. export const ACPX_DUPLEX_LOSS_CANCEL_DEADLINE_MS = 30_000; +// 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". +export const ACP_TOOL_KINDS = [ + "read", "edit", "delete", "move", "search", "execute", "think", "fetch", "switch_mode", "other", +] as const; + export const ACPX_ADAPTER_AGENT_IDS = { claude_local: "claude", codex_local: "codex", diff --git a/packages/adapter-utils/src/acpx-engine/execute.test.ts b/packages/adapter-utils/src/acpx-engine/execute.test.ts index 78fd4ebfcf3..095996c1f83 100644 --- a/packages/adapter-utils/src/acpx-engine/execute.test.ts +++ b/packages/adapter-utils/src/acpx-engine/execute.test.ts @@ -33,6 +33,7 @@ import { parseGeminiVersionParts, referencedSourceContentSignature, rewriteGeminiAcpFlagForVersion, + summarizeAcpStopActivity, summarizeAcpxTurnUsage, type AcpxEngineExecutorOptions, } from "./execute.js"; @@ -3400,6 +3401,118 @@ describe("ACP activity diagnostics", () => { expect(currentNow).toBeGreaterThan(10_000); }, ); + + it("snapshots a silent turn's activity when the wall-clock timeout fires, before cancel events", 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 execute = createAcpxEngineExecutor({ + now: () => currentNow, + createRuntime: () => ({ + ...buildRuntime(), + startTurn: () => ({ + events: (async function* () { + yield { type: "tool_call", toolCallId: "private-id", title: "private command", kind: "execute", status: "in_progress" }; + // The agent goes silent with the tool still pending. + currentNow = 9000; + await turnCancelled; + // The cancel makes the agent emit a closing event, so the + // finalize-time age alone would make this turn look active. + currentNow = 9500; + yield { type: "status", text: "private closing status" }; + })(), + result: turnCancelled.then(() => ({ status: "cancelled", stopReason: "cancelled" })), + cancel: async () => { releaseTurn?.(); }, + }), + }) as never, + }); + const result = await execute({ + runId: "silent-timeout", agent: { id: "agent-1", companyId: "company-1" }, runtime: {}, + config: { agent: "custom", agentCommand: "node ./fake-acp.js", stateDir: path.join(root, "state"), cwd, timeoutSec: 1 }, + context: {}, onMeta: async () => {}, onLog: async () => {}, + } as never); + expect(result.timedOut).toBe(true); + expect(result.resultJson).toMatchObject({ + acpObservedEventCount: 2, + acpLastEventAgeMs: 0, + acpPendingToolCount: 1, + acpLastEventAgeAtStopMs: 8000, + acpOldestPendingToolAgeAtStopMs: 8000, + acpPendingToolKinds: "execute", + }); + const diagnostics = Object.fromEntries(Object.entries(result.resultJson ?? {}).filter(([key]) => key.startsWith("acp"))); + expect(JSON.stringify(diagnostics)).not.toContain("private"); + }, 15_000); + + it("keeps the stalled tool's stop-time age when the cancel closes that tool", 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 execute = createAcpxEngineExecutor({ + now: () => currentNow, + createRuntime: () => ({ + ...buildRuntime(), + startTurn: () => ({ + events: (async function* () { + yield { type: "tool_call", toolCallId: "private-id", title: "private command", kind: "execute", status: "in_progress" }; + currentNow = 9000; + await turnCancelled; + // The cancel closes the stalled tool before finalization runs. + currentNow = 9500; + yield { type: "tool_call", tag: "tool_call_update", toolCallId: "private-id", status: "cancelled" }; + })(), + result: turnCancelled.then(() => ({ status: "cancelled", stopReason: "cancelled" })), + cancel: async () => { releaseTurn?.(); }, + }), + }) as never, + }); + const result = await execute({ + runId: "cancel-closes-tool", agent: { id: "agent-1", companyId: "company-1" }, runtime: {}, + config: { agent: "custom", agentCommand: "node ./fake-acp.js", stateDir: path.join(root, "state"), cwd, timeoutSec: 1 }, + context: {}, onMeta: async () => {}, onLog: async () => {}, + } as never); + expect(result.timedOut).toBe(true); + expect(result.resultJson).toMatchObject({ + acpPendingToolCount: 0, + acpLastEventAgeAtStopMs: 8000, + acpOldestPendingToolAgeAtStopMs: 8000, + acpPendingToolKinds: "execute", + }); + const diagnostics = Object.fromEntries(Object.entries(result.resultJson ?? {}).filter(([key]) => key.startsWith("acp"))); + expect(JSON.stringify(diagnostics)).not.toContain("private"); + }, 15_000); +}); + +describe("summarizeAcpStopActivity", () => { + it("reports nothing for an unstopped turn with no pending tools", () => { + expect(summarizeAcpStopActivity(null, 1000, [])).toEqual({}); + }); + + it("reports pending kinds without a stop, and collapses unknown kinds", () => { + expect(summarizeAcpStopActivity(null, 1000, [ + { kind: "fetch", firstSeenAt: 10 }, { kind: "private_tool_name" }, {}, { kind: "fetch" }, + ])).toEqual({ acpPendingToolKinds: "fetch,unknown" }); + }); + + it("measures ages from the stop and ignores tools first seen after it", () => { + expect(summarizeAcpStopActivity(10_000, 4000, [ + { kind: "execute", firstSeenAt: 3000 }, { kind: "read", firstSeenAt: 12_000 }, + ])).toEqual({ + acpLastEventAgeAtStopMs: 6000, + acpOldestPendingToolAgeAtStopMs: 7000, + acpPendingToolKinds: "execute,read", + }); + }); + + it("omits the event age when no event preceded the stop", () => { + expect(summarizeAcpStopActivity(10_000, null, [])).toEqual({}); + }); }); describe("summarizeAcpxTurnUsage", () => { diff --git a/packages/adapter-utils/src/acpx-engine/execute.ts b/packages/adapter-utils/src/acpx-engine/execute.ts index e84c6014991..01ae1020b8d 100644 --- a/packages/adapter-utils/src/acpx-engine/execute.ts +++ b/packages/adapter-utils/src/acpx-engine/execute.ts @@ -105,6 +105,7 @@ import { type AcpRuntimeUsageCost, } from "acpx/runtime"; import { + ACP_TOOL_KINDS, ACPX_DUPLEX_LOSS_CANCEL_DEADLINE_MS, ACPX_HANDSHAKE_TIMEOUT_MS, ACPX_HANDSHAKE_TRANSPORT_POLL_MS, @@ -3249,6 +3250,46 @@ async function emitRuntimeEvent( } } +function isPendingAcpTool(tool: { status?: string }): boolean { + return tool.status !== "completed" && tool.status !== "failed" && tool.status !== "cancelled"; +} + +/** + * Activity as of the moment the turn's stop fired, for a stopped turn only. + * Separates a turn that went silent long before its deadline from one that + * was still working. Reports only ages and closed ACP tool-kind labels. + */ +export function summarizeAcpStopActivity( + stopRequestedAt: number | null, + lastEventBeforeStopAt: number | null, + pendingTools: ReadonlyArray<{ kind?: string; firstSeenAt?: number }>, +): { acpLastEventAgeAtStopMs?: number; acpOldestPendingToolAgeAtStopMs?: number; acpPendingToolKinds?: string } { + const summary: ReturnType = {}; + if (pendingTools.length > 0) { + const knownKinds: readonly string[] = ACP_TOOL_KINDS; + summary.acpPendingToolKinds = uniqueSorted( + pendingTools.map((tool) => (tool.kind && knownKinds.includes(tool.kind) ? tool.kind : "unknown")), + ).join(","); + } + if (stopRequestedAt === null) return summary; + const age = (since: number) => { + const value = stopRequestedAt - since; + return Number.isSafeInteger(value) && value >= 0 ? value : undefined; + }; + if (lastEventBeforeStopAt !== null) { + const value = age(lastEventBeforeStopAt); + if (value !== undefined) summary.acpLastEventAgeAtStopMs = value; + } + const pendingSince = pendingTools + .map((tool) => tool.firstSeenAt) + .filter((at): at is number => typeof at === "number" && at <= stopRequestedAt); + if (pendingSince.length > 0) { + const value = age(Math.min(...pendingSince)); + if (value !== undefined) summary.acpOldestPendingToolAgeAtStopMs = value; + } + return summary; +} + function resultErrorMessage(result: AcpRuntimeTurnResult): string | null { if (result.status !== "failed") return null; return result.error.message; @@ -4046,7 +4087,7 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { let runtimeStopConfirmed = false; let safeInterruptedSession = false; let preserveInterruptedSession = false; - const interruptionTools = new Map(); + const interruptionTools = new Map(); let incompleteToolInventory = false; try { await ctx.onCancellationReady?.(); @@ -4759,6 +4800,14 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { let observedUsage: Pick = { usageComplete: false }; let lastRuntimeEventAt: number | null = null; let observedRuntimeEvents = 0; + // Activity as of the moment the turn's stop (wall-clock timeout or + // operator stop) fired. The cancel can make the agent emit closing + // events (including updates that close the stalled tool), so the + // finalize-time age and pending set alone cannot tell a silent stall + // from live work. + let turnStopRequestedAt: number | null = null; + let lastRuntimeEventBeforeStopAt: number | null = null; + let pendingToolsAtStop: Array<{ kind?: string; firstSeenAt?: 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 @@ -4846,6 +4895,11 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { }; const stepTurnStart = (signal: AbortSignal, startTimeoutMs: number | undefined): StartedTurn => { ctx.signal?.throwIfAborted(); + signal.addEventListener("abort", () => { + if (turnStopRequestedAt !== null) return; + turnStopRequestedAt = now(); + pendingToolsAtStop = [...interruptionTools.values()].filter(isPendingAcpTool); + }, { once: true }); // After entering startTurn, a thrown error cannot prove the provider // received no work. Only failures before this boundary are free to settle. turnDispatchAttempted = true; @@ -4939,6 +4993,7 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { const drainEvents = (async (): Promise => { for await (const event of turn.events) { lastRuntimeEventAt = now(); + if (turnStopRequestedAt === null) lastRuntimeEventBeforeStopAt = lastRuntimeEventAt; observedRuntimeEvents += 1; // ACPX currently flattens client-side filesystem/terminal receipts // into status text. They cannot establish complete action outcomes. @@ -4950,6 +5005,7 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { interruptionTools.set(event.toolCallId, { kind: event.kind ?? previous?.kind, status: event.status ?? previous?.status, + firstSeenAt: previous?.firstSeenAt ?? lastRuntimeEventAt, }); } } @@ -5004,14 +5060,14 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) { // 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; + const pendingTools = [...interruptionTools.values()].filter(isPendingAcpTool); const activityDiagnostics = { acpObservedEventCount: observedRuntimeEvents, ...(lastEventAgeMs !== undefined && Number.isSafeInteger(lastEventAgeMs) && lastEventAgeMs >= 0 ? { acpLastEventAgeMs: lastEventAgeMs } : {}), - acpPendingToolCount: [...interruptionTools.values()].filter( - (tool) => tool.status !== "completed" && tool.status !== "failed" && tool.status !== "cancelled", - ).length, + acpPendingToolCount: pendingTools.length, acpToolInventoryComplete: !incompleteToolInventory, + ...summarizeAcpStopActivity(turnStopRequestedAt, lastRuntimeEventBeforeStopAt, pendingToolsAtStop ?? pendingTools), }; if (input.kind === "terminal") { const terminal = input.terminal; diff --git a/server/src/services/__tests__/run-failure-diagnostics.test.ts b/server/src/services/__tests__/run-failure-diagnostics.test.ts index 731c569e0e9..e75e043311c 100644 --- a/server/src/services/__tests__/run-failure-diagnostics.test.ts +++ b/server/src/services/__tests__/run-failure-diagnostics.test.ts @@ -323,11 +323,29 @@ describe("run failure diagnostics", () => { expect(JSON.stringify(result)).not.toContain("private"); }); + it("includes stop-time ACP activity and closed pending tool-kind labels", () => { + const result = sanitizeRunFailureDiagnostics(collectRunFailureDiagnostics(run({ resultJson: { + acpLastEventAgeMs: 700, acpLastEventAgeAtStopMs: 14_000_000, acpOldestPendingToolAgeAtStopMs: 14_100_000, + acpPendingToolKinds: "execute,unknown", + } }), {})); + expect(result.execution).toEqual({ + acpLastEventAgeMs: 700, acpLastEventAgeAtStopMs: 14_000_000, acpOldestPendingToolAgeAtStopMs: 14_100_000, + acpPendingToolKinds: "execute,unknown", + }); + }); + + 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 } }), {}); + expect(result.execution).toEqual({}); + }, + ); + it.each([null, -1, Infinity, NaN, 1.5, Number.MAX_SAFE_INTEGER + 1, "private", {}])( "omits invalid ACP activity fields (%j)", (value) => { const result = collectRunFailureDiagnostics(run({ resultJson: { acpLastEventAgeMs: value, acpObservedEventCount: value, acpPendingToolCount: value, - acpToolInventoryComplete: value, + acpToolInventoryComplete: value, acpLastEventAgeAtStopMs: value, acpOldestPendingToolAgeAtStopMs: value, } }), {}); expect(result.execution).toEqual({}); }, diff --git a/server/src/services/run-failure-diagnostics.ts b/server/src/services/run-failure-diagnostics.ts index 7a14c7e3d84..ae9614a09af 100644 --- a/server/src/services/run-failure-diagnostics.ts +++ b/server/src/services/run-failure-diagnostics.ts @@ -6,6 +6,7 @@ import { readProcessLossDiagnostic } from "./process-loss-diagnostics.js"; import { WORKSPACE_RESTORE_FAILURE_CODES } from "@paperclipai/shared"; import { redactDiagnosticText } from "@paperclipai/adapter-utils/command-redaction"; import { sanitizeWorkspaceRestoreDiagnostic } from "@paperclipai/adapter-utils/workspace-restore-diagnostics"; +import { ACP_TOOL_KINDS } from "@paperclipai/adapter-utils/acpx-engine/constants"; import { redactCurrentUserText } from "../log-redaction.js"; import { redactSensitiveText, REDACTED_EVENT_VALUE } from "../redaction.js"; import { readNativeModelRejectionDiagnostic } from "./native-runtime/native-provider-failure.js"; @@ -41,6 +42,15 @@ export interface RunFailureDiagnostics { truncatedFields: string[]; } +const ACP_PENDING_TOOL_KIND_LABELS: ReadonlySet = new Set([...ACP_TOOL_KINDS, "unknown"]); + +/** Closed ACP tool-kind labels only; any other content drops the whole field. */ +function readAcpPendingToolKinds(value: unknown): string | null { + if (typeof value !== "string" || value.length === 0 || value.length > 200) return null; + const kinds = value.split(","); + return kinds.every((kind) => ACP_PENDING_TOOL_KIND_LABELS.has(kind)) ? value : null; +} + function read(value: unknown, key: string): unknown { if (!value || typeof value !== "object") return undefined; try { @@ -197,10 +207,15 @@ export function collectRunFailureDiagnostics(run: Run, options: RunFailureReport "mode", "stopReason", "timeoutFired", "timeoutSource", "timeoutConfigured", "effectiveTimeoutSec", "errorFamily", ])); - for (const field of ["acpLastEventAgeMs", "acpObservedEventCount", "acpPendingToolCount"]) { + for (const field of [ + "acpLastEventAgeMs", "acpObservedEventCount", "acpPendingToolCount", + "acpLastEventAgeAtStopMs", "acpOldestPendingToolAgeAtStopMs", + ]) { const value = read(result, field); if (typeof value === "number" && Number.isSafeInteger(value) && value >= 0) execution[field] = value; } + const pendingToolKinds = readAcpPendingToolKinds(read(result, "acpPendingToolKinds")); + if (pendingToolKinds) execution.acpPendingToolKinds = pendingToolKinds; const toolInventoryComplete = read(result, "acpToolInventoryComplete"); if (typeof toolInventoryComplete === "boolean") execution.acpToolInventoryComplete = toolInventoryComplete; const restoreFailure = read(result, "workspaceRestoreFailure");