From 16358bfd35a187de9d1ee48df887eb44640b9d02 Mon Sep 17 00:00:00 2001 From: PlatformSREEngineer Date: Sun, 20 Sep 2026 06:53:53 +0000 Subject: [PATCH] fix(github-webhook): log the reviewer-wake enqueue (BLO-22758) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `attemptPrReviewerWake` has four outcomes and only the success one was silent: duplicate, no_reviewer and declined each log, as do the caller's deferred and lock-loss branches. So a PR whose review was served and a PR whose wake was never enqueued emitted a byte-identical webhook trail, and "the wake was created and the run was lost" could not be told apart from "the wake was never created" for any individual PR. The `queued` counter from BLO-18859 does not close this. It is aggregate, so it answers the funnel question, not the per-PR one — and the per-PR one is what every stranded-review investigation actually asks. Emit a structured line carrying the idempotency key (greppable from a PR number) and `runId` (the join key to the run's own lifecycle logs, which is what makes the terminal state — served, deadline-killed, or still queued — recoverable from logs alone). The originating case, onprem-k8s#2139, needed a Loki run-lifecycle reconstruction to establish its wake had in fact been served and was then killed by activeDeadlineSeconds=600. Four September re-review strands (BLO-34349, BLO-34393, BLO-34506, BLO-34554) cite the same blind spot. Verified: server typecheck clean; the new test passes, and fails with `expected [] to have a length of 1` when the log line alone is reverted. --- server/src/__tests__/github-webhook.test.ts | 77 ++++++++++++++++++++- server/src/routes/github-webhook.ts | 24 +++++++ 2 files changed, 100 insertions(+), 1 deletion(-) diff --git a/server/src/__tests__/github-webhook.test.ts b/server/src/__tests__/github-webhook.test.ts index f61c3bf0da09..cd640fd10002 100644 --- a/server/src/__tests__/github-webhook.test.ts +++ b/server/src/__tests__/github-webhook.test.ts @@ -8,7 +8,7 @@ import { randomUUID } from "node:crypto"; import crypto from "node:crypto"; import express from "express"; import request from "supertest"; -import { afterAll, beforeAll, beforeEach, describe, expect, it } from "vitest"; +import { afterAll, beforeAll, beforeEach, describe, expect, it, vi } from "vitest"; import { agents, agentWakeupRequests, @@ -22,6 +22,7 @@ import { POSTGRES_POOL_MAX, } from "@paperclipai/db"; import { and, eq, inArray, isNull, sql } from "drizzle-orm"; +import { logger } from "../middleware/logger.js"; import { __test_backLinkAbsoluteUrl, __test_buildDependabotAlertIssueBody, @@ -3154,6 +3155,80 @@ describeEmbeddedPostgres("github-webhook route", () => { expect(runs[0]?.status).toBe("queued"); }); + // BLO-22758. The enqueue path was the ONLY outcome of attemptPrReviewerWake + // that logged nothing: duplicate, no_reviewer, declined, deferred and + // lock-loss all emit a line, so a served PR and a PR whose wake was never + // enqueued produced byte-identical webhook logs. That made a dropped review + // undiagnosable in retrospect (onprem-k8s#2139 needed a Loki run-lifecycle + // reconstruction to establish the wake had in fact been served). + // + // The assertion is on `runId` and `idempotencyKey` specifically, not on the + // message alone: the key is what makes the line greppable from a PR number, + // and the run id is the join to the run's own lifecycle logs — together they + // are what turn "no Ally response" into a terminal state. + it("logs the reviewer-wake enqueue with its idempotency key and run id (BLO-22758)", async () => { + const { agentId } = await seedCompanyAndAgent({ agentName: "Ally" }); + const app = buildApp({ + prReviewerAgentId: agentId, + heartbeatOptions: { paperclipNodeRole: "api", skipQueuedRunDispatch: false }, + }); + const payload = { + action: "opened", + pull_request: { + number: 2139, + title: "Log the reviewer-wake enqueue", + body: null, + head: { ref: "fix/reviewer-wake-enqueue-log", sha: "enqueue-log-head" }, + }, + repository: { full_name: "Blockcast/paperclip" }, + }; + const { body, signature } = signedRequest(payload); + + const infoSpy = vi.spyOn(logger, "info"); + try { + 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-enqueue-log-1") + .set("content-type", "application/json") + .send(body); + expect(res.status).toBe(200); + expect(res.body).toMatchObject({ reviewerWakeFired: true }); + + const runs = await db + .select({ id: heartbeatRuns.id }) + .from(heartbeatRuns) + .where(eq(heartbeatRuns.agentId, agentId)); + expect(runs).toHaveLength(1); + + const enqueueLogs = infoSpy.mock.calls.filter( + ([, msg]) => msg === "github webhook reviewer wake enqueued", + ); + expect(enqueueLogs).toHaveLength(1); + expect(enqueueLogs[0]?.[0]).toMatchObject({ + agentId, + event: "pull_request", + deliveryId: "delivery-enqueue-log-1", + // PR-scoped, with no delivery suffix: an `opened` redelivery must + // coalesce onto the same wake. Comment- and head-scoped reasons carry a + // suffix instead (see the ready_for_review key above), so pinning the + // literal here also pins which scope this branch dedups on. + idempotencyKey: "pr_review:Blockcast/paperclip:2139:github_pr_opened", + wakeReason: "github_pr_opened", + prNumber: 2139, + repoFullName: "Blockcast/paperclip", + runId: runs[0]!.id, + }); + // Not merely present: a null wake id would leave the durable request row + // unreachable from the log, which is half of what the line is for. + expect((enqueueLogs[0]?.[0] as { wakeupRequestId?: string | null }).wakeupRequestId) + .toEqual(expect.any(String)); + } finally { + infoSpy.mockRestore(); + } + }); + // BLO-32198. The head-attestation gate suppresses a reviewer wake for a head // an operative Ally App review already attests. These two tests exist because // the suppression path is SILENT and destructive in one direction: a wake diff --git a/server/src/routes/github-webhook.ts b/server/src/routes/github-webhook.ts index 0b7f9fbfa120..b6cca41d197b 100644 --- a/server/src/routes/github-webhook.ts +++ b/server/src/routes/github-webhook.ts @@ -3187,6 +3187,30 @@ async function attemptPrReviewerWake(params: { // terminal for this delivery. if (wakeResult) { recordGithubReviewRequestDelivery({ state: "queued", reason: context.wakeReason }); + // BLO-22758: the success side must be as loud as the failures. Every + // other outcome of this function logs (duplicate/no_reviewer/declined + // above, deferred and lock-loss in the caller), so before this line a + // *served* PR and a PR whose wake was never enqueued emitted a + // byte-identical webhook trail — "the wake was created and the run was + // lost" and "the wake was never created" were observationally + // identical. The counter alone cannot close that: it is aggregate, so + // it cannot answer the question for ONE PR. `runId` is the join key to + // the run's own lifecycle logs, which is what makes the terminal state + // (served / deadline-killed / still queued) recoverable from logs. + logger.info( + { + agentId: reviewerAgentId, + event: eventName, + deliveryId, + idempotencyKey, + wakeReason: context.wakeReason, + prNumber: context.prNumber, + repoFullName: context.repoFullName, + runId: wakeResult.id, + wakeupRequestId: wakeResult.wakeupRequestId, + }, + "github webhook reviewer wake enqueued", + ); return "queued"; } // The terminal `suppressed` increment is NOT emitted here: the wake