diff --git a/doc/execution-semantics.md b/doc/execution-semantics.md index c451b57df87..5b4c5639891 100644 --- a/doc/execution-semantics.md +++ b/doc/execution-semantics.md @@ -1723,6 +1723,19 @@ 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. +A native run can accept its result and then lose its server to a hard kill +before finalization. Its result stays leased to the controller of the earlier +boot, which cannot release the lease the way a graceful drain does. Startup +native recovery releases that lease at once when the lease belongs to a +different boot and its recorded controller process has exited or its PID now +names another process. Only the executor's lease carries that controller +identity; a finalizer or cleanup lease is never released this way and expires +on its own short lease. The stored result is then +finalized without another +provider turn, and saved follow-up messages are reconsidered. A live owner, an +owner without a recorded process, a lease of the current boot, and a remote +workspace keep the lease until it expires. Lease age alone is never proof. + 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__/heartbeat-native-restart-suspension.test.ts b/server/src/__tests__/heartbeat-native-restart-suspension.test.ts index 3cb7a89231b..0e54daf71e2 100644 --- a/server/src/__tests__/heartbeat-native-restart-suspension.test.ts +++ b/server/src/__tests__/heartbeat-native-restart-suspension.test.ts @@ -1,5 +1,5 @@ import { randomUUID } from "node:crypto"; -import { and, eq } from "drizzle-orm"; +import { and, eq, sql } from "drizzle-orm"; import { authUsers, budgetReservations, companyMemberships, completionContracts, heartbeatRunEvents, heartbeatRuns, issues, nativeRunFinalizations, nativeRunResults, workspaceOperations } from "@paperclipai/db"; import { expect, it, vi } from "vitest"; import { resolveLocalRuntimeApiUrl } from "../runtime-api.js"; @@ -323,4 +323,83 @@ describeEmbeddedPostgres("heartbeat native recovery interrupted by graceful shut const [run] = await f.db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, f.runId)); expect(run.status).toBe("running"); }, 60_000); + + /** RC-41: a hard kill leaves the accepted result leased to a controller that no longer exists. */ + async function killedController(f: Awaited>, controller: { + bootId: string; pid: number; processStartedAt: Date | null; + }) { + await f.db.update(nativeRunFinalizations).set({ controllerBootId: controller.bootId, + controllerPid: controller.pid, controllerProcessStartedAt: controller.processStartedAt }) + .where(eq(nativeRunFinalizations.runId, f.runId)); + } + async function restart(f: Awaited>) { + const providerDispatch = vi.fn(() => { throw new Error("an accepted result must not open another provider turn"); }); + const next = heartbeatService(f.db, { nativeSessionBackendFactory: providerDispatch }); + try { await next.recoverNativeRunsAfterRestart(new Date()); } + finally { await next.drainActiveRunExecutions(); } + expect(providerDispatch).not.toHaveBeenCalled(); + const [run] = await f.db.select().from(heartbeatRuns).where(eq(heartbeatRuns.id, f.runId)); + const [owner] = await f.db.select().from(nativeRunFinalizations).where(eq(nativeRunFinalizations.runId, f.runId)); + return { run, owner }; + } + + it.each([ + { holder: "runner execution", leaseOwner: (runner: string) => `${runner}:${randomUUID()}` }, + { holder: "restart-claimed execution", leaseOwner: () => `${randomUUID()}:2:${randomUUID()}` }, + // An executor that adopted a finalization-resume claim keeps that token. + { holder: "resumed execution", leaseOwner: (runner: string) => `${runner}:resume:${randomUUID()}` }, + ])("finalizes an accepted result promptly when a hard kill left its $holder lease to a dead controller", async ({ holder, leaseOwner }) => { + // RC-41: K1 lands after run.result is committed but before finalization. + // The dead boot's 20-minute lease must not hold the run `running`. + const f = await seedAcceptedResult(`ACCEPTED-THEN-SIGKILL-${holder}`, leaseOwner); + await killedController(f, { bootId: randomUUID(), pid: 2_000_000_001, processStartedAt: new Date(Date.now() - 60_000) }); + const { run, owner } = await restart(f); + const [task] = await f.db.select().from(issues).where(eq(issues.id, f.issueId)); + expect({ status: run.status, phase: owner.phase }).toEqual({ status: "succeeded", phase: "committed" }); + expect(task.status).toBe("done"); + expect(await f.db.select({ id: nativeRunResults.id }).from(nativeRunResults) + .where(eq(nativeRunResults.runId, f.runId))).toHaveLength(1); + expect(await f.db.select({ id: heartbeatRuns.id }).from(heartbeatRuns) + .where(eq(heartbeatRuns.nativeIssueId, f.issueId))).toHaveLength(1); + }, 90_000); + + it("releases a dead controller's lease whose expiry Postgres stored with microsecond precision", async () => { + // The controller writes its lease with SQL time arithmetic, so the stored + // expiry carries microseconds that a JavaScript Date cannot round-trip. + const f = await seedAcceptedResult("ACCEPTED-THEN-SIGKILL-MICROS", (runner) => `${runner}:${randomUUID()}`); + await killedController(f, { bootId: randomUUID(), pid: 2_000_000_001, processStartedAt: new Date(Date.now() - 60_000) }); + await f.db.update(nativeRunFinalizations).set({ + leaseExpiresAt: sql`date_trunc('second', now()) + interval '20 minutes 0.123456 seconds'`, + }).where(eq(nativeRunFinalizations.runId, f.runId)); + const { run, owner } = await restart(f); + expect({ status: run.status, phase: owner.phase }).toEqual({ status: "succeeded", phase: "committed" }); + }, 90_000); + + it("keeps the accepted result leased while its earlier-boot controller process is still alive", async () => { + // Another live server (or an orphaned controller of an earlier boot) can + // still be finalizing. Age and boot ID alone never prove that it stopped. + const f = await seedAcceptedResult("ACCEPTED-LIVE-FOREIGN", () => `native-finalizer:${randomUUID()}`); + const self = await currentNativeControllerIdentity(); + await killedController(f, { bootId: randomUUID(), pid: process.pid, processStartedAt: self.processStartedAt }); + const { run, owner } = await restart(f); + expect({ status: run.status, phase: owner.phase, leaseExpiresAt: owner.leaseExpiresAt }) + .toEqual({ status: "running", phase: "workspace_finalizing", leaseExpiresAt: f.leaseExpiresAt }); + }, 60_000); + + it.each(["native-finalizer", "native-cleanup"])("keeps a %s lease whose controller identity names an earlier executor", async (prefix) => { + // These claims do not rewrite the controller identity, so the dead earlier + // executor proves nothing about the process that holds the lease now. + const f = await seedAcceptedResult(`ACCEPTED-${prefix}-OF-LIVE-CLAIMANT`, () => `${prefix}:${randomUUID()}`); + await killedController(f, { bootId: randomUUID(), pid: 2_000_000_001, processStartedAt: new Date(Date.now() - 60_000) }); + const { run, owner } = await restart(f); + expect({ status: run.status, phase: owner.phase, leaseExpiresAt: owner.leaseExpiresAt }) + .toEqual({ status: "running", phase: "workspace_finalizing", leaseExpiresAt: f.leaseExpiresAt }); + }, 60_000); + + it("keeps a finalizer lease that belongs to the current boot", async () => { + const f = await seedAcceptedResult("ACCEPTED-CURRENT-BOOT", () => `native-finalizer:${randomUUID()}`); + const { run, owner } = await restart(f); + expect({ status: run.status, phase: owner.phase, leaseExpiresAt: owner.leaseExpiresAt }) + .toEqual({ status: "running", phase: "workspace_finalizing", leaseExpiresAt: f.leaseExpiresAt }); + }, 60_000); }); diff --git a/server/src/services/heartbeat/recovery.ts b/server/src/services/heartbeat/recovery.ts index 04d40f10e29..bce456589bd 100644 --- a/server/src/services/heartbeat/recovery.ts +++ b/server/src/services/heartbeat/recovery.ts @@ -1,3 +1,4 @@ +import { releaseDeadControllerResultLeases } from "../native-runtime/native-dead-controller-result-lease.js"; import { readNativeStartupCleanup, readNativeStartupContext } from "../native-runtime/native-startup-cleanup.js"; import { legacyWorkspaceRecoveryNotMigrated } from "../legacy-workspace-recovery-migration.js"; import { pendingFailedNativeRetryCancellationCondition } from "../native-runtime/native-cancellation-request.js"; @@ -935,6 +936,18 @@ export function createHeartbeatRecovery(db: Db, dependencies: HeartbeatRecoveryD } async function recoverNativeRunsAfterRestart(now = new Date(), runIds?: string[], options?: { skipDelegatedWork?: boolean; trigger?: "same_run_retry" }) { + // A hard kill cannot release its accepted results the way a graceful drain + // does. Release leases whose earlier-boot controller has exited, so the + // finalization below settles them now instead of after lease expiry. + const releasedResults = await releaseDeadControllerResultLeases(db, { now, runIds, + liveRunExecutions: activeRunExecutions }); + for (const released of releasedResults) { + const run = await getRun(released.runId).catch(() => null); + if (run) await appendRunEvent(run, { eventType: "native.recovery.transition", stream: "system", level: "info", + message: "Server restart released the accepted native result of a stopped controller for finalization", + payload: { restartKind: "hard", runnerDisposition: "awaiting_result_finalization", reason: released.reason }, + }).catch(error => logger.warn({ err: error, runId: released.runId }, "failed to record released native result lease")); + } if (!runIds && !options?.skipDelegatedWork) { await reconcileRetainedWorkspaces(db, environmentRuntime, resumeRemoteStopComments); await reconcileNativeFinalizations(db, undefined, { diff --git a/server/src/services/native-runtime/native-dead-controller-result-lease.ts b/server/src/services/native-runtime/native-dead-controller-result-lease.ts new file mode 100644 index 00000000000..7258870e2c1 --- /dev/null +++ b/server/src/services/native-runtime/native-dead-controller-result-lease.ts @@ -0,0 +1,96 @@ +import { and, eq, gt, inArray, isNotNull, isNull, ne, notInArray, notLike, sql } from "drizzle-orm"; +import { heartbeatRuns, nativeRunFinalizations, type Db } from "@paperclipai/db"; +import { notifyLiveRunRecovery } from "../live-run-recovery-notifications.js"; +import { notifyNativeFinalizationWork } from "../native-finalization-notifications.js"; +import { notifyNativeResultCommit } from "../native-result-commit-notifications.js"; +import { currentNativeControllerIdentity, evaluateNativeControllerTakeover } from "./native-restart-recovery.js"; + +type TakeoverProbe = Pick[0], "isProcessAlive" | "readProcessStartedAt">; + +/** + * A hard kill (SIGKILL, OOM, host crash) after `run.result` is accepted leaves + * the result leased to a controller of an earlier boot. A graceful drain expires + * that lease itself; a killed process cannot. Without this release, result + * finalization waits the full lease (up to 20 minutes) and the run stays + * `running` with its follow-up work held. + * + * Ownership is proved by controller identity, never by lease age: the + * executor lease belongs to a different boot and its recorded controller + * process has exited (or its PID now names a different process). A live or + * unidentifiable owner, and any lease not written with that identity, keeps + * its lease. Remote workspaces keep their fenced lease semantics. + */ +export async function releaseDeadControllerResultLeases(db: Db, input: { + now: Date; + runIds?: string[]; + liveRunExecutions?: { has(runId: string): boolean }; +} & TakeoverProbe): Promise> { + const controller = await currentNativeControllerIdentity(); + const candidates = await db.select({ + runId: nativeRunFinalizations.runId, + companyId: nativeRunFinalizations.companyId, + issueId: nativeRunFinalizations.issueId, + agentId: heartbeatRuns.agentId, + leaseOwner: nativeRunFinalizations.leaseOwner, + leaseExpiresAt: nativeRunFinalizations.leaseExpiresAt, + controllerBootId: nativeRunFinalizations.controllerBootId, + controllerPid: nativeRunFinalizations.controllerPid, + controllerProcessStartedAt: nativeRunFinalizations.controllerProcessStartedAt, + }).from(nativeRunFinalizations) + .innerJoin(heartbeatRuns, and(eq(heartbeatRuns.id, nativeRunFinalizations.runId), + eq(heartbeatRuns.companyId, nativeRunFinalizations.companyId), + eq(heartbeatRuns.nativeIssueId, nativeRunFinalizations.issueId))) + .where(and( + eq(heartbeatRuns.runtimeMode, "native"), + eq(heartbeatRuns.status, "running"), + isNotNull(nativeRunFinalizations.resultId), + notInArray(nativeRunFinalizations.phase, ["committed", "terminal_failure"]), + isNotNull(nativeRunFinalizations.leaseOwner), + // Only an executor's lease is written with the controller identity probed + // below, including an executor that adopted a resume claim (a pending + // resume claim never holds an accepted result). Finalizer and cleanup + // claims keep an earlier executor's identity, so a dead earlier executor + // proves nothing about them. Their own leases are short and expire. + notLike(nativeRunFinalizations.leaseOwner, "native-finalizer:%"), + notLike(nativeRunFinalizations.leaseOwner, "native-cleanup:%"), + gt(nativeRunFinalizations.leaseExpiresAt, input.now), + isNotNull(nativeRunFinalizations.controllerBootId), + ne(nativeRunFinalizations.controllerBootId, controller.bootId), + // Remote copyback is fenced by its own controller lease. + sql`${heartbeatRuns.runnerProfileJson}->'nativeWorkspaceSync' is null`, + sql`${heartbeatRuns.runnerProfileJson}->'remoteWorkspace' is null`, + input.runIds?.length ? inArray(nativeRunFinalizations.runId, input.runIds) : undefined, + )); + + const released: Array<{ runId: string; reason: string }> = []; + for (const row of candidates) { + if (input.liveRunExecutions?.has(row.runId)) continue; + const takeover = await evaluateNativeControllerTakeover({ + owner: row, now: input.now, requireStoppedController: true, + ...(input.isProcessAlive ? { isProcessAlive: input.isProcessAlive } : {}), + ...(input.readProcessStartedAt ? { readProcessStartedAt: input.readProcessStartedAt } : {}), + }); + if (!takeover.allowed) continue; + const updated = await db.transaction(async tx => { + await notifyLiveRunRecovery(tx, { companyId: row.companyId, runId: row.runId, agentId: row.agentId }); + await notifyNativeResultCommit(tx, { companyId: row.companyId, runId: row.runId, issueId: row.issueId }); + await notifyNativeFinalizationWork(tx, { companyId: row.companyId, runId: row.runId }); + // Compare-and-set on the exact dead owner, so a lease taken over since + // the scan is never cut short. Each lease owner token is unique; the + // stored expiry is not compared because Postgres keeps microseconds that + // a JavaScript Date drops. + return tx.update(nativeRunFinalizations).set({ leaseExpiresAt: input.now, updatedAt: input.now }) + .where(and( + eq(nativeRunFinalizations.runId, row.runId), + eq(nativeRunFinalizations.leaseOwner, row.leaseOwner!), + gt(nativeRunFinalizations.leaseExpiresAt, input.now), + eq(nativeRunFinalizations.controllerBootId, row.controllerBootId!), + row.controllerPid === null ? isNull(nativeRunFinalizations.controllerPid) + : eq(nativeRunFinalizations.controllerPid, row.controllerPid), + )) + .returning({ runId: nativeRunFinalizations.runId }); + }); + if (updated.length) released.push({ runId: row.runId, reason: takeover.reason }); + } + return released; +}