Files
PaperClipAI/server/src/services/legacy-controller-lease.ts
T
bbcf5dfe98 fix(heartbeat): renew legacy controller leases on a private pool (#17032)
## Thinking Path

> - Paperclip is the open source app people use to manage AI agents for
work
> - A legacy (non-native) agent run keeps a controller lease on its
`heartbeat_runs` row. The server renews the lease every 10 seconds. If
no renewal succeeds in 60 seconds, the watchdog stops the run with
`renewal_deadline`.
> - #16359 added timings to lease-loss reports. The first staging event
with these timings shows `deadlineLateMs=0`, `renewalPendingMs=50000`,
and 108 renewals in about 22.5 minutes, where about 135 are expected.
Thus the event loop was not blocked. One renewal UPDATE was in flight
for 50 seconds, and renewals were slow for a long time before the loss.
> - The agent had exited with code 0. The run was in post-execution
`sync_back`. Other runs on the same host completed. No code path held a
lock on the run row across slow work. A later `instruction_save` UPDATE
on the same row completed while the earlier renewal was still pending,
so a row-lock wait does not explain the stall.
> - postgres.js 3.4.9 sends a new query to a busy connection when no
connection is idle (`handler` → `go(busy.shift(), query)` in
`src/index.js`). The query waits behind the statement that is in flight
on that connection. The renewal had no timeout, and the `pending` flag
stopped all later renewals. Thus one slow unrelated statement on the
shared pool can stop a healthy run.
> - This pull request moves lease renewal to a small private pool,
bounds each attempt with a statement timeout, and retries a timed-out
attempt until the existing lease deadline.
> - The benefit is that slow application queries on the shared pool can
no longer cancel a healthy legacy run.

## Linked Issues or Issue Description

Refs #16359 (lease-loss timings that identified this cause)
Refs #16358 (pre-dispatch lease loss becomes retryable; different path)
Refs #16917 (open: keeps a clean adapter result after a lease lapsed; it
does not prevent the loss)
Refs #13389 (open: host sleep / late timers; different cause)

**What happened?**
A staging legacy `claude_local` run was cancelled with `Legacy
controller lease lost (renewal_deadline)` after the agent exited with
code 0. The timings show that the deadline timer ran on time, and one
renewal UPDATE was pending for 50 seconds.

**Expected behavior**
A live controller keeps its lease. Slow unrelated database work does not
cancel the run.

**Steps to reproduce**
1. Create a database client with one pooled connection.
2. Start `select pg_sleep(5)` on that client.
3. Call `watchLegacyControllerLease(...).assertOwned()` with the same
client.
4. Before this change, the renewal waits about 5 seconds behind
`pg_sleep`. With a long enough slow statement, the lease deadline stops
the run.

## What Changed

- `packages/db`: Add `livenessDb(db)`. It gives each `createDb` client a
private pool of at most 2 connections
(`application_name=paperclip-controller-lease`). The pool is created on
first use. Test doubles and transactions get the original client back.
- `packages/db`: Add `closeLivenessDb(db, timeoutSeconds)`. The server
calls it in `closeDatabaseClients`, so shutdown and failed startup end
the private pool too.
- `legacy-controller-lease.ts`: The watchdog renews in a transaction on
the private pool. Each attempt sets a transaction-local
`statement_timeout` of 10 seconds. A timed-out attempt (`57014`) is
retried. After a successful retry, the local deadline is measured from
that attempt's start, because that attempt's UPDATE wrote the fresh 60
second lease. The existing 60 second deadline, the abort race, and the
`renewal_rejected` / `renewal_error` attribution do not change.
`renewLegacyControllerLease` itself does not change, so the
runtime-selection caller inside its own transaction is not affected.
- Tests: a saturated shared pool no longer delays renewal; a renewal
that times out on a locked run row retries and keeps the lease; the
private pool is cached per client, has its own `application_name`, and
closes; after a 45 second timed-out attempt and a successful retry, the
next deadline is a full 60 seconds after the retry. The existing test
doubles now model the transaction.
- `docs/deploy/database.md`: Count the up to 2 extra connections per
server process when you size `max_connections`.

