From 148d2b629c9e2edaed2f731ff057036480db2cc3 Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Thu, 12 Nov 2026 00:52:06 -0600 Subject: [PATCH] fix(heartbeat): renew legacy controller leases on their own connection, timed from the statement (#21042) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - A legacy run keeps a controller lease on its `heartbeat_runs` row. The server renews every lease in the process with one batched statement every 10 seconds, and stops a run when its local lease deadline passes. > - The batched renewal ran on the 2-connection liveness pool. Native runner lease renewals use the same pool. Each native renewal holds a connection for a row lock, about seven notifications, and an update. > - With 18 native runner runs renewing every 20 seconds on a slow database, the legacy batch waited 30 to 50 seconds for a connection. The local deadline also counted that wait, so it fired 20 to 40 seconds before the database lease could expire. > - Runs then stopped with `controller_lease_lost` while no other controller owned them, and their issues looped through retries. > - This pull request gives legacy renewal its own connection and measures the deadline from the time the statement starts on that connection. > - The benefit is that a slow server no longer stops runs that still own their lease. A real takeover still stops the run. ## Linked Issues or Issue Description **What happened?** On staging, after the 05:37Z deploy, 63 of about 175 new runs failed with `controller_lease_lost` ("Legacy controller lease lost") at about 3 per minute. All were legacy runs in preparation (`executionRecovery.kind: bootstrap`, `providerWorkStarted: false`). One example had `controllerLeaseLoss: {cause: "renewal_deadline", renewalCount: 7, sinceRenewalMs: 42537, renewalPendingMs: 38798, deadlineLateMs: 134}`. Several runs that failed at the same moment had identical timing values, so they were members of the same renewal batch. The previous successful renewal took 17 to 44 seconds, so the deadline that it set was only 16 to 43 seconds away. At that time 27 legacy runs were preparing and 18 native runner runs were renewing on the same liveness pool. The issues looped: `issue_assigned`, lease lost, `issue_continuation_needed`, lease lost, `transient_failure_retry`, lease lost. **Expected behavior** A slow server or database must not cause a lease loss while the controller still owns the lease. Only a real expiry or a takeover by another controller must stop the run. **Steps to reproduce** 1. Start legacy runs and native runner runs on one server. 2. Make the database slow, so that each native lease renewal holds a liveness connection for several seconds. 3. The legacy renewal batch waits for a liveness connection, and its next local deadline is shortened by that wait. 4. The next renewal also waits, and the local deadline fires first. The run fails with `controller_lease_lost` (`renewal_deadline`). **Paperclip version or commit** Staging at 8cefbe9977. The fix is based on master at aa94939988. **Deployment mode** Hosted cloud (staging). **Agent adapter(s) involved** Legacy controller runs (Codex and Claude local adapters). Native runner runs share the liveness pool. ## What Changed - `packages/db`: add `controllerLeaseDb(db)`, a private 1-connection pool (`paperclip-legacy-controller-lease`) for legacy controller renewal. `closeLivenessDb` also ends it, so shutdown does not change. - `legacy-controller-lease.ts`: the batched renewal runs on `controllerLeaseDb` instead of the liveness pool that native lease renewals use. - `legacy-controller-lease.ts`: each batch records the time when its transaction starts on the connection. The watcher measures the next deadline from that time, not from the time the request was queued. The database sets the new expiry at UPDATE time, which is later, so the local deadline never passes the database expiry. - The renewal statement, its boot-id and expiry conditions, and revocation do not change. A takeover or an expired lease still rejects the renewal and stops the run. ## Verification - Red/green regression tests in `server/src/services/legacy-controller-lease.test.ts`: - `renews without queueing behind native lease transactions that hold every liveness connection` (embedded Postgres). Before the fix, the renewal waited 9.8 s behind four 5-second liveness transactions. After the fix, it completes in less than 2 s. - `keeps a controller owned when every renewal waits thirty-five seconds for a connection before its statement runs`. Before the fix, the lease was lost with `{sinceRenewalMs: 25000, renewalPendingMs: 20000, renewalCount: 1}`, the same pattern as on staging. After the fix, the controller stays owned for four lease periods. - Updated the private-pool tests to check the new pool and its application name. - `npx vitest run src/services/legacy-controller-lease.test.ts`: 40 passed. - `pnpm verify` (affected tests), plus `typecheck` for `packages/db` and `server`. ## Risks - Each server process opens one more database connection, only when it has a legacy run. - The local deadline can now be later than before, by the time that the batch waited for a connection. It stays at or before the database expiry, because the database sets the expiry after the recorded start time. Readers that act on an expired lease are not affected. - Low risk otherwise. There is no schema change. ## Model Used - Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, in Claude Code with tool use and code 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 Refs #20924, #20936 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-authored-by: Claude Opus 5.5 --- packages/db/src/client.ts | 19 ++++++- packages/db/src/index.ts | 1 + .../services/legacy-controller-lease.test.ts | 51 ++++++++++++++++--- .../src/services/legacy-controller-lease.ts | 23 +++++---- 4 files changed, 76 insertions(+), 18 deletions(-) diff --git a/packages/db/src/client.ts b/packages/db/src/client.ts index ee080641142..1f7c25f6c59 100644 --- a/packages/db/src/client.ts +++ b/packages/db/src/client.ts @@ -311,10 +311,24 @@ export function livenessDb(db: Db): Db { return created; } +const controllerLeaseDbFactories = new WeakMap Db>(); +const controllerLeaseDbs = new WeakMap(); + +export function controllerLeaseDb(db: Db): Db { + const existing = controllerLeaseDbs.get(db); + if (existing) return existing; + const factory = controllerLeaseDbFactories.get(db); + if (!factory) return db; + const created = factory(); + controllerLeaseDbs.set(db, created); + return created; +} + /** Ends the liveness pool if one was created. The ended pool stays cached, so * a late renewal fails like a query on the ended primary pool. */ export async function closeLivenessDb(db: Db, timeoutSeconds: number): Promise { - await livenessDbs.get(db)?.$client.end({ timeout: timeoutSeconds }); + await Promise.all([livenessDbs.get(db)?.$client.end({ timeout: timeoutSeconds }), + controllerLeaseDbs.get(db)?.$client.end({ timeout: timeoutSeconds })]); } // Control checkpoints must not occupy the request or lease-renewal pools @@ -389,6 +403,9 @@ function createDbClient(url: string, resolved: DatabaseClientOptions, owner?: ob livenessDbFactories.set(db, () => createDbClient(url, { ...resolved, maxConnections: LIVENESS_POOL_MAX_CONNECTIONS, applicationName: "paperclip-controller-lease", }, db)); + controllerLeaseDbFactories.set(db, () => createDbClient(url, { + ...resolved, maxConnections: 1, applicationName: "paperclip-legacy-controller-lease", + }, db)); checkpointDbFactories.set(db, () => createDbClient(url, { ...resolved, maxConnections: CHECKPOINT_POOL_MAX_CONNECTIONS, applicationName: "paperclip-runner-checkpoint", }, db)); diff --git a/packages/db/src/index.ts b/packages/db/src/index.ts index c513660e99e..feb4848b43e 100644 --- a/packages/db/src/index.ts +++ b/packages/db/src/index.ts @@ -4,6 +4,7 @@ export { createOwnedDatabaseListener, type OwnedDatabaseListener, livenessDb, + controllerLeaseDb, closeLivenessDb, checkpointDb, closeCheckpointDb, diff --git a/server/src/services/legacy-controller-lease.test.ts b/server/src/services/legacy-controller-lease.test.ts index 8d33b23cb42..0ff1028f38a 100644 --- a/server/src/services/legacy-controller-lease.test.ts +++ b/server/src/services/legacy-controller-lease.test.ts @@ -2,7 +2,7 @@ import { randomUUID } from "node:crypto"; import { and, eq, ne, sql, type SQL } from "drizzle-orm"; import { PgDialect } from "drizzle-orm/pg-core"; import { afterAll, beforeAll, describe, expect, it, vi } from "vitest"; -import { agents, closeLivenessDb, companies, createDb, heartbeatRuns, livenessDb, subscribeDatabaseWork } from "@paperclipai/db"; +import { agents, closeLivenessDb, companies, controllerLeaseDb, createDb, heartbeatRuns, livenessDb, subscribeDatabaseWork } from "@paperclipai/db"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "../__tests__/helpers/embedded-postgres.js"; import { resolveExternalTestDatabaseUrl } from "../__tests__/helpers/external-test-database.js"; import { DELIVERY_QUEUES } from "./delivery-work-notifications.js"; @@ -122,7 +122,7 @@ const support = external ? { supported: true } : await getEmbeddedPostgresTestSu DELIVERY_QUEUES.activeExecutionRecovery, DELIVERY_QUEUES.settledNativeProcesses, DELIVERY_QUEUES.strandedAgentStatus, DELIVERY_QUEUES.activeRunSilence]; const stops = queues.map(queue => subscribeDatabaseWork(db, queue, event => { if (event === "settled") settled.push(queue); })); - const pool = livenessDb(db), prior = pool.$client.options.debug; + const pool = controllerLeaseDb(db), prior = pool.$client.options.debug; await pool.execute(sql`select 1`); pool.$client.options.debug = (_connection, query) => { queries.push(query); }; const watch = watchLegacyControllerLease(db, run, new AbortController()); @@ -224,19 +224,42 @@ const support = external ? { supported: true } : await getEmbeddedPostgresTestSu it("renews on one private pool per client that shutdown can end", async () => { const run = await seed(); const owner = createDb(external ?? database.connectionString, { maxConnections: 6 }); - const pool = livenessDb(owner); + const pool = controllerLeaseDb(owner); expect(pool).not.toBe(owner); - expect(livenessDb(owner)).toBe(pool); + expect(pool).not.toBe(livenessDb(owner)); + expect(controllerLeaseDb(owner)).toBe(pool); const watch = watchLegacyControllerLease(owner, run, new AbortController()); try { await watch.assertOwned(); const [{ name }] = await pool.execute<{ name: string }>(sql`select current_setting('application_name') as name`); - expect(name).toBe("paperclip-controller-lease"); + expect(name).toBe("paperclip-legacy-controller-lease"); } finally { watch.stop(); } await closeLivenessDb(owner, 1); + await expect(controllerLeaseDb(owner).execute(sql`select 1`)).rejects.toThrow(); await expect(livenessDb(owner).execute(sql`select 1`)).rejects.toThrow(); }); + it("renews without queueing behind native lease transactions that hold every liveness connection", async () => { + const run = await seed(); + const owner = createDb(external ?? database.connectionString, { maxConnections: 6 }); + const nativeRenewals = Array.from({ length: 4 }, () => + livenessDb(owner).transaction(async tx => { await tx.execute(sql`select pg_sleep(5)`); })); + const controller = new AbortController(); + const watch = watchLegacyControllerLease(owner, run, controller); + try { + await new Promise(resolve => setTimeout(resolve, 200)); + const startedAt = Date.now(); + await watch.assertOwned("dispatching"); + expect(Date.now() - startedAt).toBeLessThan(2_000); + expect(controller.signal.aborted).toBe(false); + } finally { + watch.stop(); + await Promise.all(nativeRenewals); + await closeLivenessDb(owner, 1); + await owner.$client.end({ timeout: 1 }); + } + }, 30_000); + it("retries a renewal that times out waiting on the run row instead of losing the lease", async () => { const run = await seed(); let lockTaken!: () => void, releaseLock!: () => void; @@ -265,7 +288,7 @@ const support = external ? { supported: true } : await getEmbeddedPostgresTestSu try { await watch.assertOwned(); const terminated = await db.execute<{ pid: number }>(sql`select pg_terminate_backend(pid) as pid from pg_stat_activity - where application_name = 'paperclip-controller-lease' and pid <> pg_backend_pid()`); + where application_name = 'paperclip-legacy-controller-lease' and pid <> pg_backend_pid()`); expect(terminated.length).toBeGreaterThan(0); await expect(watch.assertOwned("dispatching")).resolves.toBeUndefined(); expect(controller.signal.aborted).toBe(false); @@ -277,7 +300,7 @@ const support = external ? { supported: true } : await getEmbeddedPostgresTestSu it("renews fifteen concurrent controllers in one statement", async () => { const runs = await Promise.all(Array.from({ length: 15 }, () => seed())); const queries: string[] = []; - const pool = livenessDb(db), prior = pool.$client.options.debug; + const pool = controllerLeaseDb(db), prior = pool.$client.options.debug; await pool.execute(sql`select 1`); pool.$client.options.debug = (_connection, query) => { queries.push(query); }; const controllers = runs.map(() => new AbortController()); @@ -525,6 +548,20 @@ describe("legacy controller lease loss attribution", () => { } finally { watches.forEach(watch => watch.stop()); vi.useRealTimers(); } }); + it("keeps a controller owned when every renewal waits thirty-five seconds for a connection before its statement runs", async () => { + vi.useFakeTimers(); + const run = watchedRun(LEGACY_CONTROLLER_LEASE_MS); + const pool = slowPoolDb([run.id], { connections: 1, transactionMs: 35_000 }); + const controller = new AbortController(); + const watch = watchLegacyControllerLease(pool.db, run, controller); + try { + await vi.advanceTimersByTimeAsync(4 * LEGACY_CONTROLLER_LEASE_MS); + expect(controller.signal.reason?.leaseLossTiming).toBeUndefined(); + expect(controller.signal.aborted).toBe(false); + expect(pool.transactions()).toBeGreaterThanOrEqual(5); + } finally { watch.stop(); vi.useRealTimers(); } + }); + const watchedRun = (leaseMs: number) => ({ id: randomUUID(), companyId: randomUUID(), runtimeMode: "legacy", controllerBootId: legacyControllerBootId, controllerLeaseExpiresAt: new Date(Date.now() + leaseMs) }) as WatchArgs[1]; diff --git a/server/src/services/legacy-controller-lease.ts b/server/src/services/legacy-controller-lease.ts index a6c39c31118..3565eef9a7d 100644 --- a/server/src/services/legacy-controller-lease.ts +++ b/server/src/services/legacy-controller-lease.ts @@ -1,6 +1,6 @@ import { notifyLiveRunRecovery } from "./live-run-recovery-notifications.js"; import { and, eq, gt, lte, sql } from "drizzle-orm"; -import { heartbeatRuns, livenessDb, type Db } from "@paperclipai/db"; +import { controllerLeaseDb, heartbeatRuns, type Db } from "@paperclipai/db"; import type { LegacyControllerLeaseLossCause, LegacyControllerLeaseLossTiming } from "./run-cancellation.js"; import { randomUUID } from "node:crypto"; import { @@ -110,19 +110,20 @@ function isStatementTimeout(error: unknown): boolean { return false; } +type RenewalResult = { outcome: RenewalOutcome; issuedAt: number }; type RenewalRequest = { target: RenewalTarget; statementTimeoutMs: number; - resolve(outcome: RenewalOutcome): void; + resolve(result: RenewalResult): void; reject(error: unknown): void; }; type RenewalBatch = { pending: RenewalRequest[]; flushing: boolean }; const renewalBatches = new WeakMap(); -function renewThroughBatch(db: Db, target: RenewalTarget, statementTimeoutMs: number): Promise { +function renewThroughBatch(db: Db, target: RenewalTarget, statementTimeoutMs: number): Promise { let batch = renewalBatches.get(db); if (!batch) renewalBatches.set(db, batch = { pending: [], flushing: false }); - const outcome = new Promise((resolve, reject) => { + const outcome = new Promise((resolve, reject) => { batch.pending.push({ target, statementTimeoutMs, resolve, reject }); }); if (!batch.flushing) void flushRenewals(db, batch); @@ -142,13 +143,15 @@ async function flushRenewals(db: Db, batch: RenewalBatch) { } try { const statementTimeoutMs = Math.min(...requests.map(request => request.statementTimeoutMs)); - const outcomes = await livenessDb(db).transaction(async (tx) => { + let issuedAt = 0; + const outcomes = await controllerLeaseDb(db).transaction(async (tx) => { + issuedAt = Date.now(); await tx.execute(sql`select set_config('statement_timeout', ${`${statementTimeoutMs}ms`}, true)`); return renewLegacyControllerLeasesInTransaction(tx as unknown as Db, [...targets.values()]); }); for (const request of requests) { const sameCompany = targets.get(request.target.id)!.companyId === request.target.companyId; - request.resolve(sameCompany ? outcomes.get(request.target.id) ?? "rejected" : "rejected"); + request.resolve({ outcome: sameCompany ? outcomes.get(request.target.id) ?? "rejected" : "rejected", issuedAt }); } } catch (error) { for (const request of requests) request.reject(error); @@ -351,13 +354,13 @@ export function watchLegacyControllerLease( // 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; + let renewedFrom = startedAt; const renew = async () => { for (;;) { - attemptStartedAt = Date.now(); try { - const outcome = await renewThroughBatch(db, { id: run.id, companyId: run.companyId, stage }, + const { outcome, issuedAt } = await renewThroughBatch(db, { id: run.id, companyId: run.companyId, stage }, renewalStatementTimeoutMs); + renewedFrom = issuedAt; if (outcome !== "busy") return outcome === "renewed"; await new Promise((resolve) => setTimeout(resolve, LEGACY_CONTROLLER_RENEWAL_BUSY_RETRY_DELAY_MS)); if (stopped || controller.signal.aborted) return false; @@ -389,7 +392,7 @@ export function watchLegacyControllerLease( lastRenewedAt = Date.now(); renewalCount += 1; renewalFailed = false; - armDeadline(Math.max(0, LEGACY_CONTROLLER_LEASE_MS - (Date.now() - attemptStartedAt))); + armDeadline(Math.max(0, LEGACY_CONTROLLER_LEASE_MS - (Date.now() - renewedFrom))); } }; const timer = setInterval(() => {