Files
PaperClipAI/server/src/services/legacy-controller-lease.ts
T
Devin FoleyandClaude Opus 5.5 6a45ea479e fix(heartbeat): retry failed legacy lease renewals until the deadline (#17851)
<!-- entire-trail-link-start -->
https://entire.com/gh/paperclipai/-/trails/52/changes/paperclip/52
<!-- entire-trail-link-end -->

## Thinking Path

> - Paperclip is the open source app people use to manage AI agents for
work
> - A legacy agent run keeps a durable controller lease. The server
renews the lease every 10 s. The lease lasts 60 s.
> - The lease watchdog stops the run when it loses the lease, because
another controller can then take the run.
> - #17032 moved renewal to a private pool. It also retries a renewal
that hits its statement timeout. But a renewal that fails with any other
error still stops the run at once.
> - Staging still shows this failure after #17032. A legacy run made 186
good renewals over 31 minutes. Then one renewal failed with an error
23.9 s after the last good renewal, and the watchdog stopped the run
immediately (`controllerLeaseLossCause=renewal_error`). The lease still
had about 36 s left.
> - This pull request retries a failed renewal until the lease deadline,
the same as a timed-out renewal.
> - The benefit is that one dropped database connection no longer
cancels a healthy run. The 60 s lease deadline still bounds the retries,
so the ownership guarantee does not change.

## Linked Issues or Issue Description

Refs #17032
Refs #16084

**What happened?**
A legacy agent run on staging was cancelled mid-turn. The run was
healthy. The cancellation evidence was
`cancellationSource=controller_lease` and
`controllerLeaseLossCause=renewal_error`, with
`controllerLeaseRenewalCount=186` and
`controllerLeaseSinceRenewalMs=23913`. The release already contained
#17032.

**Expected behavior**
One failed lease renewal must not stop a run while the lease is still
valid. The watchdog must try the renewal again. It must stop the run
only when the lease deadline passes or when the database rejects the
renewal.

**Steps to reproduce**
1. Start a legacy run so that `watchLegacyControllerLease` watches it.
2. Make one renewal query fail with a connection error, for example
terminate its Postgres backend with `pg_terminate_backend`.
3. See that the watchdog aborts the run immediately with
`renewal_error`, although the lease has not expired.

## What Changed

- `watchLegacyControllerLease` retries a renewal that fails with an
error. It waits 1 s between attempts
(`LEGACY_CONTROLLER_RENEWAL_RETRY_DELAY_MS`). The existing lease
deadline stops the retries.
- A retried renewal is safe. The UPDATE is idempotent, and it still
requires this controller's boot ID and an unexpired lease. A rejected
renewal (no row updated) still stops the run at once with
`renewal_rejected`.
- If the deadline passes while the attempts still fail with an error,
the cause stays `renewal_error`. A statement timeout counts as a stall,
so it stays `renewal_deadline`, as before. A good renewal clears the
error state.
- `deadlineLateMs` is now recorded whenever the deadline ends the lease,
also for `renewal_error`.
- Tests:
- New embedded-Postgres test: it terminates the renewal's own backend
while the renewal waits on the run row. The renewal retries on a new
connection and keeps the lease. Without the fix, `assertOwned` rejects.
- New unit tests: one failed attempt is retried and the lease is kept; a
stall after a recovered error is still `renewal_deadline`.
- The existing `renewal_error` test now checks that a renewal that
always fails is retried and is reported as `renewal_error` at the
deadline, with its timings.
- `doc/run-log-events.md` describes the retry and the updated
`renewal_error` and `deadlineLateMs` meaning.

## Verification

- `server/src/services/legacy-controller-lease.test.ts` with embedded
Postgres: 23 tests pass.
- With the original `legacy-controller-lease.ts`, 4 of these tests fail.
One of them is the real-Postgres test that terminates the renewal
connection.
- `server/src/services/heartbeat/run-completion.test.ts` and the
`run-cancellation` tests: 35 tests pass.
- A typecheck of the changed files reports 0 errors. CI runs the full
typecheck.

## Risks

- Low risk. The change is limited to the legacy lease watchdog.
- A run with a permanently failing renewal now stops at the lease
deadline (at most 60 s after the last good renewal), not at the first
error. Another controller cannot take the run before the lease expires
in the database, so ownership stays safe.
- A non-transient error (for example a code bug in the query) is retried
once per second until the deadline. The cause label is still
`renewal_error`.

## Model Used

- Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, used through Claude
Code with tool use (shell, code search, test execution).

## 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>
2026-11-04 10:15:08 -08:00

248 lines
11 KiB
TypeScript

import { notifyActiveExecutionRecovery, notifyLiveRunRecovery } from "./live-run-recovery-notifications.js";
import { randomUUID } from "node:crypto";
import { and, eq, gt, lte, sql } from "drizzle-orm";
import { heartbeatRuns, livenessDb, type Db } from "@paperclipai/db";
import type { LegacyControllerLeaseLossCause, LegacyControllerLeaseLossTiming } from "./run-cancellation.js";
// A boot UUID has meaning across containers; a numeric PID does not.
export const legacyControllerBootId = randomUUID();
export const LEGACY_CONTROLLER_LEASE_MS = 60_000;
export const LEGACY_CONTROLLER_RENEW_MS = 10_000;
type Run = typeof heartbeatRuns.$inferSelect;
/** A lease lost before adapter dispatch: no provider work began, so the
* continuation is retryable rather than an opaque `setup_failed`. */
export const CONTROLLER_LEASE_LOST_FAILURE_CODE = "controller_lease_lost";
/** Abort reason for a lost lease, so completion can attribute the stop. */
export class LegacyControllerLeaseLostError extends Error {
constructor(
readonly leaseLossCause: LegacyControllerLeaseLossCause,
readonly leaseLossTiming?: LegacyControllerLeaseLossTiming,
) {
super("Legacy controller lease lost");
this.name = "LegacyControllerLeaseLostError";
}
}
/** Commit these fields in the same UPDATE that claims a queued run. */
export function legacyControllerClaim(runtimeMode: string) {
if (runtimeMode === "native") return {};
return {
controllerBootId: legacyControllerBootId,
controllerLeaseExpiresAt: sql`clock_timestamp() + interval '60 seconds'`,
executionStage: "preparing",
};
}
async function renewLegacyControllerLeaseInTransaction(
tx: Db,
run: Pick<Run, "id" | "companyId" | "controllerBootId">,
stage?: "dispatching",
): Promise<boolean> {
await notifyActiveExecutionRecovery(tx, { companyId: run.companyId, runId: run.id });
const [renewed] = await tx.update(heartbeatRuns).set({
controllerLeaseExpiresAt: sql`clock_timestamp() + interval '60 seconds'`,
...(stage ? { executionStage: stage } : {}),
}).where(and(
eq(heartbeatRuns.id, run.id), eq(heartbeatRuns.companyId, run.companyId),
eq(heartbeatRuns.runtimeMode, "legacy"), eq(heartbeatRuns.status, "running"),
eq(heartbeatRuns.controllerBootId, legacyControllerBootId),
gt(heartbeatRuns.controllerLeaseExpiresAt, sql`clock_timestamp()`),
)).returning({ id: heartbeatRuns.id });
return Boolean(renewed);
}
export async function renewLegacyControllerLease(
db: Db,
run: Pick<Run, "id" | "companyId" | "controllerBootId">,
stage?: "dispatching",
): Promise<boolean> {
return db.transaction(tx => renewLegacyControllerLeaseInTransaction(tx as unknown as Db, run, stage));
}
/** One attempt may wait at most this long; a timed-out attempt is retried
* until the lease deadline instead of holding the renewal for the whole lease. */
export const LEGACY_CONTROLLER_RENEWAL_STATEMENT_TIMEOUT_MS = 10_000;
/** Pause before retrying a renewal that failed with an error, so a dropped
* connection is retried without spinning against an unavailable database. */
export const LEGACY_CONTROLLER_RENEWAL_RETRY_DELAY_MS = 1_000;
function isStatementTimeout(error: unknown): boolean {
for (let cause = error, depth = 0; cause && depth < 4; cause = (cause as { cause?: unknown }).cause, depth++) {
if ((cause as { code?: unknown }).code === "57014") return true;
}
return false;
}
/** Renew on the private liveness pool so the write cannot queue behind an
* unrelated slow statement on a busy shared connection. */
async function renewOnLivenessPool(
db: Db,
run: Pick<Run, "id" | "companyId" | "controllerBootId">,
stage: "dispatching" | undefined,
statementTimeoutMs: number,
): Promise<boolean> {
return livenessDb(db).transaction(async (tx) => {
await tx.execute(sql`select set_config('statement_timeout', ${`${statementTimeoutMs}ms`}, true)`);
return renewLegacyControllerLeaseInTransaction(tx as unknown as Db, run, stage);
});
}
export async function liveLegacyControllerExpiresAt(db: Db, run: Run): Promise<Date | null> {
if (run.runtimeMode === "native" || !run.controllerBootId) return null;
const [owner] = await db.select({ expiresAt: heartbeatRuns.controllerLeaseExpiresAt }).from(heartbeatRuns).where(and(
eq(heartbeatRuns.id, run.id), eq(heartbeatRuns.companyId, run.companyId),
eq(heartbeatRuns.status, "running"),
gt(heartbeatRuns.controllerLeaseExpiresAt, sql`clock_timestamp()`),
));
return owner?.expiresAt ?? null;
}
export async function hasLiveLegacyController(db: Db, run: Run): Promise<boolean> {
return (await liveLegacyControllerExpiresAt(db, run)) !== null;
}
export type RevokedLegacyControllerState = Pick<Run, "executionStage" | "processPid" | "processGroupId">;
/** Atomically revoke an expired controller. Renewal and revocation serialize on
* 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<RevokedLegacyControllerState | null> {
if (run.runtimeMode === "native" || !run.controllerBootId) {
return { executionStage: run.executionStage, processPid: run.processPid, processGroupId: run.processGroupId };
}
const controllerBootId = run.controllerBootId;
const [revoked] = await db.transaction(async tx => {
await notifyLiveRunRecovery(tx, { companyId: run.companyId, runId: run.id });
return tx.update(heartbeatRuns).set({
controllerBootId: randomUUID(),
controllerLeaseExpiresAt: sql`clock_timestamp() + interval '60 seconds'`,
}).where(and(
eq(heartbeatRuns.id, run.id), eq(heartbeatRuns.companyId, run.companyId),
eq(heartbeatRuns.status, "running"),
eq(heartbeatRuns.controllerBootId, controllerBootId),
lte(heartbeatRuns.controllerLeaseExpiresAt, sql`clock_timestamp()`),
)).returning({
executionStage: heartbeatRuns.executionStage,
processPid: heartbeatRuns.processPid,
processGroupId: heartbeatRuns.processGroupId,
});
});
return revoked ?? null;
}
export async function revokeExpiredLegacyController(db: Db, run: Run): Promise<boolean> {
return (await revokeExpiredLegacyControllerWithState(db, run)) !== null;
}
/** Abort the adapter if the controller cannot renew. Bound each check by the
* lease duration even when the database connection never settles. */
export function watchLegacyControllerLease(
db: Db,
run: Run,
controller: AbortController,
{ renewalStatementTimeoutMs = LEGACY_CONTROLLER_RENEWAL_STATEMENT_TIMEOUT_MS } = {},
) {
if (run.runtimeMode === "native" || !run.controllerBootId) {
return { stop() {}, async assertOwned(_stage?: "dispatching") {} };
}
let stopped = false;
let pending = false;
// Timing evidence for a loss: a renewal still in flight at the deadline
// points at the database; a late deadline callback points at the event loop.
let lastRenewedAt = Date.now();
let renewalCount = 0;
// A non-timeout error since the last successful renewal, so a deadline that
// passes during the retries is attributed to the error, not to a stall.
let renewalFailed = false;
const renewalsInFlight = new Set<{ startedAt: number }>();
let deadlineDueAt = 0;
let deadline: ReturnType<typeof setTimeout> | undefined;
const lost = (cause: LegacyControllerLeaseLossCause, atDeadline = false) => {
if (stopped || controller.signal.aborted) return;
const now = Date.now();
const oldestRenewal = Math.min(...[...renewalsInFlight].map((renewal) => renewal.startedAt));
controller.abort(new LegacyControllerLeaseLostError(cause, {
sinceRenewalMs: now - lastRenewedAt,
renewalPendingMs: renewalsInFlight.size > 0 ? now - oldestRenewal : null,
deadlineLateMs: atDeadline ? Math.max(0, now - deadlineDueAt) : null,
renewalCount,
}));
};
const deadlinePassed = () => lost(renewalFailed ? "renewal_error" : "renewal_deadline", true);
const armDeadline = (delayMs: number) => {
clearTimeout(deadline);
deadlineDueAt = Date.now() + delayMs;
deadline = setTimeout(deadlinePassed, delayMs);
deadline.unref();
};
armDeadline(Math.max(0, (run.controllerLeaseExpiresAt?.getTime() ?? 0) - Date.now()));
const assertOwned = async (stage?: "dispatching") => {
if (stopped) return;
controller.signal.throwIfAborted();
const startedAt = Date.now();
const renewal = { startedAt };
renewalsInFlight.add(renewal);
let onAbort!: () => void;
const aborted = new Promise<never>((_, reject) => {
onAbort = () => reject(controller.signal.reason);
controller.signal.addEventListener("abort", onAbort, { once: true });
});
// The successful attempt's UPDATE writes a fresh lease, so the local
// deadline is measured from that attempt rather than the first one.
// Failed attempts are retried until the deadline aborts the controller:
// the UPDATE is idempotent and still requires this controller's boot ID.
let attemptStartedAt = startedAt;
const renew = async () => {
for (;;) {
attemptStartedAt = Date.now();
try {
return await renewOnLivenessPool(db, run, stage, renewalStatementTimeoutMs);
} catch (error) {
if (stopped || controller.signal.aborted) throw error;
// A statement timeout is a stall; it stays a `renewal_deadline` loss.
if (!isStatementTimeout(error)) {
renewalFailed = true;
await new Promise((resolve) => setTimeout(resolve, LEGACY_CONTROLLER_RENEWAL_RETRY_DELAY_MS));
if (stopped || controller.signal.aborted) throw error;
}
}
}
};
let renewed: boolean;
try {
renewed = await Promise.race([renew(), aborted]);
} finally {
renewalsInFlight.delete(renewal);
controller.signal.removeEventListener("abort", onAbort);
}
if (stopped) return;
if (!renewed) {
lost("renewal_rejected");
controller.signal.throwIfAborted();
}
controller.signal.throwIfAborted();
if (!stopped) {
lastRenewedAt = Date.now();
renewalCount += 1;
renewalFailed = false;
armDeadline(Math.max(0, LEGACY_CONTROLLER_LEASE_MS - (Date.now() - attemptStartedAt)));
}
};
const timer = setInterval(() => {
if (pending || stopped) return;
pending = true;
void assertOwned().catch(() => lost("renewal_error")).finally(() => { pending = false; });
}, LEGACY_CONTROLLER_RENEW_MS);
timer.unref();
return { assertOwned, stop() { stopped = true; clearInterval(timer); clearTimeout(deadline); } };
}