## Verification

- `cd server && npx vitest run
src/services/legacy-controller-lease.test.ts`: 20 passed, on embedded
Postgres.
- Red/green: with the old `legacy-controller-lease.ts` and the new
tests, the saturated-pool test fails with `expected 5018 to be less than
2000`. With the fix, it passes.
- Red/green for the retry deadline: with the deadline measured from the
first attempt, the retry-deadline test fails (`expected true to be
false`) because the run is aborted 15 seconds after the retry. With the
fix, it passes.
- Mutation check: when the timeout retry is removed, the locked-row test
fails with `canceling statement due to statement timeout`.
- `npx vitest run src/__tests__/heartbeat-process-recovery.test.ts -t
"lease|dispatch|controller|interaction"`: 43 passed.
- `npx vitest run src/services/heartbeat/run-completion.test.ts
src/__tests__/heartbeat-orphaned-active-lease-sweep.test.ts`: 53 passed.
- `npx vitest run src/__tests__/server-startup-feedback-export.test.ts`:
passed.
- `cd packages/db && npx vitest run src/work-signals.test.ts
src/client-options.test.ts src/client-teardown-registry.test.ts`: 24
passed. `npx tsc --noEmit` for `packages/db` passed.
- Not run locally: the full server `tsc` and the full server suite. The
sandbox has a 4 GB memory limit, and `tsc` was killed (exit 137). CI is
the gate for the server typecheck, the full tests, and the build.

## Risks

- Each server process can open up to 2 more Postgres connections.
Deployments that are at their `max_connections` limit must allow for
them. The docs now say this.
- A renewal attempt is now 4 statements (BEGIN, `set_config`, UPDATE,
COMMIT) instead of 1. Each statement is a short primary-key operation on
a dedicated connection.
- If many runs wait on locked run rows at the same time, renewals for
other runs can queue on the 2 private connections. The 10 second
statement timeout limits each wait, which is less than the 60 second
lease.
- Behavior for a real lease loss does not change. A rejected renewal and
a non-timeout error still stop the run at once, and the 60 second
deadline still applies.

## Model Used

- Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, used through Claude
Code in agent mode with tool use (shell, file edit, and test execution).
A read-only subagent helped with code search.

## 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: devinfoley <139239+devinfoley@users.noreply.github.com>
Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-20 18:13:53 -07:00

214 lines
8.8 KiB
TypeScript

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",
};
}
export async function renewLegacyControllerLease(
db: Db,
run: Pick<Run, "id" | "companyId" | "controllerBootId">,
stage?: "dispatching",
): Promise<boolean> {
const [renewed] = await db.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);
}
/** 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;
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 renewLegacyControllerLease(tx as unknown as Db, run, stage);
});
}
export async function hasLiveLegacyController(db: Db, run: Run): Promise<boolean> {
if (run.runtimeMode === "native" || !run.controllerBootId) return false;
const [owner] = await db.select({ id: heartbeatRuns.id }).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 Boolean(owner);
}
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 [revoked] = await db.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, run.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;
const renewalsInFlight = new Set<{ startedAt: number }>();
let deadlineDueAt = 0;
let deadline: ReturnType<typeof setTimeout> | undefined;
const lost = (cause: LegacyControllerLeaseLossCause) => {
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: cause === "renewal_deadline" ? Math.max(0, now - deadlineDueAt) : null,
renewalCount,
}));
};
const deadlinePassed = () => lost("renewal_deadline");
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.
let attemptStartedAt = startedAt;
const renew = async () => {
for (;;) {
attemptStartedAt = Date.now();
try {
return await renewOnLivenessPool(db, run, stage, renewalStatementTimeoutMs);
} catch (error) {
if (!isStatementTimeout(error) || 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;
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); } };
}