From c445cbe9a3672b66f9e45ccd890750e02b1afbf9 Mon Sep 17 00:00:00 2001 From: PlatformSREEngineer Date: Tue, 4 Aug 2026 06:54:21 +0000 Subject: [PATCH 1/9] fix(github-webhook): bound reviewer-wake lock-timeout retries and record dead_lettered (BLO-21582) withPrReviewerTaskLock's per-PR advisory-lock acquisition can time out (2s budget) when the current holder is itself stalled acquiring the second pooled connection heartbeat.wakeup() needs (see the comment on withPrReviewerTaskLock) -- reproduced live in production during a burst of concurrent webhook deliveries. That timeout landed in the outer catch and returned false BEFORE the `received` counter a few lines further in ever incremented, so the loss was invisible to the entire paperclip_github_review_request_delivery_total funnel: not `received`, not `queued`, not `dead_lettered`. A review request that "routed correctly" on every webhook-side log vanished with zero record anywhere, while the handler still answered GitHub 200 so GitHub's own redelivery-on-failure never fired either. Adds a bounded retry (3 attempts, 300ms/900ms backoff) around the lock acquisition -- safe to re-run because the guarded closure re-checks existingWake before doing anything -- and, once every attempt is exhausted, records dead_lettered directly so this loss is finally counted by the funnel invariant the BLO-18859 observability work already built (received == queued + suppressed + dead_lettered). Two new integration tests reproduce genuine cross-session advisory-lock contention against the embedded test Postgres: one proves a contention window shorter than the retry budget self-heals, the other proves an exhausted one is recorded as dead_lettered rather than silently dropped. Co-Authored-By: Claude Sonnet 5 --- server/src/__tests__/github-webhook.test.ts | 187 ++++++++++++++++++++ server/src/routes/github-webhook.ts | 108 +++++++++-- 2 files changed, 277 insertions(+), 18 deletions(-) diff --git a/server/src/__tests__/github-webhook.test.ts b/server/src/__tests__/github-webhook.test.ts index 7a645608e374..d0024f313cee 100644 --- a/server/src/__tests__/github-webhook.test.ts +++ b/server/src/__tests__/github-webhook.test.ts @@ -2503,7 +2503,194 @@ describeEmbeddedPostgres("github-webhook route", () => { expect(queuedWakes[0]?.payload).toMatchObject({ headSha: "freshsha" }); }); + // BLO-21582: production evidence showed `withPrReviewerTaskLock` timing out + // (2s budget) under contention, and the failure landing in the outer catch + // BEFORE the `received` counter a few lines further in ever incremented -- + // so the loss was invisible to the whole delivery funnel, not just + // `dead_lettered`. These two tests reproduce genuine advisory-lock + // contention across a second, independent DB connection (a fresh + // `createDb(...)` pool -- `pg_advisory_xact_lock` only contends across + // sessions) and assert the two outcomes the fix is meant to produce: a + // contention window shorter than the retry budget self-heals, and one that + // outlasts every retry is at least COUNTED as `dead_lettered` instead of + // vanishing with zero record anywhere. + describe("reviewer wake lock contention (BLO-21582)", () => { + let lockDb: ReturnType; + + beforeAll(() => { + lockDb = createDb(tempDb!.connectionString); + }); + + afterAll(async () => { + await lockDb.$client.end(); + }); + + async function holdAdvisoryLock(taskKey: string, holdMs: number) { + let releaseHeld: () => void = () => {}; + const held = new Promise((resolve) => { + releaseHeld = resolve; + }); + const acquired = new Promise((resolveAcquired, rejectAcquired) => { + void lockDb + .transaction(async (tx) => { + await tx.execute(sql`select pg_advisory_xact_lock(hashtextextended(${taskKey}, 0))`); + resolveAcquired(); + await held; + }) + .catch(rejectAcquired); + }); + await acquired; + const timer = setTimeout(releaseHeld, holdMs); + return () => { + clearTimeout(timer); + releaseHeld(); + }; + } + + it( + "recovers a reviewer wake once a transient lock-holder releases within the retry budget", + async () => { + const reviewerAgentId = randomUUID(); + const { companyId } = await seedCompanyAndAgent(); + await db.insert(agents).values({ + id: reviewerAgentId, + companyId, + name: "Ally", + role: "engineer", + status: "idle", + adapterType: "claude_k8s", + adapterConfig: {}, + runtimeConfig: {}, + permissions: {}, + }); + + const prNumber = 21582001; + const taskKey = `pr_review:Blockcast/paperclip:${prNumber}`; + // Longer than the 2s single-attempt budget, short enough that + // attempt 2 (after the 300ms backoff) lands inside the still-held + // window and attempt 3 finds it free. + const release = await holdAdvisoryLock(taskKey, 2_300); + + const app = buildApp({ prReviewerAgentId: reviewerAgentId }); + const payload = { + action: "opened", + pull_request: { + number: prNumber, + title: "Reviewer wake lock contention regression", + body: null, + head: { ref: "fix/blo-21582-lock-contention", sha: "lockcontendsha" }, + }, + repository: { full_name: "Blockcast/paperclip" }, + }; + const { body, signature } = signedRequest(payload); + const before = await deliveryCount("dead_lettered"); + + const res = await request(app) + .post("/api/webhooks/github") + .set("x-github-event", "pull_request") + .set("x-hub-signature-256", signature) + .set("x-github-delivery", "delivery-blo-21582-lock-recovery") + .set("content-type", "application/json") + .send(body); + + release(); + + expect(res.status).toBe(200); + expect(res.body).toMatchObject({ reviewerWakeFired: true }); + expect(await deliveryCount("dead_lettered")).toBe(before); + + const queuedWakes = await db + .select({ status: agentWakeupRequests.status }) + .from(agentWakeupRequests) + .where( + and( + eq(agentWakeupRequests.agentId, reviewerAgentId), + eq(agentWakeupRequests.idempotencyKey, `pr_review:Blockcast/paperclip:${prNumber}:github_pr_opened`), + eq(agentWakeupRequests.status, "queued"), + ), + ); + expect(queuedWakes).toHaveLength(1); + }, + 15_000, + ); + + it( + "records dead_lettered (never received) once every lock-acquisition retry is exhausted, without lying in the 200 response", + async () => { + const reviewerAgentId = randomUUID(); + const { companyId } = await seedCompanyAndAgent(); + await db.insert(agents).values({ + id: reviewerAgentId, + companyId, + name: "Ally", + role: "engineer", + status: "idle", + adapterType: "claude_k8s", + adapterConfig: {}, + runtimeConfig: {}, + permissions: {}, + }); + + const prNumber = 21582002; + const taskKey = `pr_review:Blockcast/paperclip:${prNumber}`; + // Outlasts all 3 attempts and both backoffs (2000+300+2000+900+2000 + // = 7200ms worst case): every retry must find the lock still held. + const release = await holdAdvisoryLock(taskKey, 7_800); + + const app = buildApp({ prReviewerAgentId: reviewerAgentId }); + const payload = { + action: "opened", + pull_request: { + number: prNumber, + title: "Reviewer wake lock exhaustion regression", + body: null, + head: { ref: "fix/blo-21582-lock-exhaustion", sha: "lockexhaustsha" }, + }, + repository: { full_name: "Blockcast/paperclip" }, + }; + const { body, signature } = signedRequest(payload); + const beforeDeadLettered = await deliveryCount("dead_lettered"); + const beforeReceived = await deliveryCount("received"); + + const res = await request(app) + .post("/api/webhooks/github") + .set("x-github-event", "pull_request") + .set("x-hub-signature-256", signature) + .set("x-github-delivery", "delivery-blo-21582-lock-exhaustion") + .set("content-type", "application/json") + .send(body); + + release(); + + // The handler still answers GitHub 200 (matching every other + // suppression path in this route -- GitHub redelivery is not the + // backstop here), but MUST NOT claim reviewerWakeFired for a wake + // that never queued a run. + expect(res.status).toBe(200); + expect(res.body).toMatchObject({ reviewerWakeFired: false }); + + // The regression: this delivery never reached the `received` + // increment (it lives inside the lock-guarded closure, which this + // delivery's attempts never entered), but it MUST now be counted as + // `dead_lettered` so the BLO-18859 funnel invariant + // (received == queued + suppressed + dead_lettered) keeps holding + // instead of a `received`-less delivery vanishing from the funnel + // entirely. + expect(await deliveryCount("received")).toBe(beforeReceived); + expect(await deliveryCount("dead_lettered")).toBe(beforeDeadLettered + 1); + + const wakes = await db + .select({ status: agentWakeupRequests.status }) + .from(agentWakeupRequests) + .where(eq(agentWakeupRequests.agentId, reviewerAgentId)); + expect(wakes).toHaveLength(0); + }, + 20_000, + ); + }); + it("re-reviews a PR after a fixup push even though the prior review completed (stale-head regression)", async () => { + const reviewerAgentId = randomUUID(); const { companyId } = await seedCompanyAndAgent(); await db.insert(agents).values({ diff --git a/server/src/routes/github-webhook.ts b/server/src/routes/github-webhook.ts index 5a63fddf82b5..a9957b1d7c0f 100644 --- a/server/src/routes/github-webhook.ts +++ b/server/src/routes/github-webhook.ts @@ -1532,6 +1532,17 @@ async function findActivePrReviewerForTask( .then((rows) => rows[0]?.agentId ?? null); } +// BLO-21582: a distinct class (not a bare Error) so the reviewer-wake call +// site can retry ONLY a lock-acquisition timeout -- never a business-rule +// refusal (HttpError) or a genuine DB error surfacing through the same catch, +// which retrying would just delay for no benefit. +class PrReviewerTaskLockTimeoutError extends Error { + constructor(taskKey: string) { + super(`timed out acquiring PR reviewer task assignment lock for ${taskKey}`); + this.name = "PrReviewerTaskLockTimeoutError"; + } +} + async function withPrReviewerTaskLock( db: Db, taskKey: string, @@ -1558,7 +1569,7 @@ async function withPrReviewerTaskLock( }); if (outcome.acquired) return outcome.value; if (Date.now() >= deadline) { - throw new Error("timed out acquiring PR reviewer task assignment lock"); + throw new PrReviewerTaskLockTimeoutError(taskKey); } await new Promise((resolve) => setTimeout(resolve, PR_REVIEWER_TASK_LOCK_RETRY_MS)); } @@ -2034,22 +2045,47 @@ export function githubWebhookRoutes(db: Db, config: GithubWebhookConfig) { ); return false; } - try { - const heartbeat = heartbeatService(db, { - pluginWorkerManager: config.pluginWorkerManager, - ...config.heartbeatOptions, - }); - const reviewerWakeupOptions = buildPrReviewerWakeupOptions(context, eventName, deliveryId); - const reviewerTaskKey = reviewerWakeupOptions.payload.taskKey; - const idempotencyKey = reviewerWakeupOptions.idempotencyKey; - // taskKey scopes active-run coalescing; idempotencyKey scopes duplicate - // request rows for the same PR+reason before enqueueing. - // Request-scoped keys also dedup terminal completed/cancelled rows, so a - // GitHub redelivery of one event cannot re-run work that already ran or - // was retired by converted_to_draft (BLO-18953). - const idempotentStatuses = idempotentWakeStatuses( - prReviewerWakeIdempotencyScope(context, deliveryId), - ); + const heartbeat = heartbeatService(db, { + pluginWorkerManager: config.pluginWorkerManager, + ...config.heartbeatOptions, + }); + const reviewerWakeupOptions = buildPrReviewerWakeupOptions(context, eventName, deliveryId); + const reviewerTaskKey = reviewerWakeupOptions.payload.taskKey; + const idempotencyKey = reviewerWakeupOptions.idempotencyKey; + // taskKey scopes active-run coalescing; idempotencyKey scopes duplicate + // request rows for the same PR+reason before enqueueing. + // Request-scoped keys also dedup terminal completed/cancelled rows, so a + // GitHub redelivery of one event cannot re-run work that already ran or + // was retired by converted_to_draft (BLO-18953). + const idempotentStatuses = idempotentWakeStatuses( + prReviewerWakeIdempotencyScope(context, deliveryId), + ); + + // BLO-21582: withPrReviewerTaskLock can time out acquiring the per-PR + // advisory lock -- observed live in production during bursts of + // concurrent webhook deliveries, most plausibly because the lock + // holder is itself blocked acquiring the SECOND pooled connection + // `heartbeat.wakeup()` needs (see the comment on withPrReviewerTaskLock) + // and so never releases the lock within the budget. That throw used to + // land straight in the catch below and return false -- BEFORE the + // `received` counter a few lines down ever increments, so the loss was + // invisible to the entire BLO-18859 delivery funnel (not `received`, + // not `queued`, not `dead_lettered`): a review request that "routed + // correctly" per every webhook-side log vanished with zero record + // anywhere, while this handler still answered GitHub 200 (so GitHub's + // own redelivery-on-failure never fired either). + // + // Bounded retry absorbs a transient contention window instead of + // stranding the PR on one unlucky timing; it is safe to re-run because + // the closure re-checks `existingWake` under a fresh lock attempt + // before doing anything (see below). Only a lock-timeout retries -- + // an HttpError business-rule refusal or a genuine DB error propagate + // straight to the catch, matching the existing non-retry behavior for + // those (see the comment above the `wakeResult` check). + const REVIEWER_WAKE_LOCK_ATTEMPTS = 3; + const REVIEWER_WAKE_LOCK_RETRY_BACKOFF_MS = [300, 900]; + for (let attempt = 0; attempt < REVIEWER_WAKE_LOCK_ATTEMPTS; attempt++) { + try { return await withPrReviewerTaskLock(db, reviewerTaskKey, async (tx) => { // The wake insert commits through heartbeat's own transaction. Keep // this transaction-scoped lock held until that commit is visible so @@ -2150,10 +2186,40 @@ export function githubWebhookRoutes(db: Db, config: GithubWebhookConfig) { // not produce a run. return false; }); - } catch (err) { + } catch (err) { + if ( + err instanceof PrReviewerTaskLockTimeoutError && + attempt < REVIEWER_WAKE_LOCK_ATTEMPTS - 1 + ) { + logger.warn( + { + err, + attempt: attempt + 1, + maxAttempts: REVIEWER_WAKE_LOCK_ATTEMPTS, + event: eventName, + prNumber: context?.prNumber, + repoFullName: context?.repoFullName, + }, + "github webhook reviewer wake lock attempt failed, retrying", + ); + await new Promise((resolve) => + setTimeout(resolve, REVIEWER_WAKE_LOCK_RETRY_BACKOFF_MS[attempt]), + ); + continue; + } + // BLO-21582: either every retry is exhausted, or this was not a + // lock-timeout so retrying would not help -- either way this + // delivery is lost BEFORE `received` was ever recorded a few lines + // up (that increment lives inside the lock-guarded closure). Record + // `dead_lettered` directly here so the BLO-18859 funnel invariant + // (received == queued + suppressed + dead_lettered) keeps holding + // instead of quietly under-counting `received`, and so the existing + // dead-letter alerting actually sees this class of loss. + recordGithubReviewRequestDelivery({ state: "dead_lettered", reason: context.wakeReason }); logger.error( { err, + attempt: attempt + 1, agentIds: reviewerAgentIds, event: eventName, prNumber: context?.prNumber, @@ -2162,7 +2228,13 @@ export function githubWebhookRoutes(db: Db, config: GithubWebhookConfig) { "github webhook reviewer wake failed", ); return false; + } } + // Unreachable: every loop iteration above returns or continues: the + // last attempt's catch always falls through to the dead_lettered + // return since `attempt < REVIEWER_WAKE_LOCK_ATTEMPTS - 1` is false by + // then. Kept only to satisfy the function's return type. + return false; })(); // Dependabot remediation wake. Like the reviewer wake, this targets a From 100033c91ee4ac38c5cd6e87e4550a015e41ee60 Mon Sep 17 00:00:00 2001 From: Omar Ramadan Date: Tue, 4 Aug 2026 02:49:56 -0700 Subject: [PATCH 2/9] fix(github-webhook): preserve review wake funnel on lock exhaustion --- server/src/__tests__/github-webhook.test.ts | 32 ++++++++++++++------- server/src/routes/github-webhook.ts | 17 +++++------ 2 files changed, 31 insertions(+), 18 deletions(-) diff --git a/server/src/__tests__/github-webhook.test.ts b/server/src/__tests__/github-webhook.test.ts index d0024f313cee..593a56ce93fd 100644 --- a/server/src/__tests__/github-webhook.test.ts +++ b/server/src/__tests__/github-webhook.test.ts @@ -2615,7 +2615,7 @@ describeEmbeddedPostgres("github-webhook route", () => { ); it( - "records dead_lettered (never received) once every lock-acquisition retry is exhausted, without lying in the 200 response", + "records received and dead_lettered once every lock-acquisition retry is exhausted, without lying in the 200 response", async () => { const reviewerAgentId = randomUUID(); const { companyId } = await seedCompanyAndAgent(); @@ -2650,7 +2650,9 @@ describeEmbeddedPostgres("github-webhook route", () => { }; const { body, signature } = signedRequest(payload); const beforeDeadLettered = await deliveryCount("dead_lettered"); + const beforeQueued = await deliveryCount("queued"); const beforeReceived = await deliveryCount("received"); + const beforeSuppressed = await deliveryCount("suppressed"); const res = await request(app) .post("/api/webhooks/github") @@ -2669,15 +2671,25 @@ describeEmbeddedPostgres("github-webhook route", () => { expect(res.status).toBe(200); expect(res.body).toMatchObject({ reviewerWakeFired: false }); - // The regression: this delivery never reached the `received` - // increment (it lives inside the lock-guarded closure, which this - // delivery's attempts never entered), but it MUST now be counted as - // `dead_lettered` so the BLO-18859 funnel invariant - // (received == queued + suppressed + dead_lettered) keeps holding - // instead of a `received`-less delivery vanishing from the funnel - // entirely. - expect(await deliveryCount("received")).toBe(beforeReceived); - expect(await deliveryCount("dead_lettered")).toBe(beforeDeadLettered + 1); + // The regression: this delivery never reached the normal `received` + // increment inside the lock-guarded closure. The exhausted lock path + // must still record both the funnel entry and the terminal state, so + // the delivery does not disappear and the BLO-18859 equation keeps + // holding for this path's delta. + const afterDeadLettered = await deliveryCount("dead_lettered"); + const afterQueued = await deliveryCount("queued"); + const afterReceived = await deliveryCount("received"); + const afterSuppressed = await deliveryCount("suppressed"); + + expect(afterReceived).toBe(beforeReceived + 1); + expect(afterDeadLettered).toBe(beforeDeadLettered + 1); + expect(afterQueued).toBe(beforeQueued); + expect(afterSuppressed).toBe(beforeSuppressed); + expect(afterReceived - beforeReceived).toBe( + afterQueued - beforeQueued + + (afterSuppressed - beforeSuppressed) + + (afterDeadLettered - beforeDeadLettered), + ); const wakes = await db .select({ status: agentWakeupRequests.status }) diff --git a/server/src/routes/github-webhook.ts b/server/src/routes/github-webhook.ts index a9957b1d7c0f..c308e475a4b0 100644 --- a/server/src/routes/github-webhook.ts +++ b/server/src/routes/github-webhook.ts @@ -2207,14 +2207,15 @@ export function githubWebhookRoutes(db: Db, config: GithubWebhookConfig) { ); continue; } - // BLO-21582: either every retry is exhausted, or this was not a - // lock-timeout so retrying would not help -- either way this - // delivery is lost BEFORE `received` was ever recorded a few lines - // up (that increment lives inside the lock-guarded closure). Record - // `dead_lettered` directly here so the BLO-18859 funnel invariant - // (received == queued + suppressed + dead_lettered) keeps holding - // instead of quietly under-counting `received`, and so the existing - // dead-letter alerting actually sees this class of loss. + // BLO-21582: an exhausted lock-acquisition timeout happens before the + // lock-guarded closure can record `received`. Preserve the BLO-18859 + // funnel (`received == queued + suppressed + dead_lettered`) by + // recording the delivery's entry into the durable wake path before its + // terminal dead-letter. Do not do this for arbitrary errors: those may + // have been thrown after the closure's normal `received` increment. + if (err instanceof PrReviewerTaskLockTimeoutError) { + recordGithubReviewRequestDelivery({ state: "received", reason: context.wakeReason }); + } recordGithubReviewRequestDelivery({ state: "dead_lettered", reason: context.wakeReason }); logger.error( { From 08227c9eefea95076bf2b33b1334580ac8779437 Mon Sep 17 00:00:00 2001 From: PlatformSREEngineer Date: Tue, 4 Aug 2026 17:48:44 +0000 Subject: [PATCH 3/9] fix(github-webhook): bound reviewer-wake lock retry end-to-end, avoid false dead-letters on lock exhaustion (BLO-21582) Ally review follow-up on this branch (issue comment 5177920386): - Replace the 3-attempt x fresh-2s-each retry loop (worst case ~7.2s, and only bounded *after* each db.transaction() returned, so a stalled pool checkout wasn't bounded at all) with a single request-wide 4s deadline that withPrReviewerTaskLock races pool checkout + the lock probe against directly. - On lock exhaustion, recheck for an equivalent durable wake (or confirm no reviewer was ever active) before recording dead_lettered, so a concurrent duplicate delivery that already completed the wake no longer produces a false loss alert. Falls back to the pre-existing received+dead_lettered recording only when neither recheck explains the outcome. Adds a regression test for the false-dead-letter case and updates the two existing lock-contention tests for the new single-budget timing. --- server/src/__tests__/github-webhook.test.ts | 111 ++++++++++- server/src/routes/github-webhook.ts | 198 ++++++++++++++------ 2 files changed, 237 insertions(+), 72 deletions(-) diff --git a/server/src/__tests__/github-webhook.test.ts b/server/src/__tests__/github-webhook.test.ts index 593a56ce93fd..456946f7bfd4 100644 --- a/server/src/__tests__/github-webhook.test.ts +++ b/server/src/__tests__/github-webhook.test.ts @@ -2511,9 +2511,9 @@ describeEmbeddedPostgres("github-webhook route", () => { // contention across a second, independent DB connection (a fresh // `createDb(...)` pool -- `pg_advisory_xact_lock` only contends across // sessions) and assert the two outcomes the fix is meant to produce: a - // contention window shorter than the retry budget self-heals, and one that - // outlasts every retry is at least COUNTED as `dead_lettered` instead of - // vanishing with zero record anywhere. + // contention window shorter than the request-wide lock budget self-heals, + // and one that outlasts it is at least COUNTED as `dead_lettered` instead + // of vanishing with zero record anywhere. describe("reviewer wake lock contention (BLO-21582)", () => { let lockDb: ReturnType; @@ -2566,9 +2566,11 @@ describeEmbeddedPostgres("github-webhook route", () => { const prNumber = 21582001; const taskKey = `pr_review:Blockcast/paperclip:${prNumber}`; - // Longer than the 2s single-attempt budget, short enough that - // attempt 2 (after the 300ms backoff) lands inside the still-held - // window and attempt 3 finds it free. + // Well inside the 4s request-wide lock budget (PR_REVIEWER_TASK_LOCK_BUDGET_MS + // in github-webhook.ts), with a wide margin either side so this is not + // coupled to the exact retry-poll cadence: the fix retries continuously + // against one deadline rather than in discrete backed-off attempts, so + // any release before the deadline self-heals. const release = await holdAdvisoryLock(taskKey, 2_300); const app = buildApp({ prReviewerAgentId: reviewerAgentId }); @@ -2633,9 +2635,10 @@ describeEmbeddedPostgres("github-webhook route", () => { const prNumber = 21582002; const taskKey = `pr_review:Blockcast/paperclip:${prNumber}`; - // Outlasts all 3 attempts and both backoffs (2000+300+2000+900+2000 - // = 7200ms worst case): every retry must find the lock still held. - const release = await holdAdvisoryLock(taskKey, 7_800); + // Outlasts the 4s request-wide lock budget (PR_REVIEWER_TASK_LOCK_BUDGET_MS + // in github-webhook.ts) with a clear margin, so this delivery must + // exhaust the retry budget outright. + const release = await holdAdvisoryLock(taskKey, 4_600); const app = buildApp({ prReviewerAgentId: reviewerAgentId }); const payload = { @@ -2697,10 +2700,98 @@ describeEmbeddedPostgres("github-webhook route", () => { .where(eq(agentWakeupRequests.agentId, reviewerAgentId)); expect(wakes).toHaveLength(0); }, - 20_000, + 10_000, + ); + + it( + "treats lock exhaustion as a no-op, not a false dead-letter, when a concurrent duplicate delivery already produced the equivalent durable wake", + async () => { + const reviewerAgentId = randomUUID(); + const { companyId } = await seedCompanyAndAgent(); + await db.insert(agents).values({ + id: reviewerAgentId, + companyId, + name: "Ally", + role: "engineer", + status: "idle", + adapterType: "claude_k8s", + adapterConfig: {}, + runtimeConfig: {}, + permissions: {}, + }); + + const prNumber = 21582003; + const taskKey = `pr_review:Blockcast/paperclip:${prNumber}`; + const idempotencyKey = `pr_review:Blockcast/paperclip:${prNumber}:github_pr_opened`; + + // Stands in for a concurrent duplicate delivery that won the lock and + // already committed the exact durable wake this delivery would have + // produced -- the scenario the unlocked recheck in the + // PrReviewerTaskLockTimeoutError branch exists to detect (BLO-21582 + // review follow-up: "Add a concurrent same-idempotency-key test where + // one request succeeds while the other exhausts"). + await db.insert(agentWakeupRequests).values({ + companyId, + agentId: reviewerAgentId, + source: "github", + reason: "github_pr_opened", + idempotencyKey, + status: "queued", + payload: { taskKey }, + }); + + // Outlasts the request-wide lock budget with a clear margin: this + // delivery must exhaust every lock-acquisition retry and hit the + // PrReviewerTaskLockTimeoutError catch, not the normal lock-guarded + // idempotency check (which the pre-existing row above would also + // satisfy, but that path isn't what this test exercises). + const release = await holdAdvisoryLock(taskKey, 4_600); + + const app = buildApp({ prReviewerAgentId: reviewerAgentId }); + const payload = { + action: "opened", + pull_request: { + number: prNumber, + title: "Reviewer wake lock exhaustion with an equivalent durable wake", + body: null, + head: { ref: "fix/blo-21582-equivalent-wake", sha: "lockequivsha" }, + }, + repository: { full_name: "Blockcast/paperclip" }, + }; + const { body, signature } = signedRequest(payload); + const beforeDeadLettered = await deliveryCount("dead_lettered"); + const beforeQueued = await deliveryCount("queued"); + const beforeReceived = await deliveryCount("received"); + const beforeSuppressed = await deliveryCount("suppressed"); + + const res = await request(app) + .post("/api/webhooks/github") + .set("x-github-event", "pull_request") + .set("x-hub-signature-256", signature) + .set("x-github-delivery", "delivery-blo-21582-lock-equivalent-wake") + .set("content-type", "application/json") + .send(body); + + release(); + + expect(res.status).toBe(200); + expect(res.body).toMatchObject({ reviewerWakeFired: false }); + + // The false-loss the review flagged: without the recheck, this would + // have recorded received+dead_lettered even though the equivalent + // wake is already durable. It must instead be the same silent no-op + // the lock-guarded duplicate-idempotency-key check produces -- no + // delivery-funnel metric moves at all. + expect(await deliveryCount("dead_lettered")).toBe(beforeDeadLettered); + expect(await deliveryCount("queued")).toBe(beforeQueued); + expect(await deliveryCount("received")).toBe(beforeReceived); + expect(await deliveryCount("suppressed")).toBe(beforeSuppressed); + }, + 10_000, ); }); + it("re-reviews a PR after a fixup push even though the prior review completed (stale-head regression)", async () => { const reviewerAgentId = randomUUID(); diff --git a/server/src/routes/github-webhook.ts b/server/src/routes/github-webhook.ts index c308e475a4b0..d4dd6fbc641c 100644 --- a/server/src/routes/github-webhook.ts +++ b/server/src/routes/github-webhook.ts @@ -66,7 +66,14 @@ type PrReviewerSelectionDb = Pick; // Keep lock contention well below GitHub's webhook timeout. The winner holds // one pooled connection while heartbeat commits through another; createDb's // default pool satisfies the required minimum of two connections. -const PR_REVIEWER_TASK_LOCK_TIMEOUT_MS = 2_000; +// +// BLO-21582 review follow-up: this is now a single request-wide budget +// (passed to withPrReviewerTaskLock as one deadline, not re-armed per +// attempt) so the whole lock-acquisition sequence -- including pool +// checkout/query time, which a bare `await db.transaction()` does not +// otherwise bound -- cannot itself approach GitHub's response window and +// trigger the redelivery-under-contention loop this path exists to absorb. +const PR_REVIEWER_TASK_LOCK_BUDGET_MS = 4_000; const PR_REVIEWER_TASK_LOCK_RETRY_MS = 25; export interface GithubWebhookConfig { @@ -1546,14 +1553,26 @@ class PrReviewerTaskLockTimeoutError extends Error { async function withPrReviewerTaskLock( db: Db, taskKey: string, + deadline: number, action: (tx: DbTransaction) => Promise, ): Promise { - const deadline = Date.now() + PR_REVIEWER_TASK_LOCK_TIMEOUT_MS; - while (true) { + const remainingMs = deadline - Date.now(); + if (remainingMs <= 0) { + throw new PrReviewerTaskLockTimeoutError(taskKey); + } // Do not block a pooled connection while another request owns the lock: // the winner needs a second connection for heartbeat's enqueue transaction. - const outcome = await db.transaction(async (tx) => { + // + // Race pool checkout + the lock probe against the remaining budget: + // `db.transaction()` alone does not respect `deadline` (a stalled pool + // checkout under contention could block well past it), so bound it + // explicitly here rather than only checking elapsed time after it + // resolves (BLO-21582 review follow-up). Attach a `.catch` so a + // transaction that eventually settles after we've stopped waiting on it + // doesn't surface as an unhandled rejection; it still commits or rolls + // back on its own connection, we've simply moved on. + const transactionPromise = db.transaction(async (tx) => { const rows = await tx.execute( sql`select pg_try_advisory_xact_lock(hashtextextended(${taskKey}, 0)) as acquired`, ); @@ -1567,6 +1586,18 @@ async function withPrReviewerTaskLock( } return { acquired: true as const, value: await action(tx) }; }); + transactionPromise.catch((err) => { + logger.warn( + { err, taskKey }, + "github webhook reviewer wake lock transaction settled after its retry budget was abandoned", + ); + }); + const outcome = await Promise.race([ + transactionPromise, + new Promise<{ acquired: false }>((resolve) => { + setTimeout(() => resolve({ acquired: false }), remainingMs); + }), + ]); if (outcome.acquired) return outcome.value; if (Date.now() >= deadline) { throw new PrReviewerTaskLockTimeoutError(taskKey); @@ -1575,6 +1606,30 @@ async function withPrReviewerTaskLock( } } +// Shared between the lock-guarded idempotency check inside +// withPrReviewerTaskLock's closure and the unlocked recheck on lock +// exhaustion below (BLO-21582 review follow-up) -- same query, same meaning, +// just without the per-task serialization the locked read gets. +async function findExistingPrReviewerWake( + db: PrReviewerSelectionDb, + reviewerAgentIds: string[], + idempotencyKey: string, + idempotentStatuses: string[], +) { + return db + .select({ id: agentWakeupRequests.id, status: agentWakeupRequests.status }) + .from(agentWakeupRequests) + .where( + and( + inArray(agentWakeupRequests.agentId, reviewerAgentIds), + eq(agentWakeupRequests.idempotencyKey, idempotencyKey), + inArray(agentWakeupRequests.status, idempotentStatuses), + ), + ) + .limit(1) + .then((rows) => rows[0] ?? null); +} + function prFeedbackBody(context: ResolvedEventContext): string | null { return context.reviewBody ?? context.commentBody ?? null; } @@ -2075,34 +2130,26 @@ export function githubWebhookRoutes(db: Db, config: GithubWebhookConfig) { // anywhere, while this handler still answered GitHub 200 (so GitHub's // own redelivery-on-failure never fired either). // - // Bounded retry absorbs a transient contention window instead of - // stranding the PR on one unlucky timing; it is safe to re-run because - // the closure re-checks `existingWake` under a fresh lock attempt - // before doing anything (see below). Only a lock-timeout retries -- - // an HttpError business-rule refusal or a genuine DB error propagate - // straight to the catch, matching the existing non-retry behavior for - // those (see the comment above the `wakeResult` check). - const REVIEWER_WAKE_LOCK_ATTEMPTS = 3; - const REVIEWER_WAKE_LOCK_RETRY_BACKOFF_MS = [300, 900]; - for (let attempt = 0; attempt < REVIEWER_WAKE_LOCK_ATTEMPTS; attempt++) { - try { - return await withPrReviewerTaskLock(db, reviewerTaskKey, async (tx) => { + // A single request-wide budget (PR_REVIEWER_TASK_LOCK_BUDGET_MS) absorbs + // a transient contention window instead of stranding the PR on one + // unlucky timing, while staying well under GitHub's webhook response + // window -- see the comment on withPrReviewerTaskLock for how the + // budget is enforced end-to-end (review follow-up on an earlier + // 3-attempt x fresh-2s-each design that could reach ~7.2s and only + // bounded time *after* each pool checkout, not during it). + const lockDeadline = Date.now() + PR_REVIEWER_TASK_LOCK_BUDGET_MS; + try { + return await withPrReviewerTaskLock(db, reviewerTaskKey, lockDeadline, async (tx) => { // The wake insert commits through heartbeat's own transaction. Keep // this transaction-scoped lock held until that commit is visible so // concurrent first events for one PR re-check affinity instead of // assigning the same task to different reviewers. - const existingWake = await tx - .select({ id: agentWakeupRequests.id, status: agentWakeupRequests.status }) - .from(agentWakeupRequests) - .where( - and( - inArray(agentWakeupRequests.agentId, reviewerAgentIds), - eq(agentWakeupRequests.idempotencyKey, idempotencyKey), - inArray(agentWakeupRequests.status, idempotentStatuses), - ), - ) - .limit(1) - .then((rows) => rows[0] ?? null); + const existingWake = await findExistingPrReviewerWake( + tx, + reviewerAgentIds, + idempotencyKey, + idempotentStatuses, + ); if (existingWake) { logger.info( { @@ -2186,41 +2233,74 @@ export function githubWebhookRoutes(db: Db, config: GithubWebhookConfig) { // not produce a run. return false; }); - } catch (err) { - if ( - err instanceof PrReviewerTaskLockTimeoutError && - attempt < REVIEWER_WAKE_LOCK_ATTEMPTS - 1 - ) { - logger.warn( - { - err, - attempt: attempt + 1, - maxAttempts: REVIEWER_WAKE_LOCK_ATTEMPTS, - event: eventName, - prNumber: context?.prNumber, - repoFullName: context?.repoFullName, - }, - "github webhook reviewer wake lock attempt failed, retrying", - ); - await new Promise((resolve) => - setTimeout(resolve, REVIEWER_WAKE_LOCK_RETRY_BACKOFF_MS[attempt]), - ); - continue; - } - // BLO-21582: an exhausted lock-acquisition timeout happens before the - // lock-guarded closure can record `received`. Preserve the BLO-18859 - // funnel (`received == queued + suppressed + dead_lettered`) by - // recording the delivery's entry into the durable wake path before its - // terminal dead-letter. Do not do this for arbitrary errors: those may - // have been thrown after the closure's normal `received` increment. + } catch (err) { if (err instanceof PrReviewerTaskLockTimeoutError) { + // BLO-21582 review follow-up: lock exhaustion means this delivery + // never reached the lock-guarded idempotency/active-reviewer gates + // above, so we cannot assume the equivalent wake was actually + // lost -- a concurrent duplicate delivery for the same PR may have + // held the lock for the full budget and completed the exact wake + // this one would have produced, or no reviewer may have been + // active the whole time either way. An unlocked recheck can't + // fully replace the lock-guarded read (a wake committed a moment + // later still slips through), but it turns the common + // already-handled case into the same silent no-op the idempotency + // and no-active-reviewer gates use above instead of a false + // dead-letter alert, while contention with no such evidence still + // counts as loss below. + const equivalentWake = await findExistingPrReviewerWake( + db, + reviewerAgentIds, + idempotencyKey, + idempotentStatuses, + ); + if (equivalentWake) { + logger.info( + { + equivalentWakeId: equivalentWake.id, + equivalentWakeStatus: equivalentWake.status, + idempotencyKey, + event: eventName, + deliveryId, + wakeReason: context.wakeReason, + prNumber: context.prNumber, + repoFullName: context.repoFullName, + }, + "github webhook reviewer wake lock exhausted, but an equivalent wake is already durable: not counting as a lost wake", + ); + return false; + } + const equivalentReviewerAgentId = + (await findActivePrReviewerForTask(db, reviewerAgentIds, reviewerTaskKey)) ?? + (await selectPrReviewerAgentId(db, reviewerAgentIds, reviewerTaskKey)); + if (!equivalentReviewerAgentId) { + logger.warn( + { + configuredReviewerCount: reviewerAgentIds.length, + event: eventName, + prNumber: context.prNumber, + repoFullName: context.repoFullName, + }, + "github webhook reviewer wake lock exhausted, but no configured reviewer is active: not counting as a lost wake", + ); + return false; + } + // BLO-21582: an exhausted lock-acquisition timeout happens before + // the lock-guarded closure can record `received`, and neither + // recheck above found an equivalent completed/no-op outcome. + // Preserve the BLO-18859 funnel + // (`received == queued + suppressed + dead_lettered`) by recording + // the delivery's entry into the durable wake path before its + // terminal dead-letter. recordGithubReviewRequestDelivery({ state: "received", reason: context.wakeReason }); } + // Do not double-count `received` for an arbitrary (non-timeout) + // error: those are thrown from inside the closure, after its normal + // `received` increment already ran. recordGithubReviewRequestDelivery({ state: "dead_lettered", reason: context.wakeReason }); logger.error( { err, - attempt: attempt + 1, agentIds: reviewerAgentIds, event: eventName, prNumber: context?.prNumber, @@ -2229,13 +2309,7 @@ export function githubWebhookRoutes(db: Db, config: GithubWebhookConfig) { "github webhook reviewer wake failed", ); return false; - } } - // Unreachable: every loop iteration above returns or continues: the - // last attempt's catch always falls through to the dead_lettered - // return since `attempt < REVIEWER_WAKE_LOCK_ATTEMPTS - 1` is false by - // then. Kept only to satisfy the function's return type. - return false; })(); // Dependabot remediation wake. Like the reviewer wake, this targets a From 3adf09492426243554fa76b582ac4c99eead472b Mon Sep 17 00:00:00 2001 From: PlatformSREEngineer Date: Wed, 5 Aug 2026 03:15:49 +0000 Subject: [PATCH 4/9] fix(github-webhook): stop racing action(tx) against the deadline, bound the lock-exhaustion fallback recheck (BLO-21582) Ally review follow-up on this branch (PR #1003, review at issuecomment-5182720378) found two still-live gaps in the previous commit's withPrReviewerTaskLock: 1. The deadline raced the WHOLE transaction returned by db.transaction(), including action(tx) itself, not just pool checkout + the advisory-lock probe. If the lock was acquired near the deadline, the handler could abandon a live action() that later commits a wake -- while the catch block, having observed no wake yet, recorded received+dead_lettered and answered reviewerWakeFired: false. The late action then incremented received again and queued the wake, producing both a false dead-letter and broken funnel counts. Fixed by resolving a dedicated `lockProbeSettled` promise the instant the pg_try_advisory_xact_lock probe itself settles, before action(tx) ever runs, and racing ONLY that against the deadline. Once the probe reports the lock is ours, we await the in-flight transaction (running action) to completion unconditionally instead of racing it further. 2. The lock-exhaustion fallback recheck (findExistingPrReviewerWake / findActivePrReviewerForTask / selectPrReviewerAgentId) ran outside any deadline. A saturated pool that timed out the lock probe could just as easily stall these reads indefinitely, defeating the whole point of the request-wide budget and GitHub's response-window protection. Fixed with a small additional budget (PR_REVIEWER_TASK_LOCK_FALLBACK_BUDGET_MS, 1s) appended to the lock deadline. A timeout on either read is treated as "unknown" -- distinct from a confirmed "no equivalent wake" / "no active reviewer" -- and falls through to the pre-existing conservative default (record the delivery as lost) rather than blocking the response further. Two new integration tests: - Delays heartbeat.wakeup() (via a slow penstockAvailabilityGate) past the 4s lock budget after the advisory lock is acquired with zero contention, and asserts a single terminal outcome (reviewerWakeFired: true, one received/queued pair, no dead-letter) with no metric movement after the response is sent. - Forces the lock probe to exhaust its budget via genuine advisory-lock contention AND separately blocks the fallback recheck's own read with an ACCESS EXCLUSIVE table lock on agent_wakeup_requests held far longer than the fallback budget -- proving the bound, not the lock's eventual release, is what lets the response return (well under the 8s both locks are held for), while still recording the delivery as lost. Co-Authored-By: Claude Sonnet 5 --- server/src/__tests__/github-webhook.test.ts | 222 ++++++++++++++++++++ server/src/routes/github-webhook.ts | 199 ++++++++++++++---- 2 files changed, 377 insertions(+), 44 deletions(-) diff --git a/server/src/__tests__/github-webhook.test.ts b/server/src/__tests__/github-webhook.test.ts index 456946f7bfd4..b8f537525d01 100644 --- a/server/src/__tests__/github-webhook.test.ts +++ b/server/src/__tests__/github-webhook.test.ts @@ -2547,6 +2547,35 @@ describeEmbeddedPostgres("github-webhook route", () => { }; } + // Blocks any plain SELECT against `tableName` on the app's own `db` pool + // for up to `holdMs` -- unlike the advisory lock above (which only + // contends with itself), this simulates a genuinely stalled read on the + // exact query the lock-exhaustion fallback recheck issues, regardless of + // whether the real-world cause is pool-checkout starvation or something + // else blocking the connection (BLO-21582 review follow-up: "cover + // actual pool-checkout starvation, not only advisory-lock contention"). + async function holdExclusiveTableLock(tableName: string, holdMs: number) { + let releaseHeld: () => void = () => {}; + const held = new Promise((resolve) => { + releaseHeld = resolve; + }); + const acquired = new Promise((resolveAcquired, rejectAcquired) => { + void lockDb + .transaction(async (tx) => { + await tx.execute(sql.raw(`LOCK TABLE "${tableName}" IN ACCESS EXCLUSIVE MODE`)); + resolveAcquired(); + await held; + }) + .catch(rejectAcquired); + }); + await acquired; + const timer = setTimeout(releaseHeld, holdMs); + return () => { + clearTimeout(timer); + releaseHeld(); + }; + } + it( "recovers a reviewer wake once a transient lock-holder releases within the retry budget", async () => { @@ -2789,6 +2818,199 @@ describeEmbeddedPostgres("github-webhook route", () => { }, 10_000, ); + + it( + "awaits an in-flight wake to completion once the lock is already acquired, instead of abandoning " + + "it at the deadline (BLO-21582 review follow-up: racing action(tx) itself, not just the lock probe, " + + "could abandon a live transaction that later commits a wake the response already claimed was lost)", + async () => { + const reviewerAgentId = randomUUID(); + const { companyId } = await seedCompanyAndAgent(); + await db.insert(agents).values({ + id: reviewerAgentId, + companyId, + name: "Ally", + role: "engineer", + status: "idle", + adapterType: "claude_k8s", + adapterConfig: {}, + runtimeConfig: {}, + permissions: {}, + }); + + const prNumber = 21582004; + + // No advisory-lock contention here at all: the lock probe resolves + // near-instantly. Instead, `heartbeat.wakeup()` -- which runs INSIDE + // the lock-guarded action, after the lock is already acquired -- is + // held open past PR_REVIEWER_TASK_LOCK_BUDGET_MS (4s in + // github-webhook.ts) by a penstock-availability gate that only + // resolves once the test releases it. The buggy version of + // withPrReviewerTaskLock raced the WHOLE transaction (lock probe + + // action) against the deadline, so it would abandon this still-live + // transaction at 4s and answer `reviewerWakeFired: false` -- + // even though the action goes on to actually commit the wake a + // moment later, producing a false dead-letter and an uncounted + // extra `received`/`queued` pair after the response was already + // sent. The fix must instead await the action to completion once + // the lock is acquired, however long past the deadline it runs. + let releaseGate: () => void = () => {}; + const gateBlocked = new Promise((resolve) => { + releaseGate = resolve; + }); + const delayedPenstockGate: NonNullable["penstockAvailabilityGate"] = { + checkAdapter: async () => { + await gateBlocked; + return { allow: true }; + }, + _resetForTesting: () => {}, + }; + + const app = buildApp({ + prReviewerAgentId: reviewerAgentId, + heartbeatOptions: { penstockAvailabilityGate: delayedPenstockGate }, + }); + const payload = { + action: "opened", + pull_request: { + number: prNumber, + title: "Reviewer wake action-delayed-past-deadline regression", + body: null, + head: { ref: "fix/blo-21582-action-delay", sha: "actiondelaysha" }, + }, + repository: { full_name: "Blockcast/paperclip" }, + }; + const { body, signature } = signedRequest(payload); + const beforeDeadLettered = await deliveryCount("dead_lettered"); + const beforeQueued = await deliveryCount("queued"); + const beforeReceived = await deliveryCount("received"); + + const responsePromise = request(app) + .post("/api/webhooks/github") + .set("x-github-event", "pull_request") + .set("x-hub-signature-256", signature) + .set("x-github-delivery", "delivery-blo-21582-action-delay") + .set("content-type", "application/json") + .send(body); + + // Release the gate well after PR_REVIEWER_TASK_LOCK_BUDGET_MS (4s) + // has elapsed. Only the fix under test -- not racing an + // already-acquired lock's action against the deadline -- lets this + // request wait that long and still resolve with the real outcome. + await new Promise((resolve) => setTimeout(resolve, 4_300)); + releaseGate(); + + const res = await responsePromise; + + expect(res.status).toBe(200); + expect(res.body).toMatchObject({ reviewerWakeFired: true }); + + // Exactly one terminal outcome: received -> queued, no dead-letter. + expect(await deliveryCount("received")).toBe(beforeReceived + 1); + expect(await deliveryCount("queued")).toBe(beforeQueued + 1); + expect(await deliveryCount("dead_lettered")).toBe(beforeDeadLettered); + + const queuedWakes = await db + .select({ status: agentWakeupRequests.status }) + .from(agentWakeupRequests) + .where( + and( + eq(agentWakeupRequests.agentId, reviewerAgentId), + eq(agentWakeupRequests.idempotencyKey, `pr_review:Blockcast/paperclip:${prNumber}:github_pr_opened`), + eq(agentWakeupRequests.status, "queued"), + ), + ); + expect(queuedWakes).toHaveLength(1); + + // No post-response mutation: the counters and the wake row are + // already final by the time the response was sent, so waiting + // longer must not move them again. + await new Promise((resolve) => setTimeout(resolve, 250)); + expect(await deliveryCount("received")).toBe(beforeReceived + 1); + expect(await deliveryCount("queued")).toBe(beforeQueued + 1); + expect(await deliveryCount("dead_lettered")).toBe(beforeDeadLettered); + }, + 15_000, + ); + + it( + "bounds the lock-exhaustion fallback recheck instead of stalling behind the same blocked connection, " + + "and still records the loss (BLO-21582 review follow-up: 'the fallback queries are outside the " + + "deadline... defeating the end-to-end bound')", + async () => { + const reviewerAgentId = randomUUID(); + const { companyId } = await seedCompanyAndAgent(); + await db.insert(agents).values({ + id: reviewerAgentId, + companyId, + name: "Ally", + role: "engineer", + status: "idle", + adapterType: "claude_k8s", + adapterConfig: {}, + runtimeConfig: {}, + permissions: {}, + }); + + const prNumber = 21582005; + const taskKey = `pr_review:Blockcast/paperclip:${prNumber}`; + + // Force the lock-acquisition attempt to exhaust its own budget... + const releaseLock = await holdAdvisoryLock(taskKey, 8_000); + // ...and separately block the unlocked fallback recheck's own read + // (findExistingPrReviewerWake, which selects from + // agent_wakeup_requests) well past + // PR_REVIEWER_TASK_LOCK_FALLBACK_BUDGET_MS (1s) -- a stalled + // connection on that query, not more advisory-lock contention, is + // exactly the gap the review flagged. + const releaseTableLock = await holdExclusiveTableLock("agent_wakeup_requests", 8_000); + + const app = buildApp({ prReviewerAgentId: reviewerAgentId }); + const payload = { + action: "opened", + pull_request: { + number: prNumber, + title: "Reviewer wake fallback-recheck-timeout regression", + body: null, + head: { ref: "fix/blo-21582-fallback-timeout", sha: "fallbacktimeoutsha" }, + }, + repository: { full_name: "Blockcast/paperclip" }, + }; + const { body, signature } = signedRequest(payload); + const beforeDeadLettered = await deliveryCount("dead_lettered"); + const beforeQueued = await deliveryCount("queued"); + const beforeReceived = await deliveryCount("received"); + + const startedAt = Date.now(); + let res; + try { + res = await request(app) + .post("/api/webhooks/github") + .set("x-github-event", "pull_request") + .set("x-hub-signature-256", signature) + .set("x-github-delivery", "delivery-blo-21582-fallback-timeout") + .set("content-type", "application/json") + .send(body); + } finally { + releaseLock(); + releaseTableLock(); + } + const elapsedMs = Date.now() - startedAt; + + // Lock budget (4s) + fallback budget (1s) must bound the response + // well under the 8s the table lock and advisory lock are held for. + // Without the fallback bound, this would not resolve until ~8s. + expect(elapsedMs).toBeLessThan(7_000); + + expect(res.status).toBe(200); + expect(res.body).toMatchObject({ reviewerWakeFired: false }); + + expect(await deliveryCount("received")).toBe(beforeReceived + 1); + expect(await deliveryCount("dead_lettered")).toBe(beforeDeadLettered + 1); + expect(await deliveryCount("queued")).toBe(beforeQueued); + }, + 15_000, + ); }); diff --git a/server/src/routes/github-webhook.ts b/server/src/routes/github-webhook.ts index d4dd6fbc641c..c3f0df1bdbb9 100644 --- a/server/src/routes/github-webhook.ts +++ b/server/src/routes/github-webhook.ts @@ -75,6 +75,17 @@ type PrReviewerSelectionDb = Pick; // trigger the redelivery-under-contention loop this path exists to absorb. const PR_REVIEWER_TASK_LOCK_BUDGET_MS = 4_000; const PR_REVIEWER_TASK_LOCK_RETRY_MS = 25; +// Bounds the lock-exhaustion fallback recheck (findExistingPrReviewerWake / +// findActivePrReviewerForTask / selectPrReviewerAgentId) that runs after +// PR_REVIEWER_TASK_LOCK_BUDGET_MS is already spent. Those reads use the same +// pool that just failed to check out a connection in time, so a saturated +// pool can stall them exactly as it stalled the lock probe -- without a +// bound of their own they would defeat the whole point of the budget above +// (BLO-21582 review follow-up: "the fallback queries are outside the +// deadline"). Small on purpose: these are single indexed-row reads, and a +// timeout here just falls back to the pre-existing conservative default +// (record the delivery as lost) rather than confirming a no-op. +const PR_REVIEWER_TASK_LOCK_FALLBACK_BUDGET_MS = 1_000; export interface GithubWebhookConfig { /** @@ -1564,41 +1575,76 @@ async function withPrReviewerTaskLock( // Do not block a pooled connection while another request owns the lock: // the winner needs a second connection for heartbeat's enqueue transaction. // - // Race pool checkout + the lock probe against the remaining budget: - // `db.transaction()` alone does not respect `deadline` (a stalled pool - // checkout under contention could block well past it), so bound it - // explicitly here rather than only checking elapsed time after it - // resolves (BLO-21582 review follow-up). Attach a `.catch` so a - // transaction that eventually settles after we've stopped waiting on it - // doesn't surface as an unhandled rejection; it still commits or rolls - // back on its own connection, we've simply moved on. + // Race pool checkout + the lock probe -- and ONLY that -- against the + // remaining budget: `db.transaction()` alone does not respect `deadline` + // (a stalled pool checkout under contention could block well past it), + // so bound it explicitly here rather than only checking elapsed time + // after it resolves. `settleLockProbe` below fires the instant the probe + // query itself settles, before `action(tx)` ever runs, so the race can + // never observe a still-running `action` as "not acquired" (BLO-21582 + // review follow-up: racing the whole transaction -- including + // `action(tx)` -- let the handler abandon a live transaction that could + // still commit a wake after the deadline had already been reported as a + // lock-acquisition failure, producing a false dead-letter AND a second, + // uncounted wake). + let settleLockProbe: (outcome: { acquired: boolean } | { error: unknown }) => void; + const lockProbeSettled = new Promise<{ acquired: boolean } | { error: unknown }>((resolve) => { + settleLockProbe = resolve; + }); const transactionPromise = db.transaction(async (tx) => { - const rows = await tx.execute( - sql`select pg_try_advisory_xact_lock(hashtextextended(${taskKey}, 0)) as acquired`, - ); - const row = Array.isArray(rows) ? rows[0] : null; - if ( - !row || - typeof row !== "object" || - (row as Record).acquired !== true - ) { + let acquired: boolean; + try { + const rows = await tx.execute( + sql`select pg_try_advisory_xact_lock(hashtextextended(${taskKey}, 0)) as acquired`, + ); + const row = Array.isArray(rows) ? rows[0] : null; + acquired = + !!row && typeof row === "object" && (row as Record).acquired === true; + } catch (error) { + settleLockProbe({ error }); + throw error; + } + settleLockProbe({ acquired }); + if (!acquired) { return { acquired: false as const }; } + // The lock is ours from here on: no further racing against the + // deadline, even if `action` runs long. Abandoning this branch after + // this point would still let the transaction commit on its own + // connection with nobody accounting for the outcome. return { acquired: true as const, value: await action(tx) }; }); + const probeOutcome = await Promise.race([ + lockProbeSettled, + new Promise<{ acquired: false }>((resolve) => { + setTimeout(() => resolve({ acquired: false }), remainingMs); + }), + ]); + if ("error" in probeOutcome) { + // The probe query itself failed (not a lock-acquisition timeout) -- + // this is a genuine DB error, not ours to retry. Swallow the + // transaction's own rejection (same error, already surfaced here) so + // it doesn't also report as an unhandled rejection. + transactionPromise.catch(() => {}); + throw probeOutcome.error; + } + if (probeOutcome.acquired) { + // Lock acquisition already resolved inside the transaction; await the + // in-flight `action(tx)` to completion instead of racing it further. + const outcome = (await transactionPromise) as { acquired: true; value: T }; + return outcome.value; + } + // The probe did not settle within budget (most likely a stalled pool + // checkout): move on without waiting further, but log if the abandoned + // transaction eventually does settle so that's still observable. It + // still commits or rolls back on its own connection regardless of + // whether we're still waiting on it. transactionPromise.catch((err) => { logger.warn( { err, taskKey }, "github webhook reviewer wake lock transaction settled after its retry budget was abandoned", ); }); - const outcome = await Promise.race([ - transactionPromise, - new Promise<{ acquired: false }>((resolve) => { - setTimeout(() => resolve({ acquired: false }), remainingMs); - }), - ]); - if (outcome.acquired) return outcome.value; if (Date.now() >= deadline) { throw new PrReviewerTaskLockTimeoutError(taskKey); } @@ -1606,6 +1652,31 @@ async function withPrReviewerTaskLock( } } +// Sentinel distinct from any real query result (including `null`, which +// `findExistingPrReviewerWake`/`findActivePrReviewerForTask` return to mean +// "no row" -- a legitimate, confident answer that must NOT be confused with +// "we don't know because the read didn't finish in time"). +const FALLBACK_RECHECK_TIMED_OUT = Symbol("pr-reviewer-wake-fallback-recheck-timed-out"); + +// Bounds one lock-exhaustion fallback read against `deadlineMs` (BLO-21582 +// review follow-up). A timeout here must propagate as "unknown", not as a +// false "confirmed no active reviewer" -- the caller has to keep that +// distinction to avoid silently swallowing a real loss just because the +// recheck itself couldn't get a connection in time. +async function boundedFallbackRead( + promise: Promise, + deadlineMs: number, +): Promise { + const remainingMs = deadlineMs - Date.now(); + if (remainingMs <= 0) return FALLBACK_RECHECK_TIMED_OUT; + return Promise.race([ + promise, + new Promise((resolve) => { + setTimeout(() => resolve(FALLBACK_RECHECK_TIMED_OUT), remainingMs); + }), + ]); +} + // Shared between the lock-guarded idempotency check inside // withPrReviewerTaskLock's closure and the unlocked recheck on lock // exhaustion below (BLO-21582 review follow-up) -- same query, same meaning, @@ -2248,42 +2319,82 @@ export function githubWebhookRoutes(db: Db, config: GithubWebhookConfig) { // and no-active-reviewer gates use above instead of a false // dead-letter alert, while contention with no such evidence still // counts as loss below. - const equivalentWake = await findExistingPrReviewerWake( - db, - reviewerAgentIds, - idempotencyKey, - idempotentStatuses, + // + // Both reads below are bounded by PR_REVIEWER_TASK_LOCK_FALLBACK_BUDGET_MS + // (BLO-21582 review follow-up): they share the same pool that just + // failed to check out a connection in time for the lock probe, so + // an unbounded synchronous read here could stall this response + // exactly as the lock probe did, defeating the deadline's whole + // purpose. A timeout is treated as "unknown" -- NOT as "confirmed + // no equivalent wake" / "confirmed no active reviewer" -- and falls + // straight through to the pre-existing conservative default below + // (record it as lost) rather than risking a false no-op on one side + // or an unbounded wait on the other. + const fallbackDeadline = lockDeadline + PR_REVIEWER_TASK_LOCK_FALLBACK_BUDGET_MS; + const equivalentWake = await boundedFallbackRead( + findExistingPrReviewerWake(db, reviewerAgentIds, idempotencyKey, idempotentStatuses), + fallbackDeadline, ); - if (equivalentWake) { - logger.info( + if (equivalentWake === FALLBACK_RECHECK_TIMED_OUT) { + logger.warn( { - equivalentWakeId: equivalentWake.id, - equivalentWakeStatus: equivalentWake.status, - idempotencyKey, + taskKey: reviewerTaskKey, event: eventName, deliveryId, wakeReason: context.wakeReason, prNumber: context.prNumber, repoFullName: context.repoFullName, }, - "github webhook reviewer wake lock exhausted, but an equivalent wake is already durable: not counting as a lost wake", + "github webhook reviewer wake lock-exhaustion recheck (existing wake) timed out waiting for a " + + "database read; recording the delivery as lost rather than risking an unbounded synchronous read", ); - return false; - } - const equivalentReviewerAgentId = - (await findActivePrReviewerForTask(db, reviewerAgentIds, reviewerTaskKey)) ?? - (await selectPrReviewerAgentId(db, reviewerAgentIds, reviewerTaskKey)); - if (!equivalentReviewerAgentId) { - logger.warn( + } else if (equivalentWake) { + logger.info( { - configuredReviewerCount: reviewerAgentIds.length, + equivalentWakeId: equivalentWake.id, + equivalentWakeStatus: equivalentWake.status, + idempotencyKey, event: eventName, + deliveryId, + wakeReason: context.wakeReason, prNumber: context.prNumber, repoFullName: context.repoFullName, }, - "github webhook reviewer wake lock exhausted, but no configured reviewer is active: not counting as a lost wake", + "github webhook reviewer wake lock exhausted, but an equivalent wake is already durable: not counting as a lost wake", ); return false; + } else { + const equivalentReviewerAgentId = await boundedFallbackRead( + (async () => + (await findActivePrReviewerForTask(db, reviewerAgentIds, reviewerTaskKey)) ?? + (await selectPrReviewerAgentId(db, reviewerAgentIds, reviewerTaskKey)))(), + fallbackDeadline, + ); + if (equivalentReviewerAgentId === FALLBACK_RECHECK_TIMED_OUT) { + logger.warn( + { + taskKey: reviewerTaskKey, + event: eventName, + deliveryId, + wakeReason: context.wakeReason, + prNumber: context.prNumber, + repoFullName: context.repoFullName, + }, + "github webhook reviewer wake lock-exhaustion recheck (active reviewer) timed out waiting for a " + + "database read; recording the delivery as lost rather than risking an unbounded synchronous read", + ); + } else if (!equivalentReviewerAgentId) { + logger.warn( + { + configuredReviewerCount: reviewerAgentIds.length, + event: eventName, + prNumber: context.prNumber, + repoFullName: context.repoFullName, + }, + "github webhook reviewer wake lock exhausted, but no configured reviewer is active: not counting as a lost wake", + ); + return false; + } } // BLO-21582: an exhausted lock-acquisition timeout happens before // the lock-guarded closure can record `received`, and neither From d2866456f1685c2748a957135d254b728882e0be Mon Sep 17 00:00:00 2001 From: Omar Ramadan Date: Tue, 4 Aug 2026 20:36:50 -0700 Subject: [PATCH 5/9] fix(apps): keep empty review queues fresh --- ui/src/pages/apps/ReviewQueueCard.test.tsx | 19 +++++++++++++++---- ui/src/pages/apps/ReviewQueueCard.tsx | 18 +++++++++++++++--- 2 files changed, 30 insertions(+), 7 deletions(-) diff --git a/ui/src/pages/apps/ReviewQueueCard.test.tsx b/ui/src/pages/apps/ReviewQueueCard.test.tsx index bca33f7fa807..90cf8239b02f 100644 --- a/ui/src/pages/apps/ReviewQueueCard.test.tsx +++ b/ui/src/pages/apps/ReviewQueueCard.test.tsx @@ -263,8 +263,11 @@ describe("ReviewQueueCard", () => { }); }); - it("refreshes an empty mounted queue so externally-created pending requests appear", async () => { - listActionRequestsMock.mockResolvedValue({ actionRequests: [] }); + it("keeps refreshing an empty mounted queue so externally-created pending requests appear", async () => { + let pendingCreated = false; + listActionRequestsMock.mockImplementation(async () => ({ + actionRequests: pendingCreated ? [pendingRequest()] : [], + })); await render(); @@ -273,11 +276,19 @@ describe("ReviewQueueCard", () => { expect(document.body.textContent).toContain("Nothing is waiting for your OK right now."); }); - listActionRequestsMock.mockResolvedValue({ actionRequests: [pendingRequest()] }); + await vi.waitFor( + () => { + expect(listActionRequestsMock.mock.calls.length).toBeGreaterThanOrEqual(3); + expect(document.body.textContent).toContain("Nothing is waiting for your OK right now."); + }, + { timeout: 3_500 }, + ); + + pendingCreated = true; await vi.waitFor( () => { - expect(listActionRequestsMock).toHaveBeenCalledTimes(3); + expect(listActionRequestsMock.mock.calls.length).toBeGreaterThanOrEqual(4); expect(buttonContaining("Allow once")).toBeTruthy(); }, { timeout: 3_500 }, diff --git a/ui/src/pages/apps/ReviewQueueCard.tsx b/ui/src/pages/apps/ReviewQueueCard.tsx index dbeea750a0d2..2fa5657168c1 100644 --- a/ui/src/pages/apps/ReviewQueueCard.tsx +++ b/ui/src/pages/apps/ReviewQueueCard.tsx @@ -42,12 +42,16 @@ export function ReviewQueueCard({ enabled: !!selectedCompanyId, staleTime: 0, refetchOnMount: false, - refetchInterval: 20_000, + refetchInterval: (state) => { + const visibleItems = filterActionRequests(state.state.data?.actionRequests, connectionId); + return emptyState !== "hidden" && visibleItems.length === 0 + ? VISIBLE_EMPTY_QUEUE_REFRESH_MS + : 20_000; + }, }); const items = useMemo(() => { - const all = query.data?.actionRequests ?? []; - return connectionId ? all.filter((item) => item.connectionId === connectionId) : all; + return filterActionRequests(query.data?.actionRequests, connectionId); }, [query.data, connectionId]); useEffect(() => { @@ -96,6 +100,14 @@ export function ReviewQueueCard({ ); } +function filterActionRequests( + actionRequests: ToolActionRequestListItem[] | undefined, + connectionId?: string, +) { + const all = actionRequests ?? []; + return connectionId ? all.filter((item) => item.connectionId === connectionId) : all; +} + function ReviewRow({ companyId, item }: { companyId: string; item: ToolActionRequestListItem }) { const queryClient = useQueryClient(); const { pushToast } = useToast(); From 573c9ff820d7d165d6f9a50d565208381bb4be2a Mon Sep 17 00:00:00 2001 From: Omar Ramadan Date: Wed, 5 Aug 2026 17:26:34 -0700 Subject: [PATCH 6/9] fix(github-webhook): skip late reviewer wake lock actions --- server/src/__tests__/github-webhook.test.ts | 34 +++++++++++++++++++++ server/src/routes/github-webhook.ts | 9 ++++++ 2 files changed, 43 insertions(+) diff --git a/server/src/__tests__/github-webhook.test.ts b/server/src/__tests__/github-webhook.test.ts index b8f537525d01..dce16fb6b21e 100644 --- a/server/src/__tests__/github-webhook.test.ts +++ b/server/src/__tests__/github-webhook.test.ts @@ -42,6 +42,7 @@ import { __test_resolveEventContext, __test_shouldFirePrReviewerWake, __test_verifyGithubSignature, + __test_withPrReviewerTaskLock, githubWebhookRoutes, type GithubWebhookConfig, } from "../routes/github-webhook.js"; @@ -1157,6 +1158,39 @@ describe("github-webhook pure helpers", () => { expect(__test_resolveDependabotAlertContext({ action: "created", alert: {} })).toBeNull(); expect(__test_resolveDependabotAlertContext({ action: "created" })).toBeNull(); }); + + it("does not run reviewer wake action when lock acquisition settles after the deadline", async () => { + let actionCalled = false; + let probeStarted = false; + const fakeDb = { + transaction: async ( + callback: (tx: { execute: () => Promise> }) => Promise, + ) => + callback({ + execute: async () => { + probeStarted = true; + await new Promise((resolve) => setTimeout(resolve, 30)); + return [{ acquired: true }]; + }, + }), + }; + + await expect( + __test_withPrReviewerTaskLock( + fakeDb as never, + "pr_review:Blockcast/paperclip:21582006", + Date.now() + 5, + async () => { + actionCalled = true; + return "queued"; + }, + ), + ).rejects.toThrow("timed out acquiring PR reviewer task assignment lock"); + + await new Promise((resolve) => setTimeout(resolve, 50)); + expect(probeStarted).toBe(true); + expect(actionCalled).toBe(false); + }); }); describeEmbeddedPostgres("github-webhook route", () => { diff --git a/server/src/routes/github-webhook.ts b/server/src/routes/github-webhook.ts index c3f0df1bdbb9..bf51a452c439 100644 --- a/server/src/routes/github-webhook.ts +++ b/server/src/routes/github-webhook.ts @@ -1604,6 +1604,14 @@ async function withPrReviewerTaskLock( settleLockProbe({ error }); throw error; } + if (acquired && Date.now() >= deadline) { + logger.warn( + { taskKey }, + "github webhook reviewer wake lock was acquired after its retry deadline; skipping reviewer wake action", + ); + settleLockProbe({ acquired: false }); + return { acquired: false as const }; + } settleLockProbe({ acquired }); if (!acquired) { return { acquired: false as const }; @@ -3037,6 +3045,7 @@ export const __test_buildPrReviewerWakeIdempotencyKey = buildPrReviewerWakeIdemp export const __test_prReviewerWakeIdempotencyScope = prReviewerWakeIdempotencyScope; export const __test_idempotentWakeStatuses = idempotentWakeStatuses; export const __test_buildPrReviewerTaskKey = buildPrReviewerTaskKey; +export const __test_withPrReviewerTaskLock = withPrReviewerTaskLock; export const __test_buildDependabotAlertIssueBody = buildDependabotAlertIssueBody; export const __test_resolveDependabotAlertContext = resolveDependabotAlertContext; export const __test_hasActionablePrReviewFeedback = hasActionablePrReviewFeedback; From 6807e75d097e8d08f27f33fb680321d0da7299af Mon Sep 17 00:00:00 2001 From: PlatformSREEngineer Date: Fri, 7 Aug 2026 08:33:47 +0000 Subject: [PATCH 7/9] fix(github-webhook): bound the lock-probe/fallback-read connection itself, not just the promise (BLO-21582) Ally's review on #1003 (still-present, 2nd pass) flagged that withPrReviewerTaskLock's abandoned db.transaction() and boundedFallbackRead's abandoned read promise keep running against the pool after the webhook responds -- Promise.race only stops us from awaiting them, postgres.js never exposes the internal query used to acquire a pooled connection, so an abandoned attempt still lands on a freed connection later and executes its BEGIN/probe/rollback (or SELECT), adding detached work behind the exact pool saturation this code exists to survive. Replace both with sql.reserve()-based connection acquisition, which IS genuinely boundable: it issues no query until code explicitly does so on the connection it returns, so an abandoned reservation is released the instant it lands, before ever running a query. Once a connection is reserved it is exclusively ours, so: - withPrReviewerTaskLock drives BEGIN/probe/action/COMMIT itself on the reserved connection instead of through db.transaction() -- preserving the "run action to completion once acquired" guarantee, and Omar's 573c9ff8 late-acquisition guard (skip action if the probe settles after deadline), restated for the new mechanism. - boundedFallbackRead reserves a connection, then bounds the read itself with SET LOCAL statement_timeout (DB-side cancellation) since a fallback read has no self-healing value in running past its budget the way an acquired lock's action does. Added a regression test that saturates the pool with held transactions, holds contention THROUGH the response and past it, and asserts the funnel counters (and a fresh reservation) stay quiet before releasing -- addressing the review's note that the existing tests released their blocking locks immediately after the response and therefore didn't prove cleanup while contention remained. Verified this test fails against the prior implementation (a duplicate, uncounted `received` after the response already reported dead_lettered) and passes against this one. Adapted Omar's fakeDb-based unit test (573c9ff8) to fake the new $client.reserve() boundary instead of db.transaction(), since withPrReviewerTaskLock no longer goes through drizzle's transaction wrapper at all; same scenario and assertions. All 119 tests in github-webhook.test.ts pass; typecheck clean (the withdrawApprovalSchema errors in approvals.ts/openapi.ts are pre-existing on origin/fix/blo-21582-reviewer-wake-lock-timeout, unrelated to this change). Co-Authored-By: Claude Sonnet 5 --- server/src/__tests__/github-webhook.test.ts | 159 ++++++++++++- server/src/routes/github-webhook.ts | 236 +++++++++++++------- 2 files changed, 299 insertions(+), 96 deletions(-) diff --git a/server/src/__tests__/github-webhook.test.ts b/server/src/__tests__/github-webhook.test.ts index dce16fb6b21e..75b5558e5b50 100644 --- a/server/src/__tests__/github-webhook.test.ts +++ b/server/src/__tests__/github-webhook.test.ts @@ -1160,20 +1160,31 @@ describe("github-webhook pure helpers", () => { }); it("does not run reviewer wake action when lock acquisition settles after the deadline", async () => { + // Faked at the `$client.reserve()` boundary (BLO-21582 review + // follow-up), not `db.transaction()` -- withPrReviewerTaskLock no longer + // goes through drizzle's transaction wrapper at all; it reserves a raw + // connection and drives BEGIN/probe/COMMIT/ROLLBACK itself so an + // abandoned reservation can be released before ever issuing a query. + // This fake reproduces the same "probe settles after the deadline" + // scenario one level lower: reservation resolves immediately (nothing + // ours to bound there), the probe query itself is what's slow. let actionCalled = false; let probeStarted = false; - const fakeDb = { - transaction: async ( - callback: (tx: { execute: () => Promise> }) => Promise, - ) => - callback({ - execute: async () => { - probeStarted = true; - await new Promise((resolve) => setTimeout(resolve, 30)); - return [{ acquired: true }]; - }, - }), - }; + let callIndex = 0; + const fakeReservedConnection = Object.assign( + async (_strings: TemplateStringsArray, ..._values: unknown[]) => { + callIndex += 1; + if (callIndex === 1) return []; // begin + if (callIndex === 2) { + probeStarted = true; + await new Promise((resolve) => setTimeout(resolve, 30)); + return [{ acquired: true }]; + } + return []; // rollback + }, + { release: () => {} }, + ); + const fakeDb = { $client: { reserve: async () => fakeReservedConnection } }; await expect( __test_withPrReviewerTaskLock( @@ -3045,6 +3056,130 @@ describeEmbeddedPostgres("github-webhook route", () => { }, 15_000, ); + + it( + "leaves no detached lock-probe running once genuine pool-checkout contention outlasts the deadline, proven while " + + "contention is still held rather than after releasing it (BLO-21582 review follow-up: 'the current regression " + + "test releases its blocking locks immediately after the response and therefore does not prove cleanup while " + + "contention remains')", + async () => { + const reviewerAgentId = randomUUID(); + const { companyId } = await seedCompanyAndAgent(); + await db.insert(agents).values({ + id: reviewerAgentId, + companyId, + name: "Ally", + role: "engineer", + status: "idle", + adapterType: "claude_k8s", + adapterConfig: {}, + runtimeConfig: {}, + permissions: {}, + }); + + const prNumber = 21582006; + + // Saturate every connection in the app's own `db` pool with held + // transactions -- unlike holdAdvisoryLock/holdExclusiveTableLock + // above (which block a query running on an available connection), + // this blocks the pool CHECKOUT itself, reproducing the "stalled + // pool checkout" scenario withPrReviewerTaskLock's reservation + // bound targets, not merely lock contention. + const poolSize = Number(db.$client.options.max ?? 10); + const releasers: Array<() => void> = []; + const held: Array> = []; + for (let i = 0; i < poolSize; i++) { + let release: () => void = () => {}; + const gate = new Promise((resolve) => { + release = resolve; + }); + releasers.push(release); + held.push( + db.transaction(async (tx) => { + await tx.execute(sql`select 1`); + await gate; + }), + ); + } + // Let every held transaction actually claim a connection before + // firing the webhook, so the pool is genuinely saturated when it + // tries to reserve one. + await new Promise((resolve) => setTimeout(resolve, 200)); + + const app = buildApp({ prReviewerAgentId: reviewerAgentId }); + const payload = { + action: "opened", + pull_request: { + number: prNumber, + title: "Reviewer wake pool-checkout-stall regression", + body: null, + head: { ref: "fix/blo-21582-pool-checkout-stall", sha: "poolstallsha" }, + }, + repository: { full_name: "Blockcast/paperclip" }, + }; + const { body, signature } = signedRequest(payload); + const beforeDeadLettered = await deliveryCount("dead_lettered"); + const beforeReceived = await deliveryCount("received"); + const beforeQueued = await deliveryCount("queued"); + + try { + const startedAt = Date.now(); + const res = await request(app) + .post("/api/webhooks/github") + .set("x-github-event", "pull_request") + .set("x-hub-signature-256", signature) + .set("x-github-delivery", "delivery-blo-21582-pool-checkout-stall") + .set("content-type", "application/json") + .send(body); + const elapsedMs = Date.now() - startedAt; + + expect(res.status).toBe(200); + expect(res.body).toMatchObject({ reviewerWakeFired: false }); + // Bounded by PR_REVIEWER_TASK_LOCK_BUDGET_MS (4s) + + // PR_REVIEWER_TASK_LOCK_FALLBACK_BUDGET_MS (1s); the pool stays + // saturated the whole time, so the fallback recheck's own + // reservation attempt times out too. + expect(elapsedMs).toBeGreaterThanOrEqual(3_900); + expect(elapsedMs).toBeLessThan(7_000); + + expect(await deliveryCount("received")).toBe(beforeReceived + 1); + expect(await deliveryCount("dead_lettered")).toBe(beforeDeadLettered + 1); + expect(await deliveryCount("queued")).toBe(beforeQueued); + + // The pool is STILL saturated here -- this is the assertion the + // review flagged as missing. If the abandoned reservation were + // still queued and later ran its BEGIN/probe/action on a freed + // connection (the pre-fix behavior), releasing exactly one + // connection below would let it complete and move these counters + // again, after the response already reported dead_lettered. + await new Promise((resolve) => setTimeout(resolve, 500)); + expect(await deliveryCount("received")).toBe(beforeReceived + 1); + expect(await deliveryCount("dead_lettered")).toBe(beforeDeadLettered + 1); + expect(await deliveryCount("queued")).toBe(beforeQueued); + + releasers[0](); + releasers[0] = () => {}; + await new Promise((resolve) => setTimeout(resolve, 500)); + expect(await deliveryCount("received")).toBe(beforeReceived + 1); + expect(await deliveryCount("dead_lettered")).toBe(beforeDeadLettered + 1); + expect(await deliveryCount("queued")).toBe(beforeQueued); + + // A fresh reservation must be servable promptly off the one + // connection just freed -- if the abandoned reservation were + // still ahead of it in the pool's queue doing real work, this + // would stall behind it instead of resolving immediately. + const probeStartedAt = Date.now(); + const probe = await db.$client.reserve(); + const probeElapsedMs = Date.now() - probeStartedAt; + probe.release(); + expect(probeElapsedMs).toBeLessThan(1_000); + } finally { + for (const release of releasers) release(); + await Promise.allSettled(held); + } + }, + 20_000, + ); }); diff --git a/server/src/routes/github-webhook.ts b/server/src/routes/github-webhook.ts index bf51a452c439..549c6f994bb1 100644 --- a/server/src/routes/github-webhook.ts +++ b/server/src/routes/github-webhook.ts @@ -37,6 +37,8 @@ import { issues, } from "@paperclipai/db"; import { and, desc, eq, inArray, isNull, sql } from "drizzle-orm"; +import { drizzle as drizzlePgFromClient } from "drizzle-orm/postgres-js"; +import { findPgError } from "../lib/db-retry.js"; import { heartbeatService, type HeartbeatServiceOptions } from "../services/heartbeat.js"; import { issueService } from "../services/issues.js"; import { @@ -1561,12 +1563,67 @@ class PrReviewerTaskLockTimeoutError extends Error { } } +// BLO-21582 review follow-up: racing `db.transaction()` (or a bare read +// promise) against a deadline can only stop US from awaiting it -- postgres.js +// never exposes the internal query it uses to acquire a pooled connection, so +// an abandoned one still lands on a freed connection later and runs its +// BEGIN/probe/rollback (or SELECT) regardless of whether anyone is still +// listening, adding detached work behind the exact pool contention this code +// exists to survive (the prior version of this fix only logged that case). +// +// `sql.reserve()` is genuinely boundable: it never issues a query at all +// until code explicitly does so on the connection it returns. Racing the +// *reservation* against the deadline means an abandoned one can be released +// the instant it lands, before a single query runs on it, and one that lands +// in time is exclusively ours from then on -- no further pool contention is +// possible, so nothing after that point needs bounding either. +type PgClient = Db["$client"]; +type ReservedPgConnection = Awaited>; + +const RESERVATION_TIMED_OUT = Symbol("pr-reviewer-task-lock-reservation-timed-out"); + +async function reserveConnectionOrTimeout( + client: PgClient, + remainingMs: number, +): Promise { + if (remainingMs <= 0) return RESERVATION_TIMED_OUT; + const reservation = client.reserve(); + const outcome = await Promise.race([ + reservation.then((conn) => ({ conn })), + new Promise((resolve) => { + setTimeout(() => resolve(RESERVATION_TIMED_OUT), remainingMs); + }), + ]); + if (outcome !== RESERVATION_TIMED_OUT) return outcome.conn; + // postgres.js does not expose withdrawing a still-queued reserve() request + // -- but nothing has run on it, so hand it straight back the moment it + // lands instead of ever using it, which is the only part of the old + // behavior actually worth avoiding. + reservation.then((conn) => conn.release()).catch(() => {}); + return RESERVATION_TIMED_OUT; +} + +// A connection returned by `reserve()` does not carry the `.options` postgres.js +// attaches to the top-level client (only the client `postgres(...)` itself +// gets `begin`/`reserve`/`options`; see postgres.js's `Sql()` factory). The +// postgres-js drizzle driver reads `client.options.parsers` while +// constructing, so without this it throws immediately on a reserved +// connection. Sharing the pool's own `options` object here is safe: the +// mutation the driver performs on it (registering type-transparency parsers) +// already ran once when `createDb()` built `client` itself, so re-running it +// is idempotent (verified against the embedded-postgres test harness). +function drizzleOverReservedConnection(client: PgClient, reserved: ReservedPgConnection): PrReviewerSelectionDb { + Object.assign(reserved, { options: (client as unknown as { options: unknown }).options }); + return drizzlePgFromClient(reserved as unknown as PgClient); +} + async function withPrReviewerTaskLock( db: Db, taskKey: string, deadline: number, - action: (tx: DbTransaction) => Promise, + action: (tx: PrReviewerSelectionDb) => Promise, ): Promise { + const client = db.$client; while (true) { const remainingMs = deadline - Date.now(); if (remainingMs <= 0) { @@ -1574,85 +1631,63 @@ async function withPrReviewerTaskLock( } // Do not block a pooled connection while another request owns the lock: // the winner needs a second connection for heartbeat's enqueue transaction. - // - // Race pool checkout + the lock probe -- and ONLY that -- against the - // remaining budget: `db.transaction()` alone does not respect `deadline` - // (a stalled pool checkout under contention could block well past it), - // so bound it explicitly here rather than only checking elapsed time - // after it resolves. `settleLockProbe` below fires the instant the probe - // query itself settles, before `action(tx)` ever runs, so the race can - // never observe a still-running `action` as "not acquired" (BLO-21582 - // review follow-up: racing the whole transaction -- including - // `action(tx)` -- let the handler abandon a live transaction that could - // still commit a wake after the deadline had already been reported as a - // lock-acquisition failure, producing a false dead-letter AND a second, - // uncounted wake). - let settleLockProbe: (outcome: { acquired: boolean } | { error: unknown }) => void; - const lockProbeSettled = new Promise<{ acquired: boolean } | { error: unknown }>((resolve) => { - settleLockProbe = resolve; - }); - const transactionPromise = db.transaction(async (tx) => { - let acquired: boolean; + const reservation = await reserveConnectionOrTimeout(client, remainingMs); + if (reservation === RESERVATION_TIMED_OUT) { + if (Date.now() >= deadline) { + throw new PrReviewerTaskLockTimeoutError(taskKey); + } + await new Promise((resolve) => setTimeout(resolve, PR_REVIEWER_TASK_LOCK_RETRY_MS)); + continue; + } + let acquired = false; + try { + await reservation`begin`; try { - const rows = await tx.execute( - sql`select pg_try_advisory_xact_lock(hashtextextended(${taskKey}, 0)) as acquired`, - ); - const row = Array.isArray(rows) ? rows[0] : null; - acquired = - !!row && typeof row === "object" && (row as Record).acquired === true; + const rows = await reservation`select pg_try_advisory_xact_lock(hashtextextended(${taskKey}, 0)) as acquired`; + acquired = !!rows[0] && (rows[0] as Record).acquired === true; } catch (error) { - settleLockProbe({ error }); + await reservation`rollback`.catch(() => {}); throw error; } + // BLO-21582 review follow-up (preserves Omar's 573c9ff8 guard under the + // new reservation-based mechanism): the probe can still settle after + // `deadline` even though nothing here is detached anymore -- e.g. the + // reservation itself landed late within its own race, or the probe + // query was simply slow. Treat a late acquisition as not-acquired + // rather than running `action`: bounding overall response latency to + // the budget is a deliberate policy independent of the detached- + // execution bug this rewrite fixes, and readers/callers downstream + // (the 200 response, the funnel counters) are already sized around + // that budget. if (acquired && Date.now() >= deadline) { logger.warn( { taskKey }, "github webhook reviewer wake lock was acquired after its retry deadline; skipping reviewer wake action", ); - settleLockProbe({ acquired: false }); - return { acquired: false as const }; + acquired = false; } - settleLockProbe({ acquired }); - if (!acquired) { - return { acquired: false as const }; + if (acquired) { + // The lock -- and this reserved connection -- are ours from here on: + // no pool contention can delay `action` regardless of how long it + // runs, the same guarantee the previous design gave only the + // already-acquired case. Abandoning here would still leave the + // transaction open on a connection nobody is accounting for. + const value = await action(drizzleOverReservedConnection(client, reservation)); + await reservation`commit`; + return value; } - // The lock is ours from here on: no further racing against the - // deadline, even if `action` runs long. Abandoning this branch after - // this point would still let the transaction commit on its own - // connection with nobody accounting for the outcome. - return { acquired: true as const, value: await action(tx) }; - }); - const probeOutcome = await Promise.race([ - lockProbeSettled, - new Promise<{ acquired: false }>((resolve) => { - setTimeout(() => resolve({ acquired: false }), remainingMs); - }), - ]); - if ("error" in probeOutcome) { - // The probe query itself failed (not a lock-acquisition timeout) -- - // this is a genuine DB error, not ours to retry. Swallow the - // transaction's own rejection (same error, already surfaced here) so - // it doesn't also report as an unhandled rejection. - transactionPromise.catch(() => {}); - throw probeOutcome.error; - } - if (probeOutcome.acquired) { - // Lock acquisition already resolved inside the transaction; await the - // in-flight `action(tx)` to completion instead of racing it further. - const outcome = (await transactionPromise) as { acquired: true; value: T }; - return outcome.value; + await reservation`rollback`; + } catch (error) { + if (acquired) { + // `action` or `commit` failed after the lock was acquired: roll back + // so this connection doesn't return to the pool mid-transaction, + // then surface the real error instead of a lock timeout. + await reservation`rollback`.catch(() => {}); + } + throw error; + } finally { + reservation.release(); } - // The probe did not settle within budget (most likely a stalled pool - // checkout): move on without waiting further, but log if the abandoned - // transaction eventually does settle so that's still observable. It - // still commits or rolls back on its own connection regardless of - // whether we're still waiting on it. - transactionPromise.catch((err) => { - logger.warn( - { err, taskKey }, - "github webhook reviewer wake lock transaction settled after its retry budget was abandoned", - ); - }); if (Date.now() >= deadline) { throw new PrReviewerTaskLockTimeoutError(taskKey); } @@ -1667,22 +1702,53 @@ async function withPrReviewerTaskLock( const FALLBACK_RECHECK_TIMED_OUT = Symbol("pr-reviewer-wake-fallback-recheck-timed-out"); // Bounds one lock-exhaustion fallback read against `deadlineMs` (BLO-21582 -// review follow-up). A timeout here must propagate as "unknown", not as a -// false "confirmed no active reviewer" -- the caller has to keep that -// distinction to avoid silently swallowing a real loss just because the -// recheck itself couldn't get a connection in time. +// review follow-up). Reserving the connection first (same mechanism as +// `withPrReviewerTaskLock`) means a reservation that times out is released +// before it ever runs `read`. Unlike the lock probe's `action`, a fallback +// read has no self-healing value in letting a stall keep running -- it is a +// best-effort advisory check, so once the connection is ours the actual +// query still needs bounding regardless of why it might be slow (a table +// lock, a slow plan -- not just pool contention). `SET LOCAL +// statement_timeout` does that at the database itself instead of merely +// abandoning the JS promise, so nothing is left running once this connection +// is released. `read` may issue more than one statement (see +// `selectPrReviewerAgentId`'s two-query fallback); each gets its own fresh +// per-statement timer, so a multi-statement read can in the worst case take +// a small multiple of the budget rather than exactly bounding the total -- +// acceptable here because the result stays bounded and finite, not the +// unbounded hang this replaces. A timeout here must propagate as "unknown", +// not as a false "confirmed no active reviewer" -- the caller has to keep +// that distinction to avoid silently swallowing a real loss just because the +// recheck itself couldn't finish in time. async function boundedFallbackRead( - promise: Promise, + client: PgClient, deadlineMs: number, + read: (reservedDb: PrReviewerSelectionDb) => Promise, ): Promise { const remainingMs = deadlineMs - Date.now(); - if (remainingMs <= 0) return FALLBACK_RECHECK_TIMED_OUT; - return Promise.race([ - promise, - new Promise((resolve) => { - setTimeout(() => resolve(FALLBACK_RECHECK_TIMED_OUT), remainingMs); - }), - ]); + const reservation = await reserveConnectionOrTimeout(client, remainingMs); + if (reservation === RESERVATION_TIMED_OUT) return FALLBACK_RECHECK_TIMED_OUT; + try { + const statementTimeoutMs = Math.max(1, Math.floor(deadlineMs - Date.now())); + await reservation`begin`; + try { + // Not parameterized: `SET` does not accept a bind parameter for its + // value in all PostgreSQL versions/drivers (the existing `SET LOCAL + // statement_timeout` usage in routes/plugins.ts inlines a literal for + // the same reason). Safe here because the value is our own computed + // integer, never external input. + await reservation.unsafe(`set local statement_timeout = ${statementTimeoutMs}`); + const result = await read(drizzleOverReservedConnection(client, reservation)); + await reservation`commit`; + return result; + } catch (error) { + await reservation`rollback`.catch(() => {}); + if (findPgError(error)?.code === "57014") return FALLBACK_RECHECK_TIMED_OUT; + throw error; + } + } finally { + reservation.release(); + } } // Shared between the lock-guarded idempotency check inside @@ -2340,8 +2406,9 @@ export function githubWebhookRoutes(db: Db, config: GithubWebhookConfig) { // or an unbounded wait on the other. const fallbackDeadline = lockDeadline + PR_REVIEWER_TASK_LOCK_FALLBACK_BUDGET_MS; const equivalentWake = await boundedFallbackRead( - findExistingPrReviewerWake(db, reviewerAgentIds, idempotencyKey, idempotentStatuses), + db.$client, fallbackDeadline, + (reservedDb) => findExistingPrReviewerWake(reservedDb, reviewerAgentIds, idempotencyKey, idempotentStatuses), ); if (equivalentWake === FALLBACK_RECHECK_TIMED_OUT) { logger.warn( @@ -2373,10 +2440,11 @@ export function githubWebhookRoutes(db: Db, config: GithubWebhookConfig) { return false; } else { const equivalentReviewerAgentId = await boundedFallbackRead( - (async () => - (await findActivePrReviewerForTask(db, reviewerAgentIds, reviewerTaskKey)) ?? - (await selectPrReviewerAgentId(db, reviewerAgentIds, reviewerTaskKey)))(), + db.$client, fallbackDeadline, + async (reservedDb) => + (await findActivePrReviewerForTask(reservedDb, reviewerAgentIds, reviewerTaskKey)) ?? + (await selectPrReviewerAgentId(reservedDb, reviewerAgentIds, reviewerTaskKey)), ); if (equivalentReviewerAgentId === FALLBACK_RECHECK_TIMED_OUT) { logger.warn( From 37879c4e04eb501775e8ed86b1c6b98499d9df04 Mon Sep 17 00:00:00 2001 From: PlatformSREEngineer Date: Fri, 7 Aug 2026 22:53:45 +0000 Subject: [PATCH 8/9] fix(github-webhook): database-bound the lock-probe transaction, not just the reservation (BLO-21582) Ally review follow-up on #1003: reserveConnectionOrTimeout bounds the pool CHECKOUT, but once a connection landed, `begin` and the advisory-lock probe were awaited with no database-side timeout -- postgres.js can't cancel an in-flight query client-side, so a stalled backend could hold the reserved connection past the 4s request-wide budget despite the reservation race. Sets a plain (session-scoped, since `begin` predates any transaction for `SET LOCAL` to attach to) `statement_timeout` bounding both to the remaining deadline, treats SQLSTATE 57014 (query_canceled) as not-acquired, and resets the timeout to 0 both before `action` runs (so the already-acquired lock's own work stays unbounded) and unconditionally in the outer `finally` (a rollback undoes an in-transaction plain SET, so only an unconditional reset guarantees no leftover timeout leaks onto the next borrower of the connection). Replaces the delayed-probe unit test's implicit real-time wait with one that models Postgres's own statement_timeout cancellation and asserts bounded wall-clock latency, per the review note that the original only proved the action was skipped, not that the response was bounded. Also consolidates ReviewQueueCard's duplicate empty-queue polling (the review's non-blocking suggestion): a manual setTimeout effect and `refetchInterval` were independently polling the same case, which is why the call-count assertion had been loosened to `>=`. Removes the redundant effect and widens `refetchInterval` to always poll fast when empty (matching the effect's original scope, which never excluded `emptyState="hidden"`), then restores exact call-count assertions now that there is one deterministic timer. Co-Authored-By: Claude Sonnet 5 --- server/src/__tests__/github-webhook.test.ts | 77 ++++++++++++++- server/src/routes/github-webhook.ts | 101 +++++++++++++------- ui/src/pages/apps/ReviewQueueCard.test.tsx | 4 +- ui/src/pages/apps/ReviewQueueCard.tsx | 21 ++-- 4 files changed, 156 insertions(+), 47 deletions(-) diff --git a/server/src/__tests__/github-webhook.test.ts b/server/src/__tests__/github-webhook.test.ts index 75b5558e5b50..85e561342366 100644 --- a/server/src/__tests__/github-webhook.test.ts +++ b/server/src/__tests__/github-webhook.test.ts @@ -1182,7 +1182,7 @@ describe("github-webhook pure helpers", () => { } return []; // rollback }, - { release: () => {} }, + { release: () => {}, unsafe: async () => [] }, ); const fakeDb = { $client: { reserve: async () => fakeReservedConnection } }; @@ -1202,6 +1202,81 @@ describe("github-webhook pure helpers", () => { expect(probeStarted).toBe(true); expect(actionCalled).toBe(false); }); + + it( + "bounds response latency to the deadline instead of waiting out a stalled probe " + + "(BLO-21582 review follow-up: the delayed-probe test above proves the action is " + + "skipped, but it lets the request wait for the slow probe to settle and so does not " + + "prove bounded latency -- this one measures wall-clock time against the fake probe's " + + "own delay to prove the opposite)", + async () => { + // Real Postgres can't be made to stall `pg_try_advisory_xact_lock` + // itself (it touches no table, so `holdExclusiveTableLock`-style + // contention has nothing to block) -- so this models what + // `statement_timeout` actually does on a real backend: the probe + // query races its own artificial delay against the timeout the + // production code just told Postgres about via `set statement_timeout + // = `, and "wins" with a real SQLSTATE 57014 (query_canceled) the + // same way a real backend would cancel a stalled statement. + let actionCalled = false; + let probeStarted = false; + let sawTimeoutReset = false; + let statementTimeoutMs: number | null = null; + let callIndex = 0; + const PROBE_STALL_MS = 500; + const fakeReservedConnection = Object.assign( + async (_strings: TemplateStringsArray, ..._values: unknown[]) => { + callIndex += 1; + if (callIndex === 1) return []; // begin + if (callIndex === 2) { + probeStarted = true; + const timeoutMs = statementTimeoutMs ?? Number.POSITIVE_INFINITY; + return await new Promise((resolve, reject) => { + const stalled = setTimeout(() => resolve([{ acquired: true }]), PROBE_STALL_MS); + setTimeout(() => { + clearTimeout(stalled); + reject(Object.assign(new Error("canceling statement due to statement timeout"), { code: "57014" })); + }, timeoutMs); + }); + } + return []; // rollback + }, + { + release: () => {}, + unsafe: async (sqlText: string) => { + const match = /^set statement_timeout = (\d+)$/.exec(sqlText); + if (match) { + statementTimeoutMs = Number(match[1]); + if (statementTimeoutMs === 0) sawTimeoutReset = true; + } + return []; + }, + }, + ); + const fakeDb = { $client: { reserve: async () => fakeReservedConnection } }; + + const startedAt = Date.now(); + await expect( + __test_withPrReviewerTaskLock( + fakeDb as never, + "pr_review:Blockcast/paperclip:21582007", + Date.now() + 20, + async () => { + actionCalled = true; + return "queued"; + }, + ), + ).rejects.toThrow("timed out acquiring PR reviewer task assignment lock"); + const elapsedMs = Date.now() - startedAt; + + expect(probeStarted).toBe(true); + expect(actionCalled).toBe(false); + // The database-side bound fired well before the fake's simulated + // stall -- without it, this would take at least PROBE_STALL_MS. + expect(elapsedMs).toBeLessThan(PROBE_STALL_MS / 2); + expect(sawTimeoutReset).toBe(true); + }, + ); }); describeEmbeddedPostgres("github-webhook route", () => { diff --git a/server/src/routes/github-webhook.ts b/server/src/routes/github-webhook.ts index 549c6f994bb1..d9ead2cbdbfd 100644 --- a/server/src/routes/github-webhook.ts +++ b/server/src/routes/github-webhook.ts @@ -1575,8 +1575,13 @@ class PrReviewerTaskLockTimeoutError extends Error { // until code explicitly does so on the connection it returns. Racing the // *reservation* against the deadline means an abandoned one can be released // the instant it lands, before a single query runs on it, and one that lands -// in time is exclusively ours from then on -- no further pool contention is -// possible, so nothing after that point needs bounding either. +// in time is exclusively ours from then on -- no further POOL CONTENTION is +// possible. That is a different guarantee from a stalled BACKEND, though: +// once the connection is ours, `begin` and the advisory-lock probe are still +// real queries that postgres.js cannot cancel client-side, so they get their +// own database-side bound below (mirroring `boundedFallbackRead`'s +// `statement_timeout` further down this file) rather than relying on the +// reservation race to cover them too. type PgClient = Db["$client"]; type ReservedPgConnection = Awaited>; @@ -1641,42 +1646,67 @@ async function withPrReviewerTaskLock( } let acquired = false; try { - await reservation`begin`; + // BLO-21582 review follow-up: `begin` and the advisory-lock probe are + // real round trips to a real backend, and postgres.js gives no way to + // cancel one client-side once it's in flight -- racing a deadline (the + // way `reserveConnectionOrTimeout` above does for the reservation + // itself) only stops US from awaiting the result, it doesn't stop the + // backend from running it. Asking Postgres itself to cancel a stalled + // statement via `statement_timeout` is the only bound that actually + // works. It has to be a plain (session-scoped) `SET`, not `SET LOCAL`: + // `begin` runs before any transaction exists for `LOCAL` to attach to. + const probeBudgetMs = Math.max(1, Math.floor(deadline - Date.now())); + let probeError: unknown = null; try { + await reservation.unsafe(`set statement_timeout = ${probeBudgetMs}`); + await reservation`begin`; const rows = await reservation`select pg_try_advisory_xact_lock(hashtextextended(${taskKey}, 0)) as acquired`; acquired = !!rows[0] && (rows[0] as Record).acquired === true; } catch (error) { - await reservation`rollback`.catch(() => {}); - throw error; + probeError = error; } - // BLO-21582 review follow-up (preserves Omar's 573c9ff8 guard under the - // new reservation-based mechanism): the probe can still settle after - // `deadline` even though nothing here is detached anymore -- e.g. the - // reservation itself landed late within its own race, or the probe - // query was simply slow. Treat a late acquisition as not-acquired - // rather than running `action`: bounding overall response latency to - // the budget is a deliberate policy independent of the detached- - // execution bug this rewrite fixes, and readers/callers downstream - // (the 200 response, the funnel counters) are already sized around - // that budget. - if (acquired && Date.now() >= deadline) { - logger.warn( - { taskKey }, - "github webhook reviewer wake lock was acquired after its retry deadline; skipping reviewer wake action", - ); - acquired = false; - } - if (acquired) { - // The lock -- and this reserved connection -- are ours from here on: - // no pool contention can delay `action` regardless of how long it - // runs, the same guarantee the previous design gave only the - // already-acquired case. Abandoning here would still leave the - // transaction open on a connection nobody is accounting for. - const value = await action(drizzleOverReservedConnection(client, reservation)); - await reservation`commit`; - return value; + if (probeError) { + await reservation`rollback`.catch(() => {}); + if (findPgError(probeError)?.code !== "57014") throw probeError; + // The statement_timeout fired on `begin` or the probe itself -- + // treat exactly like a probe that never got the chance to run: not + // acquired (still false from above), deadline re-checked below like + // every other timeout path in this function. + } else { + // BLO-21582 review follow-up (preserves Omar's 573c9ff8 guard under + // the new reservation-based mechanism): the probe can still settle + // after `deadline` even though nothing here is detached anymore -- + // e.g. the reservation itself landed late within its own race, or + // the probe query was simply slow. Treat a late acquisition as + // not-acquired rather than running `action`: bounding overall + // response latency to the budget is a deliberate policy independent + // of the detached-execution bug this rewrite fixes, and + // readers/callers downstream (the 200 response, the funnel + // counters) are already sized around that budget. + if (acquired && Date.now() >= deadline) { + logger.warn( + { taskKey }, + "github webhook reviewer wake lock was acquired after its retry deadline; skipping reviewer wake action", + ); + acquired = false; + } + if (acquired) { + // The lock -- and this reserved connection -- are ours from here + // on: no pool contention can delay `action` regardless of how + // long it runs, the same guarantee the previous design gave only + // the already-acquired case. Abandoning here would still leave + // the transaction open on a connection nobody is accounting for. + // Reset the probe's `statement_timeout` first: it's a plain + // `SET`, so it survives the `commit` below (nothing leaks onto + // the next borrower of this connection), but `action` itself must + // not inherit a bound sized for a one-row probe. + await reservation.unsafe(`set statement_timeout = 0`); + const value = await action(drizzleOverReservedConnection(client, reservation)); + await reservation`commit`; + return value; + } + await reservation`rollback`; } - await reservation`rollback`; } catch (error) { if (acquired) { // `action` or `commit` failed after the lock was acquired: roll back @@ -1686,6 +1716,13 @@ async function withPrReviewerTaskLock( } throw error; } finally { + // Unconditional and independent of the reset above: a plain `SET`'s + // effect is undone by `rollback` (Postgres treats it as transactional + // for abort purposes even though it survives commit), so any path that + // rolled back here -- not-acquired, or an error after acquiring -- + // would otherwise hand the next borrower of this physical connection a + // leftover statement_timeout sized for a probe that already finished. + await reservation.unsafe(`set statement_timeout = 0`).catch(() => {}); reservation.release(); } if (Date.now() >= deadline) { diff --git a/ui/src/pages/apps/ReviewQueueCard.test.tsx b/ui/src/pages/apps/ReviewQueueCard.test.tsx index 90cf8239b02f..4a9c46fe9fb3 100644 --- a/ui/src/pages/apps/ReviewQueueCard.test.tsx +++ b/ui/src/pages/apps/ReviewQueueCard.test.tsx @@ -278,7 +278,7 @@ describe("ReviewQueueCard", () => { await vi.waitFor( () => { - expect(listActionRequestsMock.mock.calls.length).toBeGreaterThanOrEqual(3); + expect(listActionRequestsMock).toHaveBeenCalledTimes(3); expect(document.body.textContent).toContain("Nothing is waiting for your OK right now."); }, { timeout: 3_500 }, @@ -288,7 +288,7 @@ describe("ReviewQueueCard", () => { await vi.waitFor( () => { - expect(listActionRequestsMock.mock.calls.length).toBeGreaterThanOrEqual(4); + expect(listActionRequestsMock).toHaveBeenCalledTimes(4); expect(buttonContaining("Allow once")).toBeTruthy(); }, { timeout: 3_500 }, diff --git a/ui/src/pages/apps/ReviewQueueCard.tsx b/ui/src/pages/apps/ReviewQueueCard.tsx index 2fa5657168c1..daa61fa2d172 100644 --- a/ui/src/pages/apps/ReviewQueueCard.tsx +++ b/ui/src/pages/apps/ReviewQueueCard.tsx @@ -42,11 +42,17 @@ export function ReviewQueueCard({ enabled: !!selectedCompanyId, staleTime: 0, refetchOnMount: false, + // The single polling mechanism for "keep an empty queue fresh": poll + // fast whenever the (filtered) queue is empty -- regardless of + // `emptyState`, since a `hidden` card still needs to notice a new + // pending item promptly so it can start rendering -- and fall back to + // the slow interval once there's something to show. A second, + // independent `setTimeout`-based effect used to duplicate this exact + // polling for the visible (`reassure`) empty state; consolidated here so + // there is only ever one in-flight timer for it (review follow-up). refetchInterval: (state) => { const visibleItems = filterActionRequests(state.state.data?.actionRequests, connectionId); - return emptyState !== "hidden" && visibleItems.length === 0 - ? VISIBLE_EMPTY_QUEUE_REFRESH_MS - : 20_000; + return visibleItems.length === 0 ? VISIBLE_EMPTY_QUEUE_REFRESH_MS : 20_000; }, }); @@ -61,15 +67,6 @@ export function ReviewQueueCard({ void query.refetch(); }, [query.dataUpdatedAt, query.fetchStatus, query.refetch, selectedCompanyId]); - useEffect(() => { - if (!selectedCompanyId || items.length > 0) return; - if (query.dataUpdatedAt === 0 || query.fetchStatus === "fetching") return; - const timeout = window.setTimeout(() => { - void query.refetch(); - }, VISIBLE_EMPTY_QUEUE_REFRESH_MS); - return () => window.clearTimeout(timeout); - }, [items.length, query.dataUpdatedAt, query.fetchStatus, query.refetch, selectedCompanyId]); - if (!selectedCompanyId) return null; if (query.isLoading) return null; From 380618978ba5c394cdc035bff84d37de21b1d981 Mon Sep 17 00:00:00 2001 From: Omar Ramadan Date: Sat, 8 Aug 2026 11:46:26 +0000 Subject: [PATCH 9/9] fix(tool-access): preserve in-flight approval requests Co-Authored-By: Paperclip --- .../src/__tests__/tool-access-service.test.ts | 45 ++++++++++++++++--- server/src/services/tool-access.ts | 21 ++++++++- 2 files changed, 58 insertions(+), 8 deletions(-) diff --git a/server/src/__tests__/tool-access-service.test.ts b/server/src/__tests__/tool-access-service.test.ts index 7d4a7dad569f..8adc177264b4 100644 --- a/server/src/__tests__/tool-access-service.test.ts +++ b/server/src/__tests__/tool-access-service.test.ts @@ -3320,7 +3320,7 @@ describeEmbeddedPostgres("tool access service", () => { ]); }); - it("cancels stale pending action requests with invalid signatures before listing the review queue", async () => { + it("waits for a fresh action request to be signed while cancelling stale or invalid approvals", async () => { vi.stubEnv("PAPERCLIP_TOOL_ACTION_SIGNING_SECRET", "current-secret"); const company = await createCompany(db); const [application] = await db.insert(toolApplications).values({ @@ -3352,7 +3352,7 @@ describeEmbeddedPostgres("tool access service", () => { schemaHash: "s1", }).returning(); const canonicalArguments = canonicalToolArguments({ key: "alpha", value: "one" }); - const invocationValues = [1, 2, 3].map(() => ({ + const invocationValues = [1, 2, 3, 4].map(() => ({ companyId: company.id, applicationId: application.id, connectionId: connection.id, @@ -3364,7 +3364,7 @@ describeEmbeddedPostgres("tool access service", () => { approvalState: "pending" as const, status: "awaiting_approval" as const, })); - const [validInvocation, missingSignatureInvocation, oldSecretInvocation] = + const [validInvocation, freshUnsignedInvocation, staleUnsignedInvocation, oldSecretInvocation] = await db.insert(toolInvocations).values(invocationValues).returning(); const validSignedArguments = signToolArguments({ invocationId: validInvocation.id, @@ -3378,7 +3378,8 @@ describeEmbeddedPostgres("tool access service", () => { canonicalArguments, signingSecret: "old-secret", }); - const [validRequest, missingSignatureRequest, oldSecretRequest] = await db.insert(toolActionRequests).values([ + const staleUnsignedCreatedAt = new Date(Date.now() - 60_000); + const [validRequest, freshUnsignedRequest, staleUnsignedRequest, oldSecretRequest] = await db.insert(toolActionRequests).values([ { companyId: company.id, invocationId: validInvocation.id, @@ -3389,12 +3390,22 @@ describeEmbeddedPostgres("tool access service", () => { }, { companyId: company.id, - invocationId: missingSignatureInvocation.id, + invocationId: freshUnsignedInvocation.id, status: "pending", canonicalArgumentsHash: "args-hash", canonicalArgumentsSummary: { summary: canonicalArguments, sha256: "args-hash", sizeBytes: canonicalArguments.length }, signedArguments: null, }, + { + companyId: company.id, + invocationId: staleUnsignedInvocation.id, + status: "pending", + canonicalArgumentsHash: "args-hash", + canonicalArgumentsSummary: { summary: canonicalArguments, sha256: "args-hash", sizeBytes: canonicalArguments.length }, + signedArguments: null, + createdAt: staleUnsignedCreatedAt, + updatedAt: staleUnsignedCreatedAt, + }, { companyId: company.id, invocationId: oldSecretInvocation.id, @@ -3405,14 +3416,34 @@ describeEmbeddedPostgres("tool access service", () => { }, ]).returning(); - const list = await toolAccessService(db).listActionRequests(company.id, "pending"); + const service = toolAccessService(db); + const list = await service.listActionRequests(company.id, "pending"); const rows = await db.select().from(toolActionRequests); const statusById = new Map(rows.map((row) => [row.id, row.status])); expect(list.map((item) => item.request.id)).toEqual([validRequest.id]); expect(statusById.get(validRequest.id)).toBe("pending"); - expect(statusById.get(missingSignatureRequest.id)).toBe("cancelled"); + expect(statusById.get(freshUnsignedRequest.id)).toBe("pending"); + expect(statusById.get(staleUnsignedRequest.id)).toBe("cancelled"); expect(statusById.get(oldSecretRequest.id)).toBe("cancelled"); + + await db + .update(toolActionRequests) + .set({ + signedArguments: signToolArguments({ + invocationId: freshUnsignedInvocation.id, + toolName: freshUnsignedInvocation.toolName, + canonicalArguments, + signingSecret: "current-secret", + }), + updatedAt: new Date(), + }) + .where(eq(toolActionRequests.id, freshUnsignedRequest.id)); + + const signedList = await service.listActionRequests(company.id, "pending"); + expect(signedList.map((item) => item.request.id).sort()).toEqual( + [freshUnsignedRequest.id, validRequest.id].sort(), + ); }); it("tracks new profile tools, reviews mixed allow/block decisions, and clears pending counts", async () => { diff --git a/server/src/services/tool-access.ts b/server/src/services/tool-access.ts index c3a69bccc2cc..8213a12f3087 100644 --- a/server/src/services/tool-access.ts +++ b/server/src/services/tool-access.ts @@ -125,6 +125,11 @@ type ActorInfo = { const ACTIVE_BROKER_RUN_STATUSES = new Set(["running"]); const REMOTE_HTTP_REDIRECT_STATUSES = new Set([301, 302, 303, 307, 308]); const MAX_REMOTE_HTTP_REDIRECTS = 5; +// `recordInvocation` creates an approval request before the gateway can attach +// its invocation-bound signature. A queue poll may observe that short-lived +// row, so do not expose or cancel it until signing has had a chance to finish. +// Unsigned rows older than this are still treated as invalid and cancelled. +const PENDING_ACTION_REQUEST_SIGNING_GRACE_MS = 30_000; type OAuthProviderEndpoints = { provider: string; @@ -5676,8 +5681,18 @@ export function toolAccessService(db: Db, options: ToolAccessServiceOptions = {} const invocationById = new Map(invocations.map((invocation) => [invocation.id, invocation])); let visibleRequests = requests; if (status === "pending") { + const signingGraceCutoff = now().getTime() - PENDING_ACTION_REQUEST_SIGNING_GRACE_MS; + const signingRequestIds = new Set( + requests + .filter((request) => !request.signedArguments && request.createdAt.getTime() > signingGraceCutoff) + .map((request) => request.id), + ); const invalidRequestIds = requests .filter((request) => { + // The signer writes after `recordInvocation` has inserted the + // request. Keep that short-lived, unsigned row out of the queue + // rather than cancelling it as if it had been tampered with. + if (signingRequestIds.has(request.id)) return false; const invocation = invocationById.get(request.invocationId); if (!invocation) return true; try { @@ -5701,7 +5716,11 @@ export function toolAccessService(db: Db, options: ToolAccessServiceOptions = {} inArray(toolActionRequests.id, invalidRequestIds), )); const invalidIds = new Set(invalidRequestIds); - visibleRequests = requests.filter((request) => !invalidIds.has(request.id)); + visibleRequests = requests.filter( + (request) => !invalidIds.has(request.id) && !signingRequestIds.has(request.id), + ); + } else if (signingRequestIds.size > 0) { + visibleRequests = requests.filter((request) => !signingRequestIds.has(request.id)); } } if (visibleRequests.length === 0) return [];