mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-10-02 02:07:25 +08:00
Record ACP activity and workspace restore failure evidence (#14665)
## Thinking Path Paperclip records terminal run failures for operators. A timeout's own log and cleanup output update the run's last-output timestamp, so that timestamp can make a long-silent provider look active. Snapshot runtime activity before finalization and include the saved workspace restore classification to make the next failure actionable without copying tool payloads. ## Linked Issues or Issue Description **What existing behavior does this improve?** Terminal run diagnostics in the existing opt-in Sentry integration. **Current behavior** Reports cannot distinguish runtime events from finalization logging and omit the already-persisted workspace restore code. A later successful run also does not establish that earlier workspace files were restored. **Proposed behavior** Record runtime-event age/count and pending-tool inventory at finalization, before status reads and cleanup. Forward only finite counts, a completeness boolean, and known restore codes through the existing reporter. **Reason and benefit** Operators can distinguish a silent turn with unfinished tools from recent runtime activity and see restore failures without retrieving private run output. Neither signal certifies productive work or successful recovery. **Breaking changes** None. Error grouping, execution deadlines, cancellation, recovery policy, and the Sentry opt-in remain unchanged. Related diagnostic work: #14573, #14575, #14639. ## What Changed - Snapshot ACP activity before success/failure finalization, including thrown relay failures. - Forward bounded numeric/boolean evidence and shared workspace restore codes; exclude commands, tool IDs, paths, and arbitrary result data. - Document limitations and test silence, empty streams, timeout, cleanup delay, incomplete tool inventory, and privacy. ## Verification - `pnpm -r typecheck` passed after the final implementation. - Changed suites: 252 tests passed; all 29 database reporter tests subsequently passed after restoring the embedded-Postgres package library symlinks. The migration test also passed (30 database cases total). - `pnpm build` passed during implementation. Final head `fe78dba6f592b1abccac7cdbf341bd2e0b0d30cb` passed all 53 CI checks, including complete test coverage, typecheck, build, and browser/runner gates; two unrelated checks intentionally skipped. - Full local test attempts initially hit missing embedded-Postgres library symlinks; the dependency setup was repaired and database tests passed. Duplicate local full-suite runs were stopped after full CI completed. This PR does not claim a completed full local suite. - Review regression: completed, failed, and cancelled tools are excluded from the pending count; focused activity/timeout tests and adapter-utils typecheck passed. - Reviewed the diff for secrets, customer data, and internal references. ## Risks Low risk, diagnostic-only. The existing tool inventory is incomplete for some runtime events, so the report carries its completeness flag. Event age is measured at finalization and does not prove useful work or identify the underlying provider failure. No schema changes or new capture gate. ## Model Used OpenAI GPT-6 via Codex, with repository inspection, code execution, and tests. Exact model build identifier is not exposed by this session. ## Checklist - [x] Thinking path and model are specified - [x] Checked ROADMAP.md; this is a maintenance correction, not planned feature work - [x] Searched for duplicate and related PRs - [x] Described the issue using the enhancement template - [x] No internal issue references, customer data, or private instance links - [x] Descriptive branch name - [x] Focused regression tests pass - [x] Added tests and updated documentation - [x] Risks documented - [x] Required validation and CI gates are green (full suite validated in CI; local scope documented above) - [x] Greptile is 5/5 with no unresolved findings - [x] I will address review comments before requesting merge --------- Co-authored-by: Paperclip <noreply@paperclip.ing>
This commit is contained in:
+19
-1
@@ -457,13 +457,31 @@ The shared reporter also attaches bounded diagnostic contexts for both legacy
|
|||||||
and native runs:
|
and native runs:
|
||||||
|
|
||||||
- `run_execution`: runtime mode, execution stage/native phase, driver and version,
|
- `run_execution`: runtime mode, execution stage/native phase, driver and version,
|
||||||
duration, failure phase, stop reason, error family, and timeout settings when available.
|
duration, ACP activity, failure phase, stop reason, error family,
|
||||||
|
and timeout settings when available.
|
||||||
- `adapter_failure`: selected adapter error fields such as phase, category,
|
- `adapter_failure`: selected adapter error fields such as phase, category,
|
||||||
protocol code, retryability, cause message, stack preview, HTTP status, and request ID.
|
protocol code, retryability, cause message, stack preview, HTTP status, and request ID.
|
||||||
- `provider_failure`: the saved provider failure category, title, and details.
|
- `provider_failure`: the saved provider failure category, title, and details.
|
||||||
- `run_exception_0` through `run_exception_3`: exception names, codes, HTTP
|
- `run_exception_0` through `run_exception_3`: exception names, codes, HTTP
|
||||||
statuses, and request IDs for a caught exception and up to three causes.
|
statuses, and request IDs for a caught exception and up to three causes.
|
||||||
|
|
||||||
|
ACP turns record `acpLastEventAgeMs`, `acpObservedEventCount`,
|
||||||
|
`acpPendingToolCount`, and `acpToolInventoryComplete` at finalization, before
|
||||||
|
usage reads, error logging, and cleanup. The age measures time since the last
|
||||||
|
runtime event and is omitted if no event was observed or the clock is invalid.
|
||||||
|
Timeout and cleanup log messages do not reset this age. The pending count uses
|
||||||
|
known tool statuses; an incomplete inventory cannot establish that no work is
|
||||||
|
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.
|
||||||
|
|
||||||
|
When settlement records a workspace restore failure, `run_execution` also
|
||||||
|
includes `workspaceRestoreFailure` with one of the shared, path-free codes:
|
||||||
|
`restore_permission_denied`, `restore_lock_timeout`, `restore_unsafe_archive`,
|
||||||
|
or `restore_failed`. Unknown values are omitted. Workspace paths and arbitrary
|
||||||
|
pre-restore result data are not included. A later successful run does not, by
|
||||||
|
itself, establish that an earlier failed restore recovered the workspace files.
|
||||||
|
|
||||||
The execution and setup catch paths pass the original exception to the reporter.
|
The execution and setup catch paths pass the original exception to the reporter.
|
||||||
It snapshots and rebuilds only these selected fields and the original message and
|
It snapshots and rebuilds only these selected fields and the original message and
|
||||||
stack. Sentry receives the sanitized cause chain rather than a stack created at
|
stack. Sentry receives the sanitized cause chain rather than a stack created at
|
||||||
|
|||||||
@@ -3030,9 +3030,69 @@ describe("gemini ACP flag selection", () => {
|
|||||||
expect(result.errorCode).toBe("acpx_timeout");
|
expect(result.errorCode).toBe("acpx_timeout");
|
||||||
expect(result.errorMessage).toBe(expectedMessage);
|
expect(result.errorMessage).toBe(expectedMessage);
|
||||||
expect(cancelReasons).toContain(expectedMessage);
|
expect(cancelReasons).toContain(expectedMessage);
|
||||||
|
expect(result.resultJson).toMatchObject({ acpObservedEventCount: 0, acpPendingToolCount: 0, acpToolInventoryComplete: true });
|
||||||
|
expect(result.resultJson).not.toHaveProperty("acpLastEventAgeMs");
|
||||||
}, 15_000);
|
}, 15_000);
|
||||||
});
|
});
|
||||||
|
|
||||||
|
describe("ACP activity diagnostics", () => {
|
||||||
|
it.each(["terminal", "relay_error", "no_events"])(
|
||||||
|
"snapshots %s activity before usage reads, failure logging, and cleanup", async (outcome) => {
|
||||||
|
const root = await makeTempRoot();
|
||||||
|
const cwd = path.join(root, "worktree");
|
||||||
|
await fs.mkdir(cwd, { recursive: true });
|
||||||
|
let currentNow = 1000;
|
||||||
|
let statusReads = 0;
|
||||||
|
const execute = createAcpxEngineExecutor({
|
||||||
|
now: () => currentNow,
|
||||||
|
createRuntime: () => ({
|
||||||
|
...buildRuntime(),
|
||||||
|
getStatus: async () => {
|
||||||
|
if (++statusReads > 1) currentNow += 100_000;
|
||||||
|
return null;
|
||||||
|
},
|
||||||
|
startTurn: () => ({
|
||||||
|
events: (async function* () {
|
||||||
|
if (outcome !== "no_events") {
|
||||||
|
yield { type: "tool_call", toolCallId: "private-pending-id", title: "private command", kind: "execute", status: "in_progress" };
|
||||||
|
yield { type: "tool_call", toolCallId: "private-done-id", title: "private read", kind: "read", status: "in_progress" };
|
||||||
|
yield { type: "tool_call", toolCallId: "private-done-id", status: "completed" };
|
||||||
|
yield { type: "tool_call", toolCallId: "private-cancelled-id", status: "cancelled" };
|
||||||
|
yield { type: "tool_call", toolCallId: "private-failed-id", status: "failed" };
|
||||||
|
yield { type: "status", text: "terminal/create private receipt" };
|
||||||
|
}
|
||||||
|
currentNow = 10_000;
|
||||||
|
if (outcome === "relay_error") throw new Error("relay failed");
|
||||||
|
})(),
|
||||||
|
result: Promise.resolve({ status: "failed", error: new Error("turn failed") }),
|
||||||
|
cancel: async () => {},
|
||||||
|
}),
|
||||||
|
close: async () => { currentNow += 100_000; },
|
||||||
|
}) as never,
|
||||||
|
});
|
||||||
|
const result = await execute({
|
||||||
|
runId: "activity-run", 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) => {
|
||||||
|
if (text.includes('"type":"acpx.error"')) currentNow += 100_000;
|
||||||
|
},
|
||||||
|
} as never);
|
||||||
|
expect(result.exitCode).toBe(1);
|
||||||
|
expect(result.resultJson).toMatchObject({
|
||||||
|
acpObservedEventCount: outcome === "no_events" ? 0 : 6,
|
||||||
|
acpPendingToolCount: outcome === "no_events" ? 0 : 1,
|
||||||
|
acpToolInventoryComplete: outcome === "no_events",
|
||||||
|
});
|
||||||
|
if (outcome === "no_events") expect(result.resultJson).not.toHaveProperty("acpLastEventAgeMs");
|
||||||
|
else expect(result.resultJson?.acpLastEventAgeMs).toBe(9000);
|
||||||
|
const diagnostics = Object.fromEntries(Object.entries(result.resultJson ?? {}).filter(([key]) => key.startsWith("acp")));
|
||||||
|
expect(JSON.stringify(diagnostics)).not.toContain("private");
|
||||||
|
expect(currentNow).toBeGreaterThan(10_000);
|
||||||
|
},
|
||||||
|
);
|
||||||
|
});
|
||||||
|
|
||||||
describe("summarizeAcpxTurnUsage", () => {
|
describe("summarizeAcpxTurnUsage", () => {
|
||||||
it("uses the post-turn amount alone when the cumulative cost counter reset", () => {
|
it("uses the post-turn amount alone when the cumulative cost counter reset", () => {
|
||||||
const summary = summarizeAcpxTurnUsage({
|
const summary = summarizeAcpxTurnUsage({
|
||||||
|
|||||||
@@ -4691,6 +4691,8 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||||||
};
|
};
|
||||||
let eventBreakdown: AcpRuntimeUsageBreakdown | null = null;
|
let eventBreakdown: AcpRuntimeUsageBreakdown | null = null;
|
||||||
let eventCostUsd: number | null = null;
|
let eventCostUsd: number | null = null;
|
||||||
|
let lastRuntimeEventAt: number | null = null;
|
||||||
|
let observedRuntimeEvents = 0;
|
||||||
// The turn-local state the sequence steps share. `promptBuild` sets the
|
// The turn-local state the sequence steps share. `promptBuild` sets the
|
||||||
// prompt, `preTurnUsage` sets the pre-turn status, `turnStart` sets the
|
// prompt, `preTurnUsage` sets the pre-turn status, `turnStart` sets the
|
||||||
// active turn, and `turnFinalize` reads all three. `activeTurn` is the run-
|
// active turn, and `turnFinalize` reads all three. `activeTurn` is the run-
|
||||||
@@ -4861,6 +4863,8 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||||||
const toolTitles = new Map<string, string>();
|
const toolTitles = new Map<string, string>();
|
||||||
const drainEvents = (async (): Promise<void> => {
|
const drainEvents = (async (): Promise<void> => {
|
||||||
for await (const event of turn.events) {
|
for await (const event of turn.events) {
|
||||||
|
lastRuntimeEventAt = now();
|
||||||
|
observedRuntimeEvents += 1;
|
||||||
// ACPX currently flattens client-side filesystem/terminal receipts
|
// ACPX currently flattens client-side filesystem/terminal receipts
|
||||||
// into status text. They cannot establish complete action outcomes.
|
// into status text. They cannot establish complete action outcomes.
|
||||||
if (event.type === "status" && /^(fs|terminal)\//.test(event.text)) incompleteToolInventory = true;
|
if (event.type === "status" && /^(fs|terminal)\//.test(event.text)) incompleteToolInventory = true;
|
||||||
@@ -4918,6 +4922,18 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||||||
const stepTurnFinalize = async (
|
const stepTurnFinalize = async (
|
||||||
input: TurnFinalizeInput<AcpRuntimeTurnResult>,
|
input: TurnFinalizeInput<AcpRuntimeTurnResult>,
|
||||||
): Promise<TurnCompletion> => {
|
): Promise<TurnCompletion> => {
|
||||||
|
// 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 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,
|
||||||
|
acpToolInventoryComplete: !incompleteToolInventory,
|
||||||
|
};
|
||||||
if (input.kind === "terminal") {
|
if (input.kind === "terminal") {
|
||||||
const terminal = input.terminal;
|
const terminal = input.terminal;
|
||||||
const timedOut = input.timedOut;
|
const timedOut = input.timedOut;
|
||||||
@@ -5047,6 +5063,7 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||||||
costUsd: turnUsage.costUsd,
|
costUsd: turnUsage.costUsd,
|
||||||
resultJson: {
|
resultJson: {
|
||||||
status: channelLost ? "failed" : terminal.status,
|
status: channelLost ? "failed" : terminal.status,
|
||||||
|
...activityDiagnostics,
|
||||||
...(failureDiagnostic ? { terminalSessionFailure: failureDiagnostic } : {}),
|
...(failureDiagnostic ? { terminalSessionFailure: failureDiagnostic } : {}),
|
||||||
...(classifiedFailure?.errorFamily ? { errorFamily: classifiedFailure.errorFamily } : {}),
|
...(classifiedFailure?.errorFamily ? { errorFamily: classifiedFailure.errorFamily } : {}),
|
||||||
...(classifiedFailure?.retryNotBefore
|
...(classifiedFailure?.retryNotBefore
|
||||||
@@ -5181,7 +5198,7 @@ export function createAcpxEngineExecutor(deps: AcpxEngineExecutorOptions = {}) {
|
|||||||
...referencedProjectStagingFailuresField,
|
...referencedProjectStagingFailuresField,
|
||||||
model: prepared.requestedModel || null,
|
model: prepared.requestedModel || null,
|
||||||
clearSession: clearSession || timedOut,
|
clearSession: clearSession || timedOut,
|
||||||
resultJson: { phase },
|
resultJson: { phase, ...activityDiagnostics },
|
||||||
summary: message,
|
summary: message,
|
||||||
};
|
};
|
||||||
// Return a typed failed completion so the coordinator settles for a cause
|
// Return a typed failed completion so the coordinator settles for a cause
|
||||||
|
|||||||
@@ -7,6 +7,47 @@ const run = (overrides: Partial<Run> = {}) => ({ resultJson: null, ...overrides
|
|||||||
const collect = (error: unknown) => collectRunFailureDiagnostics(run(), { error });
|
const collect = (error: unknown) => collectRunFailureDiagnostics(run(), { error });
|
||||||
|
|
||||||
describe("run failure diagnostics", () => {
|
describe("run failure diagnostics", () => {
|
||||||
|
it.each(["restore_permission_denied", "restore_lock_timeout", "restore_unsafe_archive", "restore_failed"])(
|
||||||
|
"includes the saved %s classification without copying workspace paths or results", (code) => {
|
||||||
|
const result = sanitizeRunFailureDiagnostics(collectRunFailureDiagnostics(run({ resultJson: {
|
||||||
|
workspaceRestoreFailure: code, workspaceRestorePath: "/private/workspace",
|
||||||
|
executionBeforeRestore: { errorMessage: "private provider response" },
|
||||||
|
} }), {}));
|
||||||
|
expect(result.execution).toEqual({ workspaceRestoreFailure: code });
|
||||||
|
expect(JSON.stringify(result)).not.toContain("private");
|
||||||
|
},
|
||||||
|
);
|
||||||
|
|
||||||
|
it.each([null, false, 1, "private arbitrary code", { error: "private" }])(
|
||||||
|
"omits unknown workspace restore classifications (%j)", (value) => {
|
||||||
|
const result = collectRunFailureDiagnostics(run({ resultJson: { workspaceRestoreFailure: value } }), {});
|
||||||
|
expect(result.execution).not.toHaveProperty("workspaceRestoreFailure");
|
||||||
|
expect(JSON.stringify(result)).not.toContain("private");
|
||||||
|
},
|
||||||
|
);
|
||||||
|
|
||||||
|
it("includes only bounded ACP activity fields, not tool names, identities, or output", () => {
|
||||||
|
const result = sanitizeRunFailureDiagnostics(collectRunFailureDiagnostics(run({ resultJson: {
|
||||||
|
acpLastEventAgeMs: 14_000_000, acpObservedEventCount: 9, acpPendingToolCount: 2,
|
||||||
|
acpToolInventoryComplete: false, acpToolNames: ["private command"], lastEvent: "private output",
|
||||||
|
} }), {}));
|
||||||
|
expect(result.execution).toEqual({
|
||||||
|
acpLastEventAgeMs: 14_000_000, acpObservedEventCount: 9, acpPendingToolCount: 2,
|
||||||
|
acpToolInventoryComplete: false,
|
||||||
|
});
|
||||||
|
expect(JSON.stringify(result)).not.toContain("private");
|
||||||
|
});
|
||||||
|
|
||||||
|
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,
|
||||||
|
} }), {});
|
||||||
|
expect(result.execution).toEqual({});
|
||||||
|
},
|
||||||
|
);
|
||||||
|
|
||||||
it("selects declared environment secrets under opaque names and common credential keys", () => {
|
it("selects declared environment secrets under opaque names and common credential keys", () => {
|
||||||
expect(collectRunFailureSecretValues({
|
expect(collectRunFailureSecretValues({
|
||||||
CUSTOM_BINDING: "bound-opaque-value", ACCESS_TOKEN: "plain-opaque-value", REGION: "us-east-1", EMPTY_KEY: "",
|
CUSTOM_BINDING: "bound-opaque-value", ACCESS_TOKEN: "plain-opaque-value", REGION: "us-east-1", EMPTY_KEY: "",
|
||||||
|
|||||||
@@ -1,4 +1,5 @@
|
|||||||
import type { heartbeatRuns } from "@paperclipai/db";
|
import type { heartbeatRuns } from "@paperclipai/db";
|
||||||
|
import { WORKSPACE_RESTORE_FAILURE_CODES } from "@paperclipai/shared";
|
||||||
import { redactDiagnosticText } from "@paperclipai/adapter-utils/command-redaction";
|
import { redactDiagnosticText } from "@paperclipai/adapter-utils/command-redaction";
|
||||||
import { redactCurrentUserText } from "../log-redaction.js";
|
import { redactCurrentUserText } from "../log-redaction.js";
|
||||||
import { redactSensitiveText, REDACTED_EVENT_VALUE } from "../redaction.js";
|
import { redactSensitiveText, REDACTED_EVENT_VALUE } from "../redaction.js";
|
||||||
@@ -146,6 +147,15 @@ export function collectRunFailureDiagnostics(run: Run, options: RunFailureReport
|
|||||||
"mode", "stopReason", "timeoutFired", "timeoutSource", "timeoutConfigured",
|
"mode", "stopReason", "timeoutFired", "timeoutSource", "timeoutConfigured",
|
||||||
"effectiveTimeoutSec", "errorFamily",
|
"effectiveTimeoutSec", "errorFamily",
|
||||||
]));
|
]));
|
||||||
|
for (const field of ["acpLastEventAgeMs", "acpObservedEventCount", "acpPendingToolCount"]) {
|
||||||
|
const value = read(result, field);
|
||||||
|
if (typeof value === "number" && Number.isSafeInteger(value) && value >= 0) execution[field] = value;
|
||||||
|
}
|
||||||
|
const toolInventoryComplete = read(result, "acpToolInventoryComplete");
|
||||||
|
if (typeof toolInventoryComplete === "boolean") execution.acpToolInventoryComplete = toolInventoryComplete;
|
||||||
|
const restoreFailure = read(result, "workspaceRestoreFailure");
|
||||||
|
const restoreCode = WORKSPACE_RESTORE_FAILURE_CODES.find((code) => code === restoreFailure);
|
||||||
|
if (restoreCode) execution.workspaceRestoreFailure = restoreCode;
|
||||||
const adapter = scalars(options.adapterErrorMeta, [
|
const adapter = scalars(options.adapterErrorMeta, [
|
||||||
"category", "phase", "errorName", "acpCode", "causeMessage", "retryable",
|
"category", "phase", "errorName", "acpCode", "causeMessage", "retryable",
|
||||||
"stackPreview", "status", "statusCode", "requestId",
|
"stackPreview", "status", "statusCode", "requestId",
|
||||||
|
|||||||
Reference in New Issue
Block a user