diff --git a/doc/execution-semantics.md b/doc/execution-semantics.md index 9047d556370..7ea137edf07 100644 --- a/doc/execution-semantics.md +++ b/doc/execution-semantics.md @@ -2487,6 +2487,17 @@ agent, workspace, retained session, and termination of prior execution. The checkpoint must match the exact Runner, lease, run, session, turn, and item. A missing restart claim does not remove these checks or authorize a fresh session. +These checks can refuse the exact checkpoint before the retry claims a new +provider attempt. For example, the interrupted attempt can leave the provider +state not suspended. The run error then names the interrupted attempt first, as +`: ; exact checkpoint resume refused: +`. The run result keeps the same facts in `nativeExactResumeRefusal`. +The error code, recovery owner, and retry eligibility do not change: retry, +recovery and stop-reason checks read the refusal, not the earlier failure text. +Both texts are masked before they are cut to fit the 2,000-character bound. +The interrupted attempt's text stays in company-scoped run records; a Sentry +run-failure report carries only the refusal. + Reattachment readies the exact retained sandbox lease through the provider's bounded lifecycle resume before running short preparation commands such as the managed project-authentication check. The resume receipt must confirm the same diff --git a/server/src/services/__tests__/run-failure-report.test.ts b/server/src/services/__tests__/run-failure-report.test.ts index f308bec5443..9e288030a26 100644 --- a/server/src/services/__tests__/run-failure-report.test.ts +++ b/server/src/services/__tests__/run-failure-report.test.ts @@ -126,6 +126,22 @@ describeEmbeddedPostgres("reportRunFailure", () => { } as unknown as typeof heartbeatRuns.$inferSelect; } + it("reports only the refusal of a refused exact resume, never the interrupted attempt's provider text", async () => { + await seedCompanyAndAgent(); + const marker = "interrupted-provider-explanation-7f3c"; + const refusal = "Plugin Runner retained session is not authorized"; + await reportRunFailure(db, buildRun({ + errorCode: "adapter_failed", + error: `native_session_interrupted: ${marker}; exact checkpoint resume refused: ${refusal}`, + resultJson: { nativeExactResumeRefusal: { originalFailureCode: "native_session_interrupted", + originalMessage: marker, interruptedAttempt: 1, refusal } }, + })); + expect(mockCaptureRunFailure).toHaveBeenCalledOnce(); + const event = mockCaptureRunFailure.mock.calls[0]![0]; + expect(event.errorMessage).toBe(refusal); + expect(JSON.stringify(event)).not.toContain(marker); + }); + it.each([undefined, "", "off", "true", "invalid"])("does no reporting work without an explicit valid mode: %s", async mode => { vi.stubEnv("PAPERCLIP_SENTRY_RUN_FAILURES", mode); if (mode === undefined) delete process.env.PAPERCLIP_SENTRY_RUN_FAILURES; diff --git a/server/src/services/heartbeat/retries.test.ts b/server/src/services/heartbeat/retries.test.ts index 37ffe770d93..ab5cb054f6c 100644 --- a/server/src/services/heartbeat/retries.test.ts +++ b/server/src/services/heartbeat/retries.test.ts @@ -198,6 +198,36 @@ describe("heartbeat retry module callbacks", () => { expect(deps.finalizeAgentStatus).toHaveBeenCalledAfter(deps.releaseIssueExecutionAndPromote); expect(database.access).not.toHaveBeenCalled(); }); + + it("decides an interaction continuation retry from a refused exact resume's refusal, not its earlier spawn failure", async () => { + const refusal = "Plugin Runner retained session is not authorized"; + const interaction = { issueId: "issue", interactionId: "interaction-1", interactionStatus: "answered", mutation: "interaction", + wakeReason: "issue_commented", timerClaimWasFirstHeartbeat: true }; + // The retry budget is spent, so an eligible run reports exhaustion + // without scheduling, and an ineligible one escalates directly. + const failed = { ...unitRun(), status: "failed", errorCode: "adapter_failed", scheduledRetryAttempt: 2, + scheduledRetryReason: legacy.INTERACTION_CONTINUATION_INFRA_RETRY_REASON, contextSnapshot: interaction } as Run; + const refused = { ...failed, + error: `native_session_interrupted: failed to start command: spawn agent ENOENT; exact checkpoint resume refused: ${refusal}`, + resultJson: { nativeExactResumeRefusal: { originalFailureCode: "native_session_interrupted", + originalMessage: "failed to start command: spawn agent ENOENT", interruptedAttempt: 1, refusal } } } as Run; + const spawnFailure = { ...failed, error: "failed to start command: spawn agent ENOENT", resultJson: {} } as Run; + const exhaustion = expect.objectContaining({ retryExhaustion: expect.objectContaining({ + retryReason: legacy.INTERACTION_CONTINUATION_INFRA_RETRY_REASON }) }); + + const database = guardedDatabase(); + const refusedDeps = callbacks(); + await expect(extracted.createHeartbeatRetries(database.db, refusedDeps) + .scheduleInteractionContinuationInfrastructureRetryIfEligible(refused, { adapterType: "codex_local" } as Agent)).resolves.toBeNull(); + expect(refusedDeps.appendRunEvent).not.toHaveBeenCalledWith(refused, exhaustion); + expect(refusedDeps.escalatePlanApprovalResumeFailureNeedsAttention).toHaveBeenCalledOnce(); + + const spawnDeps = callbacks(); + await extracted.createHeartbeatRetries(database.db, spawnDeps) + .scheduleInteractionContinuationInfrastructureRetryIfEligible(spawnFailure, { adapterType: "codex_local" } as Agent); + expect(spawnDeps.appendRunEvent).toHaveBeenCalledWith(spawnFailure, exhaustion); + expect(database.access).not.toHaveBeenCalled(); + }); }); import { resolveExternalTestDatabaseUrl } from "../../__tests__/helpers/external-test-database.js"; diff --git a/server/src/services/heartbeat/retries.ts b/server/src/services/heartbeat/retries.ts index 34a08c0afaf..d7a734a57fc 100644 --- a/server/src/services/heartbeat/retries.ts +++ b/server/src/services/heartbeat/retries.ts @@ -78,6 +78,7 @@ import { import type { AppendHeartbeatRunEventInput } from "../heartbeat-run-events.js"; import type { evaluateAgentInvokabilityFromDb } from "../agent-invokability.js"; +import { currentRunFailureText } from "../native-runtime/native-exact-resume-failure.js"; import type { createHeartbeatRunState } from "./run-state.js"; import type { createHeartbeatRunPreparation } from "./run-preparation.js"; import type { createRunDispatch, PostCommitEffect } from "../../modules/run-dispatch/index.js"; @@ -370,11 +371,14 @@ function isRetryableInteractionContinuationInfrastructureFailure( return false; const resultJson = parseObject(run.resultJson); + // A refused exact resume names its interrupted attempt in `error`; the + // retry decision follows the current refusal only. + const error = currentRunFailureText(run); return ( - isSpawnLikeFailureMessage(run.error) || + isSpawnLikeFailureMessage(error) || isSpawnLikeFailureMessage(resultJson.errorMessage) || isSpawnLikeFailureMessage(resultJson.message) || - isSandboxProviderWorkerUnavailableFailureMessage(run.error) || + isSandboxProviderWorkerUnavailableFailureMessage(error) || isSandboxProviderWorkerUnavailableFailureMessage(resultJson.errorMessage) || isSandboxProviderWorkerUnavailableFailureMessage(resultJson.message) ); diff --git a/server/src/services/heartbeat/run-completion.test.ts b/server/src/services/heartbeat/run-completion.test.ts index 278caf7f769..6ff985ed53d 100644 --- a/server/src/services/heartbeat/run-completion.test.ts +++ b/server/src/services/heartbeat/run-completion.test.ts @@ -97,7 +97,7 @@ function callbacks(db: Db) { budgets: { getInvocationBlock: vi.fn(async () => null) }, treeControlSvc: { getActivePauseHoldGate: vi.fn(async () => null) }, enqueueWakeup: vi.fn(), - getCurrentUserRedactionOptions: vi.fn(async () => ({ enabled: false })), + getCurrentUserRedactionOptions: vi.fn(async () => ({ enabled: false })), getAgentInvokability: vi.fn(async () => ({ invokable: true })), emitTerminalAgentTaskRun: vi.fn(), budgetHooks: {}, } satisfies HeartbeatLifecycleDependencies; @@ -722,6 +722,85 @@ describe.skipIf(!support.supported && !process.env.PAPERCLIP_TEST_DATABASE_URL)( expect(f.deps.releaseIssueExecutionAndPromote).toHaveBeenCalledWith(expect.objectContaining({ id: f.run.id }), { suppressImmediateRecovery: true }); }); + describe("a same-run exact-checkpoint resume refused before its provider claim", () => { + const originalMessage = "PRP command turn.start failed: ACPX turn start failed closed: classification=session_resume_required"; + const refusal = "Plugin Runner retained session is not authorized"; + async function resumeClaim(recoveryHistory: Array>, attempt = 1) { + const f = await fixture({ runtimeMode: "native" }); + const [issue] = await db.insert(issues).values({ companyId: f.run.companyId, title: "Native resume" }).returning(); + await db.update(heartbeatRuns).set({ nativeIssueId: issue.id }).where(eq(heartbeatRuns.id, f.run.id)); + const leaseOwner = `runner:resume:${randomUUID()}`; + await db.insert(nativeRunFinalizations).values({ runId: f.run.id, companyId: f.run.companyId, issueId: issue.id, + phase: "observed", attempt, leaseOwner, leaseExpiresAt: new Date(Date.now() + 20 * 60_000), recoveryHistory }); + return { f, issue, leaseOwner, attempt }; + } + const interruption = { at: "2099-01-01T00:00:00.000Z", disposition: "retryable_failure", reason: "native_session_interrupted", + providerAttempt: 1, stderrTail: originalMessage, providerSessionEstablished: true, checkpointExists: true }; + + it("reports the interrupted first attempt in the terminal error, result and coordinator detail", async () => { + const { f, leaseOwner, attempt } = await resumeClaim([interruption]); + await f.completion.failRun(f.failure(new Error(refusal))); + const expected = `native_session_interrupted: ${originalMessage}; exact checkpoint resume refused: ${refusal}`; + const failed = await read(f.run.id); + expect(failed).toMatchObject({ status: "failed", errorCode: "adapter_failed", error: expected }); + expect(failed.resultJson).toMatchObject({ nativeExactResumeRefusal: { + originalFailureCode: "native_session_interrupted", originalMessage, interruptedAttempt: 1, refusal } }); + const [errorEvent] = await db.select().from(heartbeatRunEvents).where(and(eq(heartbeatRunEvents.runId, f.run.id), + eq(heartbeatRunEvents.eventType, "error"))); + expect(errorEvent?.message).toBe(expected); + + // The dispatcher then releases its unstarted claim; the coordinator keeps + // the same named cause and its unchanged eligibility fields. + const { settleUnstartedNativeSessionResume } = await import("../native-runtime/native-failed-run-owner-release.js"); + await expect(settleUnstartedNativeSessionResume(db, { runId: f.run.id, leaseOwner, attempt })).resolves.toBe(true); + const [coordinator] = await db.select().from(nativeRunFinalizations).where(eq(nativeRunFinalizations.runId, f.run.id)); + expect(coordinator).toMatchObject({ phase: "terminal_failure", failureCode: "adapter_failed", + failureDetail: { message: expected, originalFailureCode: "adapter_failed" } }); + }); + + it("masks usernames in both texts before their length budgets cut them", async () => { + // Each username crosses a cut: 1,500 characters for the original message + // and 480 for the refusal. A cut before masking would keep "casp". + const userName = "casperhost"; + const original = `${"x".repeat(1_495)} ${userName} could not resume`; + const longRefusal = `${"r".repeat(475)} ${userName} retained session is not authorized`; + const { f } = await resumeClaim([{ ...interruption, stderrTail: original }]); + f.deps.getCurrentUserRedactionOptions.mockResolvedValue({ enabled: true, userNames: [userName], homeDirs: [] }); + await f.completion.failRun(f.failure(new Error(longRefusal))); + const failed = await read(f.run.id); + const recorded = (failed.resultJson as { nativeExactResumeRefusal: Record }).nativeExactResumeRefusal; + expect(failed.error).toHaveLength(2_000); + expect(failed.error!.startsWith("native_session_interrupted: xxx")).toBe(true); + expect(failed.error!.endsWith(`; exact checkpoint resume refused: ${"r".repeat(475)} c***`)).toBe(true); + expect(recorded.originalMessage).toBe(`${"x".repeat(1_495)} c***`); + expect(recorded.refusal).toBe(`${"r".repeat(475)} c********* retained session is not authorized`); + for (const text of [failed.error!, recorded.originalMessage, recorded.refusal]) expect(text).not.toContain("casp"); + }); + + it("saves the failure when an emoji crosses each cut", async () => { + const emoji = "\u{1F642}"; + const { f } = await resumeClaim([{ ...interruption, stderrTail: `${"x".repeat(1_499)}${emoji} could not resume` }]); + await f.completion.failRun(f.failure(new Error(`${"r".repeat(479)}${emoji} retained session is not authorized`))); + const failed = await read(f.run.id); + expect(failed.status).toBe("failed"); + const recorded = (failed.resultJson as { nativeExactResumeRefusal: Record }).nativeExactResumeRefusal; + expect(recorded.originalMessage).toBe("x".repeat(1_499)); + expect(failed.error!.endsWith(`; exact checkpoint resume refused: ${"r".repeat(479)}`)).toBe(true); + }); + + it.each([ + ["has no prior interruption", [], 0], + ["follows a bootstrap retry", [{ ...interruption, checkpointExists: false, providerSessionEstablished: false }], 1], + ["already claimed a later provider attempt", [interruption], 2], + ])("keeps the thrown error unchanged when the run %s", async (_name, history, attempt) => { + const { f } = await resumeClaim(history, attempt); + await f.completion.failRun(f.failure(new Error(refusal))); + const failed = await read(f.run.id); + expect(failed).toMatchObject({ status: "failed", errorCode: "adapter_failed", error: refusal }); + expect(failed.resultJson).not.toHaveProperty("nativeExactResumeRefusal"); + }); + }); + it("persists a project denial without provider work or an automatic retry", async () => { const f = await fixture(); const projectId = randomUUID(); diff --git a/server/src/services/heartbeat/run-completion.ts b/server/src/services/heartbeat/run-completion.ts index fb071a79ce3..2a24bbe3006 100644 --- a/server/src/services/heartbeat/run-completion.ts +++ b/server/src/services/heartbeat/run-completion.ts @@ -2,6 +2,7 @@ import { preserveAcceptedRunUsageProjectionSql } from "../usage-receipts.js"; import { isContextCompactionRun } from "../context-compaction.js"; import { providerFailureFromError } from "../../vendor/paperclip-runner/index.js"; import { nativeTaskSessionPublicationHandled } from "../native-runtime/native-task-session-publication.js"; +import { boundOriginalMessage, describeRefusedExactResume, interruptedExactResumeCause } from "../native-runtime/native-exact-resume-failure.js"; import { settledResponsePublicationSql } from "../native-runtime/native-response-publication-receipt.js"; import { notifyChatRunMilestones } from "../chat-run-milestone-notifications.js"; import { measureRunPhase } from "../execution-preparation-timing.js"; @@ -1087,10 +1088,9 @@ export function createHeartbeatRunCompletion(db: Db, dependencies: HeartbeatRunC await processRunCancellationSettlements.get(run.id)?.settled; const providerFailure = providerFailureFromError(err); const currentUserRedactionOptions = await getCurrentUserRedactionOptions(); - const message = redactCurrentUserText( - identityRedactor.redact(err instanceof Error ? err.message : "Unknown adapter failure"), - currentUserRedactionOptions, - ); + const redactFailureText = (text: string) => + redactCurrentUserText(identityRedactor.redact(text), currentUserRedactionOptions); + const thrownMessage = redactFailureText(err instanceof Error ? err.message : "Unknown adapter failure"); const workspaceValidationFailure = isWorkspaceValidationFailure(err) ? err : null; @@ -1107,23 +1107,39 @@ export function createHeartbeatRunCompletion(db: Db, dependencies: HeartbeatRunC // durable coordinator is also the stronger authority here: legacy // runs simply have no row, while native result-less exhaustion keeps // its named failure instead of being flattened to `adapter_failed`. - const nativeTerminalFailureCode = await db + const nativeCoordinator = await db .select({ phase: nativeRunFinalizations.phase, resultId: nativeRunFinalizations.resultId, failureCode: nativeRunFinalizations.failureCode, + attempt: nativeRunFinalizations.attempt, + recoveryHistory: nativeRunFinalizations.recoveryHistory, }) .from(nativeRunFinalizations) .where(eq(nativeRunFinalizations.runId, run.id)) .limit(1) - .then((rows) => { - const coordinator = rows[0]; - return coordinator?.phase === "terminal_failure" && - coordinator.resultId === null - ? coordinator.failureCode - : null; - }) + .then((rows) => rows[0] ?? null) .catch(() => null); + const nativeTerminalFailureCode = + nativeCoordinator?.phase === "terminal_failure" && + nativeCoordinator.resultId === null + ? nativeCoordinator.failureCode + : null; + // A same-run exact-checkpoint retry can fail closed before the executor + // claims a provider attempt, for example when the interrupted attempt left + // its checkpoint unresumable. The refusal alone hides why the run retried, + // so the reported failure names the interrupted attempt first. Failure + // classification reads only the thrown error (here and, through + // `nativeExactResumeRefusal.refusal`, in the retry and recovery + // classifiers). Both texts are masked whole before any length budget cuts + // them, so a cut cannot leave an unmasked username prefix. + const exactResumeCause = interruptedExactResumeCause(nativeCoordinator); + const interruptedExactResume = exactResumeCause + ? { ...exactResumeCause, originalMessage: redactFailureText(exactResumeCause.originalMessage) } + : null; + const message = interruptedExactResume + ? describeRefusedExactResume(interruptedExactResume, thrownMessage) + : thrownMessage; const failureErrorCode = workspaceValidationFailure?.code ?? configurationIncompleteFailure?.code ?? @@ -1168,11 +1184,17 @@ export function createHeartbeatRunCompletion(db: Db, dependencies: HeartbeatRunC finishedAt: new Date(), resultJson: mergeRunStopMetadataForAgent(agent, failureOutcome, { errorCode: failureErrorCode, - errorMessage: message, + errorMessage: thrownMessage, resultJson: { ...parseObject(stopSnapshot?.resultJson), ...(providerFailure ? { providerFailure: { ...providerFailure, message: redactCurrentUserText(identityRedactor.redact(providerFailure.message), currentUserRedactionOptions) } } : {}), + ...(interruptedExactResume ? { nativeExactResumeRefusal: { + originalFailureCode: interruptedExactResume.originalFailureCode, + originalMessage: boundOriginalMessage(interruptedExactResume.originalMessage), + interruptedAttempt: interruptedExactResume.interruptedAttempt, + refusal: thrownMessage, + } } : {}), ...requiredWorkspaceRestoreEvidence, ...(workspaceValidationFailure?.resultJson ?? configurationIncompleteFailure?.resultJson ?? @@ -1216,7 +1238,7 @@ export function createHeartbeatRunCompletion(db: Db, dependencies: HeartbeatRunC wasFirstHeartbeat: timerClaimWasFirstHeartbeat(run), keepIdleOnFailure: Boolean(nonRetryablePreflightFailureCode(err)) || - isWorkspaceSyncConflictFailure(message), + isWorkspaceSyncConflictFailure(thrownMessage), }); await setWakeupStatus(run.wakeupRequestId, "failed", { finishedAt: new Date(), diff --git a/server/src/services/native-runtime/native-exact-resume-failure.test.ts b/server/src/services/native-runtime/native-exact-resume-failure.test.ts new file mode 100644 index 00000000000..50405fe9157 --- /dev/null +++ b/server/src/services/native-runtime/native-exact-resume-failure.test.ts @@ -0,0 +1,135 @@ +import { describe, expect, it } from "vitest"; +import { boundOriginalMessage, describeRefusedExactResume, currentRunFailureText, interruptedExactResumeCause } from "./native-exact-resume-failure.js"; + +const interruption = { + at: "2099-01-01T00:00:00.000Z", + disposition: "retryable_failure", + reason: "native_session_interrupted", + providerAttempt: 1, + stderrTail: "PRP command turn.start failed: classification=session_resume_required", + providerSessionEstablished: true, + checkpointExists: true, +}; +const claimed = { phase: "observed", attempt: 1, resultId: null, recoveryHistory: [interruption] }; + +describe("interruptedExactResumeCause", () => { + it("returns the interrupted attempt that a pending exact-checkpoint resume claim was resuming", () => { + expect(interruptedExactResumeCause(claimed)).toEqual({ + originalFailureCode: "native_session_interrupted", + originalMessage: "PRP command turn.start failed: classification=session_resume_required", + interruptedAttempt: 1, + }); + }); + + it("uses only the latest recovery history entry", () => { + const earlier = { ...interruption, reason: "provider_transport_failed", providerAttempt: 1, stderrTail: "older" }; + expect(interruptedExactResumeCause({ ...claimed, attempt: 2, + recoveryHistory: [earlier, { ...interruption, providerAttempt: 2 }] })?.originalMessage).toBe(interruption.stderrTail); + }); + + it.each([ + ["no coordinator", null], + ["a first attempt without recovery history", { ...claimed, attempt: 0, recoveryHistory: [] }], + ["an executor-claimed later attempt", { ...claimed, attempt: 2 }], + ["a coordinator that is not a pending claim", { ...claimed, phase: "retryable_failure" }], + ["an accepted result", { ...claimed, resultId: "result" }], + ["a bootstrap retry without a checkpoint", { ...claimed, recoveryHistory: [{ ...interruption, checkpointExists: false, providerSessionEstablished: false }] }], + ["an exhausted terminal entry", { ...claimed, recoveryHistory: [{ ...interruption, disposition: "terminal_failure" }] }], + ["malformed history", { ...claimed, recoveryHistory: { reason: "native_session_interrupted" } }], + ])("returns null for %s", (_name, coordinator) => { + expect(interruptedExactResumeCause(coordinator)).toBeNull(); + }); + + it("finds the interruption behind restart-recovery waits for the same attempt", () => { + const blocked = { at: "2099-01-01T00:01:00.000Z", disposition: "blocked", reason: "native_retry_admission_ineligible", providerAttempt: 1 }; + const awaiting = { at: "2099-01-01T00:02:00.000Z", disposition: "awaiting_evidence", reason: "current_controller_preparing", providerAttempt: 1 }; + expect(interruptedExactResumeCause({ ...claimed, recoveryHistory: [interruption, blocked, awaiting] })).toEqual({ + originalFailureCode: "native_session_interrupted", + originalMessage: "PRP command turn.start failed: classification=session_resume_required", + interruptedAttempt: 1, + }); + }); + + it.each([ + ["a wait for a later provider attempt", { disposition: "blocked", reason: "held", providerAttempt: 2 }], + ["a later recovery entry that is not a wait", { disposition: "resume_dead_runner", reason: "restart", providerAttempt: 1 }], + ])("does not reach past %s", (_name, later) => { + expect(interruptedExactResumeCause({ ...claimed, recoveryHistory: [interruption, later] })).toBeNull(); + }); + + it("returns the whole original message so it can be masked before any cut", () => { + const cause = interruptedExactResumeCause({ ...claimed, recoveryHistory: [{ ...interruption, stderrTail: "x".repeat(4_096) }] }); + expect(cause?.originalMessage).toHaveLength(4_096); + expect(boundOriginalMessage(cause!.originalMessage)).toHaveLength(1_500); + const message = describeRefusedExactResume(cause!, "Plugin Runner retained session is not authorized"); + expect(message.length).toBeLessThanOrEqual(2_000); + expect(message).toContain(`native_session_interrupted: ${"x".repeat(1_500)}; exact checkpoint`); + }); +}); + +describe("describeRefusedExactResume", () => { + it("names the original failure before the refusal", () => { + expect(describeRefusedExactResume(interruptedExactResumeCause(claimed)!, "Plugin Runner retained session is not authorized")) + .toBe("native_session_interrupted: PRP command turn.start failed: classification=session_resume_required; " + + "exact checkpoint resume refused: Plugin Runner retained session is not authorized"); + }); + + it("keeps the refusal readable when both messages are long", () => { + const cause = interruptedExactResumeCause({ ...claimed, recoveryHistory: [{ ...interruption, stderrTail: "o".repeat(4_096) }] })!; + const refusal = `Plugin Runner retained session is not authorized: ${"r".repeat(600)}`; + const message = describeRefusedExactResume(cause, refusal); + expect(message).toHaveLength(2_000); + expect(message.startsWith("native_session_interrupted: ooo")).toBe(true); + expect(message.endsWith(`; exact checkpoint resume refused: ${refusal.slice(0, 480)}`)).toBe(true); + }); + + it("keeps a short refusal whole after a maximal original message", () => { + const cause = interruptedExactResumeCause({ ...claimed, recoveryHistory: [{ ...interruption, stderrTail: "o".repeat(4_096) }] })!; + const message = describeRefusedExactResume(cause, "Plugin Runner retained session is not authorized"); + expect(message.length).toBeLessThanOrEqual(2_000); + expect(message.endsWith("; exact checkpoint resume refused: Plugin Runner retained session is not authorized")).toBe(true); + }); + + it("keeps the original failure code when no message was persisted", () => { + expect(describeRefusedExactResume({ originalFailureCode: "native_session_interrupted", originalMessage: "", interruptedAttempt: 1 }, "refused")) + .toBe("native_session_interrupted; exact checkpoint resume refused: refused"); + }); +}); + +describe("currentRunFailureText", () => { + it("classifies a refused exact resume from its refusal, not the chained error", () => { + expect(currentRunFailureText({ + error: "native_session_interrupted: spawn agent ENOENT; exact checkpoint resume refused: retained session is not authorized", + resultJson: { nativeExactResumeRefusal: { refusal: "retained session is not authorized" } }, + })).toBe("retained session is not authorized"); + }); + + it.each([ + ["no result", { error: "spawn agent ENOENT", resultJson: null }], + ["a result without a refusal", { error: "spawn agent ENOENT", resultJson: { errorMessage: "other" } }], + ["a malformed refusal", { error: "spawn agent ENOENT", resultJson: { nativeExactResumeRefusal: { refusal: 7 } } }], + ])("uses the run error for %s", (_name, run) => { + expect(currentRunFailureText(run)).toBe("spawn agent ENOENT"); + }); +}); + +describe("cuts at whole Unicode characters", () => { + const emoji = "\u{1F642}"; + const wellFormed = (text: string) => !/[\ud800-\udbff](?![\udc00-\udfff])|(? { + const bounded = boundOriginalMessage(`${"x".repeat(1_499)}${emoji}tail`); + expect(bounded).toBe("x".repeat(1_499)); + expect(wellFormed(bounded)).toBe(true); + }); + + it("does not split an emoji at the refusal or dynamic original-message cuts", () => { + const message = describeRefusedExactResume( + { originalFailureCode: "native_session_interrupted", originalMessage: `${"o".repeat(1_449)}${emoji}${"o".repeat(200)}`, interruptedAttempt: 1 }, + `${"r".repeat(479)}${emoji}${"r".repeat(100)}`, + ); + expect(wellFormed(message)).toBe(true); + expect(message.endsWith(`; exact checkpoint resume refused: ${"r".repeat(479)}`)).toBe(true); + expect(message.length).toBeLessThanOrEqual(2_000); + }); +}); diff --git a/server/src/services/native-runtime/native-exact-resume-failure.ts b/server/src/services/native-runtime/native-exact-resume-failure.ts new file mode 100644 index 00000000000..21c150d416c --- /dev/null +++ b/server/src/services/native-runtime/native-exact-resume-failure.ts @@ -0,0 +1,113 @@ +/** + * The interrupted provider attempt that a same-run exact-checkpoint retry was + * resuming when the retry failed before it took its own provider claim. + */ +export type InterruptedExactResume = { + originalFailureCode: string; + originalMessage: string; + interruptedAttempt: number; +}; + +/** Bounds the original message in the chained message and in the run result. */ +const ORIGINAL_MESSAGE_MAX_CHARS = 1_500; +/** The coordinator failure detail keeps at most this many characters. */ +const FAILURE_DETAIL_MAX_CHARS = 2_000; +/** Leaves the refusal readable however long the original message is. */ +const REFUSAL_MAX_CHARS = 480; +const REFUSAL_SEPARATOR = "; exact checkpoint resume refused: "; +/** Restart-recovery waits that keep the interrupted provider attempt. */ +const RECOVERY_WAIT_DISPOSITIONS: ReadonlySet = new Set(["blocked", "awaiting_evidence"]); + +/** + * Cuts to at most `max` UTF-16 code units without splitting a surrogate pair. + * A lone surrogate is invalid Unicode, and PostgreSQL `jsonb` rejects it, so + * a split emoji would make the failure write itself fail. + */ +function cutWholeCharacters(text: string, max: number): string { + if (text.length <= max) return text; + const last = max > 0 ? text.charCodeAt(max - 1) : 0; + return text.slice(0, last >= 0xd800 && last <= 0xdbff ? max - 1 : Math.max(0, max)); +} + +function record(value: unknown): Record { + return value && typeof value === "object" && !Array.isArray(value) + ? (value as Record) + : {}; +} + +/** + * A same-run resume claim clears the coordinator failure fields, so the + * interrupted attempt survives only in its recovery history entry. That entry + * explains the retry only while the claim is still `observed` and no later + * provider attempt was claimed: the executor increments `attempt` when it + * claims, and it records its own failures for that attempt. A retryable entry + * with a checkpoint was an exact-checkpoint resume, because a bootstrap retry + * has no checkpoint and an ambiguous state is never retryable. Restart + * recovery can record waits for the same attempt after that entry (for + * example a held remote retry); those are skipped. Any other entry, or any + * entry for a later provider attempt, ends the search without a cause. + */ +export function interruptedExactResumeCause(coordinator: { + phase: string; + attempt: number; + resultId: string | null; + recoveryHistory: unknown; +} | null | undefined): InterruptedExactResume | null { + if (!coordinator || coordinator.phase !== "observed" || coordinator.resultId !== null || coordinator.attempt < 1) return null; + const history = Array.isArray(coordinator.recoveryHistory) ? coordinator.recoveryHistory : []; + let entry: Record = {}; + for (let index = history.length - 1; index >= 0; index -= 1) { + entry = record(history[index]); + if (!RECOVERY_WAIT_DISPOSITIONS.has(entry.disposition) || entry.providerAttempt !== coordinator.attempt) break; + } + if ( + entry.disposition !== "retryable_failure" || + entry.providerAttempt !== coordinator.attempt || + entry.checkpointExists !== true || + entry.providerSessionEstablished !== true || + typeof entry.reason !== "string" || !entry.reason + ) return null; + // The executor removed credentials and bounded this tail before it + // persisted the entry. It is returned whole so the caller can mask + // usernames before any length budget cuts it. + const message = typeof entry.stderrTail === "string" ? entry.stderrTail.trim() : ""; + return { + originalFailureCode: entry.reason, + originalMessage: message, + interruptedAttempt: coordinator.attempt, + }; +} + +/** The original message as the run result keeps it. Mask it before calling this. */ +export function boundOriginalMessage(message: string): string { + return cutWholeCharacters(message, ORIGINAL_MESSAGE_MAX_CHARS); +} + +/** + * The run's current failure text. A refused exact resume reports the + * interrupted attempt in `error` for operators in company-scoped run records, + * but retry and recovery decisions and Sentry failure reports must use only + * the current refusal, which the run result keeps separately. The earlier + * attempt's provider text stays out of Sentry. + */ +export function currentRunFailureText(run: { error?: string | null; resultJson?: unknown } | null | undefined): string | null { + const refusal = record(record(run?.resultJson).nativeExactResumeRefusal).refusal; + return typeof refusal === "string" ? refusal : run?.error ?? null; +} + +/** + * Names the interrupted attempt first, then why its exact checkpoint could not + * resume. The refusal keeps its own budget, and the original message is cut to + * the room left, so the whole message fits the failure-detail bound. Both + * texts must already be masked, because a cut can split a username. + */ +export function describeRefusedExactResume(cause: InterruptedExactResume, refusal: string): string { + const refused = `${REFUSAL_SEPARATOR}${cutWholeCharacters(refusal, REFUSAL_MAX_CHARS)}`; + const originalBudget = Math.max(0, FAILURE_DETAIL_MAX_CHARS - refused.length); + const code = cutWholeCharacters(cause.originalFailureCode, originalBudget); + const messageBudget = originalBudget - code.length - 2; + const original = cause.originalMessage && messageBudget > 0 + ? `${code}: ${cutWholeCharacters(cause.originalMessage, Math.min(ORIGINAL_MESSAGE_MAX_CHARS, messageBudget))}` + : code; + return `${original}${refused}`; +} diff --git a/server/src/services/recovery/provider-failure-classification.test.ts b/server/src/services/recovery/provider-failure-classification.test.ts index 29dded8d4d6..6c3b94e147f 100644 --- a/server/src/services/recovery/provider-failure-classification.test.ts +++ b/server/src/services/recovery/provider-failure-classification.test.ts @@ -45,6 +45,23 @@ describe("classifyAdapterFailureForRecovery", () => { expect(classifyContinuationFailure(run as never).kind).toBe("default"); }); + it.each([ + ["a provider quota", "model is at capacity", { kind: "provider_quota" }], + ["a configuration blocker", "missing credentials", { kind: "configuration_incomplete" }], + ])("classifies a refused exact resume from its refusal, not an earlier %s", (_name, earlier, own) => { + const refusal = "Plugin Runner retained session is not authorized"; + const refused = { + errorCode: "adapter_failed", + error: `native_session_interrupted: ${earlier}; exact checkpoint resume refused: ${refusal}`, + resultJson: { nativeExactResumeRefusal: { originalFailureCode: "native_session_interrupted", + originalMessage: earlier, interruptedAttempt: 1, refusal } }, + }; + expect(classifyAdapterFailureForRecovery(refused)).toBeNull(); + // The same text as the run's own failure still chooses that recovery. + expect(classifyAdapterFailureForRecovery({ errorCode: "adapter_failed", error: earlier, resultJson: null })) + .toMatchObject(own); + }); + it("uses a typed ACP quota reset without needing the provider's original message", () => { const now = new Date("2026-07-15T20:00:00.000Z"); expect(classifyAdapterFailureForRecovery({ diff --git a/server/src/services/recovery/service.ts b/server/src/services/recovery/service.ts index b84ca31b738..30f3f03b832 100644 --- a/server/src/services/recovery/service.ts +++ b/server/src/services/recovery/service.ts @@ -176,6 +176,7 @@ import { isStrandedIssueRecoveryOriginKind, } from "./origins.js"; import { withRecoveryContext } from "./status-only-context.js"; +import { currentRunFailureText } from "../native-runtime/native-exact-resume-failure.js"; import { isAutomaticRecoverySuppressedByPauseHold } from "./pause-hold-guard.js"; import { collectDispositionRepairSourceState, @@ -433,7 +434,7 @@ function isProviderQuotaRecovery(latestRun: LatestIssueRun) { if (readRecoveryRunErrorFamily(latestRun) === "provider_quota") return true; if (latestRun?.errorCode !== "adapter_failed") return false; return /(?:usage|rate|quota) limit|you(?:'|’)ve hit your (?:\w+ )?limit|quota (?:exceeded|reset)|try again after/i.test( - latestRun.error ?? "", + currentRunFailureText(latestRun) ?? "", ); } @@ -625,10 +626,13 @@ export function classifyAdapterFailureForRecovery( return null; } const resultJson = parseObject(latestRun.resultJson); + // A refused exact resume keeps its interrupted attempt for operators in + // `error` and `nativeExactResumeRefusal`. Recovery follows the refusal only. + const { nativeExactResumeRefusal: _interruptedAttempt, ...currentResult } = resultJson; const error = [ latestRun.errorCode ?? "", - latestRun.error ?? "", - JSON.stringify(resultJson), + currentRunFailureText(latestRun) ?? "", + JSON.stringify(currentResult), ].join("\n"); if ( latestRun.errorCode === "configuration_incomplete" || diff --git a/server/src/services/run-failure-report.ts b/server/src/services/run-failure-report.ts index 0d5dd0bd487..b25e97ead98 100644 --- a/server/src/services/run-failure-report.ts +++ b/server/src/services/run-failure-report.ts @@ -1,3 +1,4 @@ +import { currentRunFailureText } from "./native-runtime/native-exact-resume-failure.js"; import { and, eq, gte, sql } from "drizzle-orm"; import { agents, dotRunnerAssignments, grokBotDispatches, heartbeatRuns, nativeRunFinalizations, type Db } from "@paperclipai/db"; import { captureRunFailure, type RunFailureStatus } from "../sentry.js"; @@ -369,7 +370,9 @@ async function captureTerminalRunFailure( ): Promise { try { const snapshot = redactRunFailureSecretValues({ - errorMessage: run.error ?? "", + // A refused exact resume keeps the interrupted attempt's provider text + // in `error` for operators only; Sentry gets the current refusal. + errorMessage: currentRunFailureText(run) ?? "", errorCode: run.errorCode ?? null, diagnostics: collectRunFailureDiagnostics(run, options), }, [...new Set([