mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-09 07:10:34 +01:00
fix(recovery): finalize an accepted native result after a hard kill (#19713)
## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - A native run hands its accepted result to a controller lease, and the controller finalizes the task from that result > - A graceful shutdown releases that lease for the next server (#19591), but a hard kill (SIGKILL, OOM, host crash) cannot > - After a hard kill between result acceptance and finalization, the next server waited for the dead controller's 20-minute lease, so the run stayed `running` and the user's follow-up comment waited with it > - This pull request releases that lease at startup when the controller is proved dead by its boot ID and process identity, never by age > - The benefit is that the saved result finalizes within seconds after a restart, without another provider turn, and queued follow-up work continues ## Linked Issues or Issue Description Refs #19591 (the graceful-shutdown counterpart) and #19578 (boot-identity proof for legacy runs). **What happened?** A restart-chaos wave sent K1 (SIGKILL) 20 ms after a Claude run recorded `run.result.accepted` and `run.terminal`. The run then stayed `running` for more than 10 minutes, through four more restarts. The finalization row was `workspace_finalizing` with the stored result. Its lease belonged to the killed server: a different `controller_boot_id`, a `controller_pid` with no process, and `lease_expires_at` 20 minutes ahead. Startup recovery skips runs that already have a result. The result-commit worker waits until the lease expires. The task's follow-up comment could not run until then. **Steps to reproduce** 1. Let a native local run accept its result. 2. SIGKILL the server before finalization finishes. 3. Restart the server. The run stays `running` until the old lease expires. **Expected behavior** After a restart, a result lease held by a stopped controller of an earlier boot is treated as released at once. The stored result finalizes once, with no new provider turn, and the follow-up wake runs after it. ## What Changed - New `server/src/services/native-runtime/native-dead-controller-result-lease.ts`: `releaseDeadControllerResultLeases` finds `running` native runs with an accepted result and an unexpired lease. It requires the lease to belong to a different controller boot. It proves the controller stopped with `evaluateNativeControllerTakeover` (`requireStoppedController`): the process is dead, or its PID now names another process. It then expires that lease with a compare-and-set on the exact owner token, boot ID, and PID, and notifies the result-commit and finalization workers. - `server/src/services/heartbeat/recovery.ts`: `recoverNativeRunsAfterRestart` calls this first and records a `native.recovery.transition` event (`awaiting_result_finalization`) for each released run. - Only executor leases are released, because only the executor claim writes the controller identity together with the lease. Finalizer (`native-finalizer:`) and cleanup (`native-cleanup:`) claims keep an earlier executor's identity, so they are never released this way and expire on their own short leases. A finalization-resume token (`:resume:`) on a result row always belongs to the executor that adopted it, because a pending resume claim is taken only on a row without a result. - Also not released: a live owner, an owner without a recorded process, a lease of the current boot, a run this process is executing, and remote workspaces (`nativeWorkspaceSync` or `remoteWorkspace`), which keep their fenced lease. - The compare-and-set does not compare the stored expiry. Postgres stores microseconds that a JavaScript `Date` drops, and an exact-expiry comparison silently skipped the real lease in the live reproduction. - `doc/execution-semantics.md`: documents the rule. ## Verification - Red then green on embedded Postgres (`server/src/__tests__/heartbeat-native-restart-suspension.test.ts`): - A hard kill with a dead controller's executor lease (first claim, restart claim, or resumed claim) now finalizes on the next startup: run `succeeded`, finalization `committed`, task `done`, one result, one run, no provider dispatch. These tests failed before the fix with `status: running`. - A lease expiry stored with microsecond precision is released. This test failed against the first version of the fix and reproduces the live miss. - A live controller of another boot keeps its lease, and so does a lease of the current boot. - A live claimant's finalizer or cleanup lease is kept when the recorded earlier executor is dead. - `npx vitest run src/__tests__/heartbeat-native-restart-suspension.test.ts`: 20 passed. - Related suites pass: `native-session-resumption`, `native-runner-restart-recovery.integration`, `native-run-projection-work`, `live-recovery-work`. One `live-recovery-work` legacy case timed out once under load and passed when run again by itself. - Live, local: `tests/restart-chaos/main.ts --workloads C1 --triggers result --faults K1 --rc06-masked`. The failing case above came from such a wave. I started its kept database and confirmed the stored lease state and the compare-and-set miss. Against that same database, the fixed release expires the stuck executor lease. Two later waves (12 tasks, `--triggers result`) passed every task. Run events were not kept for passing tasks, so I cannot confirm that a kill landed in the narrow pre-finalization window in those waves. - Live proof on head `8971874654`: local ACPX Claude, workload A1, seed 7411, `--triggers result` (a local variant that fires on A1 2.5–3.5 s after the run's result proposal), `--keep`. The run passed 4 of 4 tasks. In two tasks, K1 landed 1.5 s and 2.0 s after `run.result.accepted`. On the next startup, each run recorded "Server restart released the accepted native result of a stopped controller for finalization" (`controller_process_dead`). Each finished `succeeded` about 1 s later, with its task `done` and exactly one run per task (no extra provider turn). Before this fix, the same shape stayed `running` until the 10-minute budget ran out (seeds 7411, 7422, and 7423 from the RC-33b investigation in #19691). ## Risks - Startup could take a lease from a finalizer that is still running. Mitigations: the lease must belong to another boot, the controller process must be proved stopped on this host (the same proof the existing runner takeover uses), and the update matches the exact owner. Remote workspaces are excluded. Multi-host deployments keep the existing PID-liveness assumption that `claimNativeRestartRecoveries` already makes. - Low behavioral risk otherwise: finalization uses the existing reconciler path, which #19591 already exercises after a graceful drain. ## Model Used - Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, run as an agent in Claude Code with tool use (shell, file editing, local test execution, live restart-chaos waves). ## 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 - [ ] All Paperclip CI gates are green - [ ] 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 <noreply@anthropic.com>
This commit is contained in:
1 parent
42f6b3a870
commit
51eb4ff705
4 files changed
+202
-1
No files matched your search
@@ -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
|
||||
|
||||
@@ -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<ReturnType<typeof seedAcceptedResult>>, 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<ReturnType<typeof seedAcceptedResult>>) {
|
||||
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);
|
||||
});
|
||||
@@ -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, {
|
||||
|
||||
@@ -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<Parameters<typeof evaluateNativeControllerTakeover>[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<Array<{ runId: string; reason: string }>> {
|
||||
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;
|
||||
}
|
||||
Reference in new issue
Block a user