From 5e8956c207b098179a9d9cdc9e97d6cb6cd5805c Mon Sep 17 00:00:00 2001 From: Devin Foley Date: Wed, 14 Oct 2026 18:27:11 -0700 Subject: [PATCH] fix(heartbeat): retry legacy runs a restart stopped before dispatch (#16355) A hard server restart can stop a legacy run after it is claimed but before the adapter is dispatched. The next boot reaped it as failed/process_lost with no retry and held it for operator reconciliation, so the task wake was lost. The legacy controller only writes executionStage "dispatching" in the lease renewal that admits the adapter. The orphan reaper now revokes the expired foreign-boot controller first, and uses the stage and process identifiers returned by that same UPDATE ... RETURNING. If the run is still "preparing" with no process identifiers, it records bootstrap evidence (providerWorkStarted: false) and uses the existing one-time process-loss retry. In "unexpected" mode, run-failure reporting does not send this retried restart interruption to Sentry. Runs that reached dispatching, native runs, and runs owned by the current boot are unchanged. Verified exact head 91f1352097d6a60b170a97a9f98e3330773e452a: full CI green, Greptile 5/5, no unresolved review threads, no conflicts. The tests were not run locally (sandbox memory limit); CI is the test run. Co-Authored-By: Claude Opus 5.5 --- .../heartbeat-process-recovery.test.ts | 66 +++++++++++++++++++ .../__tests__/run-failure-report.test.ts | 46 +++++++++++++ server/src/services/heartbeat/recovery.ts | 27 +++++++- .../services/legacy-controller-lease.test.ts | 13 +++- .../src/services/legacy-controller-lease.ts | 28 ++++++-- server/src/services/run-failure-report.ts | 20 +++++- 6 files changed, 190 insertions(+), 10 deletions(-) diff --git a/server/src/__tests__/heartbeat-process-recovery.test.ts b/server/src/__tests__/heartbeat-process-recovery.test.ts index ea30fdea2c4..46c9e3de558 100644 --- a/server/src/__tests__/heartbeat-process-recovery.test.ts +++ b/server/src/__tests__/heartbeat-process-recovery.test.ts @@ -3250,6 +3250,72 @@ describeEmbeddedPostgres("heartbeat orphaned process recovery", () => { expect(retries).toHaveLength(0); }); + // A hard restart can kill the server after it claimed a legacy run but before + // the adapter dispatch renewal, leaving an expired lease from another boot. + async function seedRestartOrphanedLegacySetup(executionStage: "preparing" | "dispatching") { + const fixture = await seedRunFixture({ + adapterType: "paperclip_runner", + agentStatus: "idle", + runtimeMode: "legacy", + }); + await db.update(heartbeatRuns).set({ + controllerBootId: randomUUID(), + controllerLeaseExpiresAt: sql`clock_timestamp() - interval '1 second'`, + executionStage, + }).where(eq(heartbeatRuns.id, fixture.runId)); + return fixture; + } + + it("retries a legacy run that a restart stopped before adapter dispatch", async () => { + const { companyId, runId, issueId } = await seedRestartOrphanedLegacySetup("preparing"); + + const heartbeat = heartbeatService(db); + const result = await heartbeat.reapOrphanedRuns(); + + expect(result).toEqual({ reaped: 1, runIds: [runId] }); + const [reaped] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, runId)); + expect(reaped).toMatchObject({ + status: "failed", + errorCode: "process_lost", + error: "Process lost -- server may have restarted; retrying once", + }); + expect(reaped?.resultJson).toMatchObject({ + executionRecovery: { kind: "bootstrap", providerWorkStarted: false }, + processLossDiagnostic: { localCheck: "no_identifiers", retryEligible: true, runPredatesObserver: true }, + }); + const retries = await db.select().from(heartbeatRuns).where(and( + eq(heartbeatRuns.companyId, companyId), + eq(heartbeatRuns.retryOfRunId, runId), + )); + expect(retries).toEqual([expect.objectContaining({ status: "scheduled_retry" })]); + expect(await db.select().from(issueRecoveryActions) + .where(eq(issueRecoveryActions.sourceIssueId, issueId))).toEqual([]); + expect(mockAdapterExecute).not.toHaveBeenCalled(); + }); + + it("keeps an orphaned legacy run that reached adapter dispatch held for reconciliation", async () => { + const { companyId, runId, issueId } = await seedRestartOrphanedLegacySetup("dispatching"); + + const heartbeat = heartbeatService(db); + await heartbeat.reapOrphanedRuns(); + + const [reaped] = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, runId)); + expect(reaped).toMatchObject({ + status: "failed", + errorCode: "process_lost", + error: "Process lost -- server may have restarted", + }); + expect(reaped?.resultJson).not.toHaveProperty("executionRecovery"); + expect(await db.select().from(heartbeatRuns).where(and( + eq(heartbeatRuns.companyId, companyId), + eq(heartbeatRuns.retryOfRunId, runId), + ))).toEqual([]); + expect(await db.select().from(issueRecoveryActions) + .where(eq(issueRecoveryActions.sourceIssueId, issueId))).toEqual([ + expect.objectContaining({ cause: "legacy_execution_requires_reconciliation" }), + ]); + }); + async function withTempPaperclipHome( fn: (home: string) => Promise, ): Promise { diff --git a/server/src/services/__tests__/run-failure-report.test.ts b/server/src/services/__tests__/run-failure-report.test.ts index 0914b1a2e3d..038f2b6fd32 100644 --- a/server/src/services/__tests__/run-failure-report.test.ts +++ b/server/src/services/__tests__/run-failure-report.test.ts @@ -393,6 +393,52 @@ describeEmbeddedPostgres("reportRunFailure", () => { expect(mockCaptureRunFailure).toHaveBeenCalledOnce(); }); + function restartInterruptedSetupRun(overrides: Partial = {}) { + return buildRun({ + error: "Process lost -- server may have restarted; retrying once", + runtimeMode: "legacy", executionStage: "preparing", processPid: null, processGroupId: null, + resultJson: { + executionRecovery: { kind: "bootstrap", providerWorkStarted: false }, + processLossDiagnostic: { + pidRecorded: false, groupRecorded: false, localCheck: "no_identifiers", + retryEligible: true, runPredatesObserver: true, + }, + }, + ...overrides, + }); + } + + it("keeps a retried restart interruption of legacy setup local", async () => { + await seedCompanyAndAgent({ adapterType: "paperclip_runner" }); + await reportRunFailure(db, restartInterruptedSetupRun()); + expect(mockCaptureRunFailure).not.toHaveBeenCalled(); + }); + + it("reports a retried restart interruption of legacy setup in all mode", async () => { + vi.stubEnv("PAPERCLIP_SENTRY_RUN_FAILURES", "all"); + await seedCompanyAndAgent({ adapterType: "paperclip_runner" }); + await reportRunFailure(db, restartInterruptedSetupRun()); + expect(mockCaptureRunFailure).toHaveBeenCalledOnce(); + }); + + it.each([ + { executionStage: "dispatching" }, { runtimeMode: "native" }, { processPid: 4242 }, + { errorCode: "adapter_failed" }, + { resultJson: { processLossDiagnostic: { localCheck: "no_identifiers", retryEligible: true, runPredatesObserver: true } } }, + { resultJson: { + executionRecovery: { kind: "bootstrap", providerWorkStarted: false }, + processLossDiagnostic: { localCheck: "no_identifiers", retryEligible: false, runPredatesObserver: true }, + } }, + { resultJson: { + executionRecovery: { kind: "bootstrap", providerWorkStarted: false }, + processLossDiagnostic: { localCheck: "no_identifiers", retryEligible: true, runPredatesObserver: false }, + } }, + ])("reports process loss without restart-before-dispatch evidence: %j", async (overrides) => { + await seedCompanyAndAgent({ adapterType: "paperclip_runner" }); + await reportRunFailure(db, restartInterruptedSetupRun(overrides)); + expect(mockCaptureRunFailure).toHaveBeenCalledOnce(); + }); + async function expiredGrokOffer(input: { wakes: Array<{ status: "rejected" | "accepted" | "acknowledged" | "unknown"; httpStatus: number | null }>; acceptedAt?: Date | null; diff --git a/server/src/services/heartbeat/recovery.ts b/server/src/services/heartbeat/recovery.ts index 4a6db618b5a..27ac5659e84 100644 --- a/server/src/services/heartbeat/recovery.ts +++ b/server/src/services/heartbeat/recovery.ts @@ -9,7 +9,7 @@ import { recordNativeLocalProcessStop } from "../native-local-process-stop.js"; import { legacyControllerBootId, hasLiveLegacyController, - revokeExpiredLegacyController, + revokeExpiredLegacyControllerWithState, } from "../legacy-controller-lease.js"; import { remoteTerminationReceipt } from "../remote-execution-termination.js"; import { runUsedConversationAdapter } from "../conversation-continuation.js"; @@ -2314,12 +2314,27 @@ export function createHeartbeatRecovery(db: Db, dependencies: HeartbeatRecoveryD readNonEmptyString(runContext.wakeReason) === "issue_monitor_due" && monitorNextCheckAt !== undefined && (!monitorNextCheckAt || monitorNextCheckAt.getTime() <= now.getTime()); + const revokedState = await revokeExpiredLegacyControllerWithState(db, run); + if (!revokedState) continue; + // A legacy controller persists "dispatching" in the same lease renewal + // that admits the adapter. An expired lease from another boot that is + // still "preparing" proves a restart stopped setup before provider work. + // Use the state committed with the revocation, not the earlier snapshot: + // the old controller may have dispatched before its lease expired. + // The revocation matched the snapshot's boot ID before replacing it. + const restartInterruptedBeforeDispatch = + run.runtimeMode === "legacy" && + revokedState.executionStage === "preparing" && + !!run.controllerBootId && + run.controllerBootId !== legacyControllerBootId && + !revokedState.processPid && + !revokedState.processGroupId; const shouldRetry = (run.processLossRetryCount ?? 0) < 1 && ((tracksLegacyLocalChild && (!!run.processPid || !!run.processGroupId)) || + restartInterruptedBeforeDispatch || monitorDispatchLostWithoutFutureWake); - if (!(await revokeExpiredLegacyController(db, run))) continue; const baseMessage = buildProcessLossMessage(run); const processLossDiagnostic = buildProcessLossDiagnostic({ run, @@ -2344,7 +2359,13 @@ export function createHeartbeatRecovery(db: Db, dependencies: HeartbeatRecoveryD "failed", { conversationContinuationEligible, - resultJson: { ...parseObject(run.resultJson), processLossDiagnostic }, + resultJson: { + ...parseObject(run.resultJson), + processLossDiagnostic, + ...(restartInterruptedBeforeDispatch + ? { executionRecovery: { kind: "bootstrap", providerWorkStarted: false } } + : {}), + }, errorCode: "process_lost", errorMessage: shouldRetry ? `${baseMessage}; retrying once` diff --git a/server/src/services/legacy-controller-lease.test.ts b/server/src/services/legacy-controller-lease.test.ts index d2e4b2e2c40..2280f70dd0e 100644 --- a/server/src/services/legacy-controller-lease.test.ts +++ b/server/src/services/legacy-controller-lease.test.ts @@ -5,7 +5,8 @@ import { agents, companies, createDb, heartbeatRuns } from "@paperclipai/db"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "../__tests__/helpers/embedded-postgres.js"; import { heartbeatService } from "./heartbeat.js"; import { hasLiveLegacyController, LEGACY_CONTROLLER_RENEW_MS, legacyControllerBootId, legacyControllerClaim, LegacyControllerLeaseLostError, - renewLegacyControllerLease, revokeExpiredLegacyController, watchLegacyControllerLease } from "./legacy-controller-lease.js"; + renewLegacyControllerLease, revokeExpiredLegacyController, revokeExpiredLegacyControllerWithState, + watchLegacyControllerLease } from "./legacy-controller-lease.js"; const support = await getEmbeddedPostgresTestSupport(); (support.supported ? describe : describe.skip)("durable legacy controller ownership", () => { @@ -79,6 +80,16 @@ const support = await getEmbeddedPostgresTestSupport(); expect(attempts.filter(Boolean)).toHaveLength(1); expect(await renewLegacyControllerLease(db, run)).toBe(false); }); + it("revocation reports the committed dispatch boundary instead of the caller's stale snapshot", async () => { + const stale = await seed(); + expect(await renewLegacyControllerLease(db, stale, "dispatching")).toBe(true); + await expire(stale.id); + expect(stale.executionStage).toBe("preparing"); + expect(await revokeExpiredLegacyControllerWithState(db, stale)).toEqual({ + executionStage: "dispatching", processPid: null, processGroupId: null, + }); + expect(await revokeExpiredLegacyControllerWithState(db, stale)).toBeNull(); + }); it("a crash after revocation permits a later recovery claim", async () => { const run = await seed(); await expire(run.id); diff --git a/server/src/services/legacy-controller-lease.ts b/server/src/services/legacy-controller-lease.ts index f8ec824002c..e13e2ee2308 100644 --- a/server/src/services/legacy-controller-lease.ts +++ b/server/src/services/legacy-controller-lease.ts @@ -55,10 +55,20 @@ export async function hasLiveLegacyController(db: Db, run: Run): Promise; + /** Atomically revoke an expired controller. Renewal and revocation serialize on - * the run row. Expiry permits cleanup, never dispatch of a replacement agent. */ -export async function revokeExpiredLegacyController(db: Db, run: Run): Promise { - if (run.runtimeMode === "native" || !run.controllerBootId) return true; + * the run row. Expiry permits cleanup, never dispatch of a replacement agent. + * Returns the stage and process identifiers committed with the revocation, or + * null when another writer owns the row. They cannot advance afterwards, + * because renewal requires the replaced boot ID. */ +export async function revokeExpiredLegacyControllerWithState( + db: Db, + run: Run, +): Promise { + if (run.runtimeMode === "native" || !run.controllerBootId) { + return { executionStage: run.executionStage, processPid: run.processPid, processGroupId: run.processGroupId }; + } const [revoked] = await db.update(heartbeatRuns).set({ controllerBootId: randomUUID(), controllerLeaseExpiresAt: sql`clock_timestamp() + interval '60 seconds'`, @@ -67,8 +77,16 @@ export async function revokeExpiredLegacyController(db: Db, run: Run): Promise { + return (await revokeExpiredLegacyControllerWithState(db, run)) !== null; } /** Abort the adapter if the controller cannot renew. Bound each check by the diff --git a/server/src/services/run-failure-report.ts b/server/src/services/run-failure-report.ts index abf0152adf3..0fe6b277688 100644 --- a/server/src/services/run-failure-report.ts +++ b/server/src/services/run-failure-report.ts @@ -166,6 +166,23 @@ function isHermesConnectionFailure(run: HeartbeatRun, options: RunFailureReportO (connection.reason === "remote_unavailable" && code === "hermes_gateway_upstream_error"); } +/** + * The orphan reaper proved a server restart stopped legacy setup before + * dispatch and made the run eligible for its bounded retry. Only that reaper + * branch pairs process loss with bootstrap evidence. + */ +function isRestartInterruptedSetup(run: HeartbeatRun): boolean { + if ( + run.status !== "failed" || run.errorCode !== "process_lost" || run.runtimeMode !== "legacy" || + run.executionStage !== "preparing" || run.processPid != null || run.processGroupId != null + ) return false; + const recovery = asRecord(run.resultJson?.executionRecovery); + const processLoss = asRecord(run.resultJson?.processLossDiagnostic); + return recovery?.kind === "bootstrap" && recovery.providerWorkStarted === false && + processLoss?.retryEligible === true && processLoss.runPredatesObserver === true && + processLoss.localCheck === "no_identifiers"; +} + /** * The adapter proved the user's provider account is out of quota, and recovery * waits for its reset. Both fields come from the adapter's own classifier. @@ -218,7 +235,8 @@ export function reportRunFailure(db: Db, run: HeartbeatRun, options: RunFailureR isAiConnectionSelectionBlocker(run, options) || isLocalPathWorkspaceConfigurationBlocker(run, options) || isGitConnectionFailure(run, options) || - isProviderQuotaFailure(run, options) + isProviderQuotaFailure(run, options) || + isRestartInterruptedSetup(run) )) return Promise.resolve(); const runStatus = run.status; const report = captureTerminalRunFailure(db, run, runStatus, options, mode);