diff --git a/server/src/__tests__/github-webhook.test.ts b/server/src/__tests__/github-webhook.test.ts index 7a645608e374..85e561342366 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,125 @@ 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 () => { + // 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; + 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: () => {}, unsafe: async () => [] }, + ); + const fakeDb = { $client: { reserve: async () => fakeReservedConnection } }; + + 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); + }); + + 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", () => { @@ -2503,7 +2623,643 @@ 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 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; + + 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(); + }; + } + + // 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 () => { + 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}`; + // 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 }); + 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 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(); + 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 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 = { + 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 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-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 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 }) + .from(agentWakeupRequests) + .where(eq(agentWakeupRequests.agentId, reviewerAgentId)); + expect(wakes).toHaveLength(0); + }, + 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( + "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, + ); + + 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, + ); + }); + + 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/__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/routes/github-webhook.ts b/server/src/routes/github-webhook.ts index 5a63fddf82b5..d9ead2cbdbfd 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 { @@ -66,8 +68,26 @@ 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; +// 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 { /** @@ -1532,38 +1552,266 @@ 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"; + } +} + +// 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. 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>; + +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, - action: (tx: DbTransaction) => Promise, + deadline: number, + action: (tx: PrReviewerSelectionDb) => Promise, ): Promise { - const deadline = Date.now() + PR_REVIEWER_TASK_LOCK_TIMEOUT_MS; - + const client = db.$client; 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) => { - 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 - ) { - return { acquired: false as const }; + const reservation = await reserveConnectionOrTimeout(client, remainingMs); + if (reservation === RESERVATION_TIMED_OUT) { + if (Date.now() >= deadline) { + throw new PrReviewerTaskLockTimeoutError(taskKey); } - return { acquired: true as const, value: await action(tx) }; - }); - if (outcome.acquired) return outcome.value; + await new Promise((resolve) => setTimeout(resolve, PR_REVIEWER_TASK_LOCK_RETRY_MS)); + continue; + } + let acquired = false; + try { + // 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) { + probeError = error; + } + 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`; + } + } 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 { + // 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) { - 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)); } } +// 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). 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( + client: PgClient, + deadlineMs: number, + read: (reservedDb: PrReviewerSelectionDb) => Promise, +): Promise { + const remainingMs = deadlineMs - Date.now(); + 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 +// 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; } @@ -2034,39 +2282,56 @@ export function githubWebhookRoutes(db: Db, config: GithubWebhookConfig) { ); return false; } + 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). + // + // 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 { - 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), - ); - return await withPrReviewerTaskLock(db, reviewerTaskKey, async (tx) => { + 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( { @@ -2151,6 +2416,112 @@ export function githubWebhookRoutes(db: Db, config: GithubWebhookConfig) { return false; }); } 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. + // + // 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( + db.$client, + fallbackDeadline, + (reservedDb) => findExistingPrReviewerWake(reservedDb, reviewerAgentIds, idempotencyKey, idempotentStatuses), + ); + if (equivalentWake === 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 (existing wake) timed out waiting for a " + + "database read; recording the delivery as lost rather than risking an unbounded synchronous read", + ); + } else 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; + } else { + const equivalentReviewerAgentId = await boundedFallbackRead( + db.$client, + fallbackDeadline, + async (reservedDb) => + (await findActivePrReviewerForTask(reservedDb, reviewerAgentIds, reviewerTaskKey)) ?? + (await selectPrReviewerAgentId(reservedDb, reviewerAgentIds, reviewerTaskKey)), + ); + 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 + // 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, @@ -2779,6 +3150,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; 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 []; diff --git a/ui/src/pages/apps/ReviewQueueCard.test.tsx b/ui/src/pages/apps/ReviewQueueCard.test.tsx index bca33f7fa807..4a9c46fe9fb3 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).toHaveBeenCalledTimes(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(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..daa61fa2d172 100644 --- a/ui/src/pages/apps/ReviewQueueCard.tsx +++ b/ui/src/pages/apps/ReviewQueueCard.tsx @@ -42,12 +42,22 @@ export function ReviewQueueCard({ enabled: !!selectedCompanyId, staleTime: 0, refetchOnMount: false, - refetchInterval: 20_000, + // 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 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(() => { @@ -57,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; @@ -96,6 +97,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();