From 876a2e4857b416cd64a7767135dbf75b4a365d4d Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Fri, 6 Nov 2026 15:17:58 -0600 Subject: [PATCH] fix(recovery): recover a prior boot's unstarted run at lease expiry (#19578) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - After a server restart, a task must continue automatically and promptly when that is safe > - A user clicks Retry, and the server is killed before the new run starts a process > - Recovery leaves that run `running` until the orphan reap's five-minute stale-age threshold passes > - The user sees nothing happen for about five minutes > - This pull request recovers that run when its controller lease from the earlier boot expires > - The benefit is that the automatic retry starts about one lease period after the kill, not five minutes later ## Linked Issues or Issue Description **What happened?** A Retry admitted a legacy run. The server was killed before the run recorded a process. The run kept a controller lease from the killed boot and `executionStage: preparing`. After the restart, live recovery skipped the run until `updatedAt` was five minutes old (`server/src/services/heartbeat/recovery.ts`, `staleThresholdMs ?? 5 * 60_000`). Restart-chaos measured 5 m 01 s from run creation to `process_lost` and the automatic retry, twice (4 m 20 s after the server was ready). **Expected behavior** Recovery should claim the run as soon as the earlier boot's lease expires. The lease is the only liveness proof for a legacy controller, and no process was ever recorded. **Paperclip version or commit** `master` at `71313207eb`. **Steps to reproduce** Click Retry on an interrupted task, then SIGKILL the server within about one second. Observe the retried run stay `running` for about five minutes. ## What Changed - `recoverActiveExecutions` skips the stale-age gate for a legacy `running` run when all of these are true: its controller lease is expired (checked by the existing live-lease gate), the lease belongs to an earlier boot (`controllerBootId !== legacyControllerBootId`), the run is still `preparing` (no adapter dispatch), and the run has no recorded `processPid` or `processGroupId`. - The stage and process fields committed with the revocation are checked again. If the old controller dispatched before its lease expired, the run keeps the age guard. - The existing revocation (`revokeExpiredLegacyControllerWithState`) still requires the expired boot ID, so a concurrent renewal wins. The existing `restartInterruptedBeforeDispatch` rule still decides the single process-loss retry. - `doc/execution-semantics.md` describes the rule in section 10. - Two regressions in `server/src/__tests__/live-recovery-work.test.ts` (embedded Postgres, real residual-recovery workers). ## Verification - Red before the fix: `recovers a fresh run from a prior boot at lease expiry ...` failed with `expected 'running' to be 'failed'`. - Green after the fix: `pnpm exec vitest run src/__tests__/live-recovery-work.test.ts -t "stale-age|fresh foreign controller|suppressed live runs"` passes 4/4. The run fails `process_lost` with `executionRecovery.providerWorkStarted: false` within seconds of lease expiry, and exactly one retry runs to `succeeded`. - Race case: a DB trigger makes the row committed with the revocation say `dispatching` while the scan saw `preparing`. The run stays `running`, and no retry is created. - Guard cases: a run with an expired lease of the current boot, a run from an earlier boot with a recorded process, and a run from an earlier boot that was `dispatching` (for example a remote HTTP adapter) all stay `running` after four minutes. - Related suites: `heartbeat-process-recovery`, `heartbeat-observed-workspace-preservation`, `native-startup-cleanup-recovery`, `services/heartbeat/recovery.test.ts`, full `live-recovery-work`. - Live K8 probe (restart-chaos supervisor, local instance, ACPX Claude agent): the first run fails with a provider error, the probe clicks Retry, and the server is SIGKILLed 100 ms later, before the Retry run records a process. The probe then measures how long the Retry run stays `running`. | Build | Retry run created to `process_lost` | Server ready to `process_lost` | Automatic retry run | | --- | --- | --- | --- | | Base (`71313207eb`) | 300.1 s | 293.5 s | started at 5 m 00 s | | This PR | 60.1 s | 54.5 s | started 0.1 s after `process_lost` | The claim now happens when the killed boot's 60-second controller lease expires. In this probe the restart took about 6 s, so the claim came about 54 s after ready. In the restart-chaos waves, kill to ready took about 41 s, so the claim would come about 20 s after ready. - A chaos wave with the `retry` trigger (`w-20261106T195715-s2727`, branch #19513 merged locally) missed the trigger: no Retry was offered because recovery completed the task automatically (claude t01 PASS). The probe above makes the Retry-then-kill timing deterministic. ## Risks - Low risk. The change only removes an age wait. Ownership is still proved by the expired lease of another boot. A rolling deploy or hot restart whose earlier instance is still alive keeps renewing its lease, so the run is not touched. - Runs with a recorded process, and dispatched runs, keep the five-minute guard. A process on another host or a remote request is not inferred dead. - Native runs are not changed. Their ownership is in `native_run_finalizations` and startup native recovery. > For core feature work, check [`ROADMAP.md`](ROADMAP.md) first and discuss it in `#dev` before opening the PR. Feature PRs that overlap with planned core work may need to be redirected — check the roadmap first. See `CONTRIBUTING.md`. ## Model Used - Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, via Claude Code with tool use (shell, file edits, test execution). Extended reasoning enabled. ## Checklist - [x] I have included a thinking path that traces from project context to this change - [x] I have specified the model used (with version and capability details) - [x] I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work - [x] I have searched GitHub for duplicate or related PRs and linked them above - [x] I have either (a) linked existing issues with `Fixes: #` / `Closes #` / `Refs #` OR (b) described the issue in-PR following the relevant issue template - [x] I have not referenced internal/instance-local Paperclip issues or links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip` URLs) - [x] My branch name describes the change (e.g. `docs/...`, `fix/...`) and contains no internal Paperclip ticket id or instance-derived details - [x] I have run tests locally and they pass - [x] I have added or updated tests where applicable - [x] I have updated relevant documentation to reflect my changes - [x] I have considered and documented any risks above - [x] All Paperclip CI gates are green - [x] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5.5 --- doc/execution-semantics.md | 8 +++ .../src/__tests__/live-recovery-work.test.ts | 60 +++++++++++++++++++ server/src/services/heartbeat/recovery.ts | 26 +++++++- 3 files changed, 93 insertions(+), 1 deletion(-) diff --git a/doc/execution-semantics.md b/doc/execution-semantics.md index e5451eb7ace..61af30f3920 100644 --- a/doc/execution-semantics.md +++ b/doc/execution-semantics.md @@ -1647,6 +1647,14 @@ On startup and on the periodic recovery loop, Paperclip performs the following r 3. reconcile stranded assigned work 4. scan silent active runs only for source-aware terminal folding and legacy cleanup; API reads classify ordinary output silence for the board UI +The orphan reap normally waits until a `running` run has been unchanged for five +minutes. A legacy run whose controller lease belongs to an earlier server boot +and has expired, which was still preparing (before adapter dispatch), and which +has no recorded process is recovered when that lease expires instead. The +expired lease proves that the earlier owner is gone, and no provider work +started. A live lease, a lease of the current boot, a dispatched adapter, or a +recorded process keeps the five-minute guard. + The stranded-work pass closes the gap where issue state survives a crash but the wake/run path does not. The silent-run scan covers the separate case where a live process exists but has stopped producing observable output. Native finalization reconciliation (part of native recovery and the orphan diff --git a/server/src/__tests__/live-recovery-work.test.ts b/server/src/__tests__/live-recovery-work.test.ts index 1adb2d01bfb..3c774a05dda 100644 --- a/server/src/__tests__/live-recovery-work.test.ts +++ b/server/src/__tests__/live-recovery-work.test.ts @@ -301,6 +301,66 @@ describe("residual recovery production matrix", () => { }, { timeout: 45_000 }); await competing.stop(); extraStops.pop(); await quiet(); }); + it("recovers a fresh run from a prior boot at lease expiry instead of waiting for the stale-age threshold", async () => { + // RC-27: a Retry admitted just before a kill records a controller lease but + // no process. The prior boot's expired lease is the ownership proof. + const f = await fixture(), expiry = new Date(Date.now() + 3_000); + const [run] = await db.insert(heartbeatRuns).values({ companyId: f.companyId, agentId: f.agent.id, status: "running", + runtimeMode: "legacy", responsibleUserId: f.actorId, controllerBootId: randomUUID(), controllerLeaseExpiresAt: expiry, + executionStage: "preparing", updatedAt: new Date(), startedAt: new Date() }).returning(); + await start(true); + expect((await getRun(run.id)).status).toBe("running"); + await vi.waitFor(async () => expect((await getRun(run.id)).status).toBe("failed"), { timeout: 15_000 }); + expect(Date.now() - expiry.getTime()).toBeLessThan(15_000); + expect(await getRun(run.id)).toMatchObject({ errorCode: "process_lost", + resultJson: expect.objectContaining({ executionRecovery: { kind: "bootstrap", providerWorkStarted: false } }) }); + await vi.waitFor(async () => { + const retries = await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.retryOfRunId, run.id)); + expect(retries).toHaveLength(1); + await heartbeat.drainActiveRunExecutions(); + expect((await getRun(retries[0].id)).status).toBe("succeeded"); + }, { timeout: 45_000 }); + await quiet(); + }); + it("keeps the age guard when the prior boot dispatched between the scan and the revocation", async () => { + // Stage the race: the scanned row says `preparing`, and the row committed + // with the revocation says `dispatching` (the old controller's last renewal). + const f = await fixture(), expiry = new Date(Date.now() + 2_000); + const [run] = await db.insert(heartbeatRuns).values({ companyId: f.companyId, agentId: f.agent.id, status: "running", + runtimeMode: "legacy", responsibleUserId: f.actorId, controllerBootId: randomUUID(), controllerLeaseExpiresAt: expiry, + executionStage: "preparing", updatedAt: new Date(), startedAt: new Date() }).returning(); + await db.execute(sql.raw(`create or replace function rc27_dispatch_on_revoke() returns trigger language plpgsql as $$ + begin if new.id = '${run.id}' and new.controller_boot_id is distinct from old.controller_boot_id + then new.execution_stage := 'dispatching'; end if; return new; end $$`)); + await db.execute(sql`create trigger rc27_dispatch_on_revoke before update on heartbeat_runs + for each row execute function rc27_dispatch_on_revoke()`); + extraStops.push(async () => { + await db.execute(sql`drop trigger if exists rc27_dispatch_on_revoke on heartbeat_runs`); + await db.execute(sql`drop function if exists rc27_dispatch_on_revoke()`); + }); + await start(true); + await vi.waitFor(async () => expect((await getRun(run.id)).controllerBootId).not.toBe(run.controllerBootId), { timeout: 15_000 }); + await realDelay(5_000); await Promise.allSettled([...passes]); + expect(await getRun(run.id)).toMatchObject({ status: "running", executionStage: "dispatching", errorCode: null }); + expect(await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.retryOfRunId, run.id))).toEqual([]); + }); + it("keeps the stale-age guard for this boot, a recorded process, or a dispatched adapter", async () => { + const f = await fixture(), now = Date.now(), expired = new Date(now - 1_000); + const [sameBoot] = await db.insert(heartbeatRuns).values({ companyId: f.companyId, agentId: f.agent.id, status: "running", + runtimeMode: "legacy", responsibleUserId: f.actorId, controllerBootId: legacyControllerBootId, controllerLeaseExpiresAt: expired, + executionStage: "preparing", updatedAt: new Date(now), startedAt: new Date(now) }).returning(); + const [withProcess] = await db.insert(heartbeatRuns).values({ companyId: f.companyId, agentId: f.agent.id, status: "running", + runtimeMode: "legacy", responsibleUserId: f.actorId, controllerBootId: randomUUID(), controllerLeaseExpiresAt: expired, + executionStage: "dispatching", processPid: 2 ** 22 + 17, updatedAt: new Date(now), startedAt: new Date(now) }).returning(); + // A dispatched adapter may hold remote work without a local process. + const [dispatched] = await db.insert(heartbeatRuns).values({ companyId: f.companyId, agentId: f.agent.id, status: "running", + runtimeMode: "legacy", responsibleUserId: f.actorId, controllerBootId: randomUUID(), controllerLeaseExpiresAt: expired, + executionStage: "dispatching", updatedAt: new Date(now), startedAt: new Date(now) }).returning(); + await start(); await advance(4 * 60_000); + expect((await getRun(sameBoot.id)).status).toBe("running"); + expect((await getRun(withProcess.id)).status).toBe("running"); + expect((await getRun(dispatched.id)).status).toBe("running"); + }); it.each(["confirmed", "already_retired", "missing_terminal", "unproven_terminal", "ack_failure", "late_terminal"] as const)( "settles an API-only Stop after deferred controller retirement without inventing proof: %s", async mode => { const f = await fixture(), runId = randomUUID(), sessionId = randomUUID(), runnerId = randomUUID(); diff --git a/server/src/services/heartbeat/recovery.ts b/server/src/services/heartbeat/recovery.ts index aedc155f5fd..065ecafa922 100644 --- a/server/src/services/heartbeat/recovery.ts +++ b/server/src/services/heartbeat/recovery.ts @@ -2471,8 +2471,23 @@ export function createHeartbeatRecovery(db: Db, dependencies: HeartbeatRecoveryD const legacyLease = await liveLegacyControllerExpiresAt(db, run); if (legacyLease) { scope.onDeferredDeadline?.(legacyLease.getTime()); continue; } + // A legacy controller proves it is alive only by renewing its lease, and + // the check above found no live lease (a missing expiry also lands here; + // revocation below then refuses the row). When the lease belongs to a + // previous boot, setup never reached adapter dispatch, and no process + // was recorded, the owner is gone and no provider work can be running: + // recover now instead of waiting for the age threshold. A dispatched + // adapter (for example a remote HTTP request) keeps the age guard. The + // stage is rechecked from the state committed with the revocation below. + const priorBootSetupExpired = + run.runtimeMode === "legacy" && + run.executionStage === "preparing" && + !!run.controllerBootId && + run.controllerBootId !== legacyControllerBootId && + !run.processPid && + !run.processGroupId; // Apply staleness threshold to avoid false positives - if (staleThresholdMs > 0) { + if (staleThresholdMs > 0 && !priorBootSetupExpired) { const refTime = run.updatedAt ? new Date(run.updatedAt).getTime() : 0; if (now.getTime() - refTime < staleThresholdMs) { scope.onDeferredDeadline?.(refTime + staleThresholdMs); @@ -2543,6 +2558,15 @@ export function createHeartbeatRecovery(db: Db, dependencies: HeartbeatRecoveryD (!monitorNextCheckAt || monitorNextCheckAt.getTime() <= now.getTime()); const revokedState = await revokeExpiredLegacyControllerWithState(db, run); if (!revokedState) continue; + // The earlier snapshot may predate a final renewal that admitted the + // adapter. Revocation leaves a fresh foreign lease, so a later pass + // applies the age guard to that dispatched run. + if (priorBootSetupExpired && staleThresholdMs > 0 && (revokedState.executionStage !== "preparing" + || revokedState.processPid || revokedState.processGroupId)) { + const refTime = run.updatedAt ? new Date(run.updatedAt).getTime() : 0; + scope.onDeferredDeadline?.(Math.max(refTime + staleThresholdMs, Date.now() + 60_000)); + 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.