mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-13 07:12:00 +01:00
fix(heartbeat): renew legacy controller leases on their own connection, timed from the statement (#21042)
## 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 <noreply@anthropic.com>
This commit is contained in:
1 parent
98c18784c6
commit
148d2b629c
4 files changed
+76
-18
No files matched your search
@@ -311,10 +311,24 @@ export function livenessDb(db: Db): Db {
|
||||
return created;
|
||||
}
|
||||
|
||||
const controllerLeaseDbFactories = new WeakMap<object, () => Db>();
|
||||
const controllerLeaseDbs = new WeakMap<object, Db>();
|
||||
|
||||
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<void> {
|
||||
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));
|
||||
|
||||
@@ -4,6 +4,7 @@ export {
|
||||
createOwnedDatabaseListener,
|
||||
type OwnedDatabaseListener,
|
||||
livenessDb,
|
||||
controllerLeaseDb,
|
||||
closeLivenessDb,
|
||||
checkpointDb,
|
||||
closeCheckpointDb,
|
||||
|
||||
@@ -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];
|
||||
|
||||
|
||||
@@ -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<object, RenewalBatch>();
|
||||
|
||||
function renewThroughBatch(db: Db, target: RenewalTarget, statementTimeoutMs: number): Promise<RenewalOutcome> {
|
||||
function renewThroughBatch(db: Db, target: RenewalTarget, statementTimeoutMs: number): Promise<RenewalResult> {
|
||||
let batch = renewalBatches.get(db);
|
||||
if (!batch) renewalBatches.set(db, batch = { pending: [], flushing: false });
|
||||
const outcome = new Promise<RenewalOutcome>((resolve, reject) => {
|
||||
const outcome = new Promise<RenewalResult>((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(() => {
|
||||
|
||||
Reference in new issue
Block a user