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.