mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-07 16:35:48 +01:00
fix(acpx): record turn activity at the moment a stop fires
Sandbox claude_local runs that hit the 4h wall-clock backstop report acpLastEventAgeMs at finalization, after the timeout's cancel. Some agents emit closing events on cancel, so a turn that went silent minutes into the run can look active at its deadline. Record, for a stopped turn, the last-event age and the oldest pending tool's age as of the stop, plus the pending tools' closed ACP ToolKind labels. The server forwards these to run-failure diagnostics only when they are non-negative integers or closed enum labels. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
1 parent
b189f586d2
commit
eed2d27675
6 files changed
+175
-6
No files matched your search
@@ -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",
|
||||
|
||||
@@ -33,6 +33,7 @@ import {
|
||||
parseGeminiVersionParts,
|
||||
referencedSourceContentSignature,
|
||||
rewriteGeminiAcpFlagForVersion,
|
||||
summarizeAcpStopActivity,
|
||||
summarizeAcpxTurnUsage,
|
||||
type AcpxEngineExecutorOptions,
|
||||
} from "./execute.js";
|
||||
@@ -3347,6 +3348,77 @@ 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<void>((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);
|
||||
});
|
||||
|
||||
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", () => {
|
||||
|
||||
@@ -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,42 @@ async function emitRuntimeEvent(
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* 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<typeof summarizeAcpStopActivity> = {};
|
||||
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 +4083,7 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
||||
let runtimeStopConfirmed = false;
|
||||
let safeInterruptedSession = false;
|
||||
let preserveInterruptedSession = false;
|
||||
const interruptionTools = new Map<string, { kind?: string; status?: string }>();
|
||||
const interruptionTools = new Map<string, { kind?: string; status?: string; firstSeenAt?: number }>();
|
||||
let incompleteToolInventory = false;
|
||||
try {
|
||||
await ctx.onCancellationReady?.();
|
||||
@@ -4759,6 +4796,12 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
||||
let observedUsage: Pick<AdapterExecutionResult, "usage" | "usageBasis" | "costUsd" | "usageComplete"> = { 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, so the finalize-time age alone cannot tell a silent stall
|
||||
// from live work.
|
||||
let turnStopRequestedAt: number | null = null;
|
||||
let lastRuntimeEventBeforeStopAt: 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 +4889,7 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
||||
};
|
||||
const stepTurnStart = (signal: AbortSignal, startTimeoutMs: number | undefined): StartedTurn => {
|
||||
ctx.signal?.throwIfAborted();
|
||||
signal.addEventListener("abort", () => { turnStopRequestedAt ??= now(); }, { 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 +4983,7 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
||||
const drainEvents = (async (): Promise<void> => {
|
||||
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 +4995,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 +5050,16 @@ 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(
|
||||
(tool) => tool.status !== "completed" && tool.status !== "failed" && tool.status !== "cancelled",
|
||||
);
|
||||
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, pendingTools),
|
||||
};
|
||||
if (input.kind === "terminal") {
|
||||
const terminal = input.terminal;
|
||||
|
||||
Reference in new issue
Block a user