Skip to content

fix(github-webhook): log the reviewer-wake enqueue (BLO-22758) - #1952

Merged
kkroo merged 1 commit into
masterfrom
fix/blo-22758-reviewer-wake-enqueue-log
Sep 23, 2026
Merged

kkroo merged 1 commit into
masterfrom
fix/blo-22758-reviewer-wake-enqueue-log

Conversation

@allyblockcast

@allyblockcast allyblockcast Bot commented Sep 20, 2026 •

Copy link
Copy Markdown

Thinking Path

  • Paperclip is the open source app people use to manage AI agents for work
  • One of its jobs is waking the Ally reviewer agent when a GitHub PR event arrives — attemptPrReviewerWake in server/src/routes/github-webhook.ts
  • That function has four outcomes, and every one of them logs except success: duplicate, no_reviewer and declined each emit a line, 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 produce a byte-identical webhook trail — for any individual PR, "the wake was created and the run was lost" cannot be told apart from "the wake was never created"
  • The queued counter added by 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
  • This pull request adds the missing success-side log line, carrying the idempotency key and the resulting run id
  • The benefit is that a dropped PR review becomes diagnosable from logs alone: the originating case needed a manual Loki run-lifecycle reconstruction to establish its wake had been served and was then killed by activeDeadlineSeconds=600

Linked Issues or Issue Description

What Changed

  • server/src/routes/github-webhook.ts — one logger.info("github webhook reviewer wake enqueued") in the queued branch of attemptPrReviewerWake, carrying agentId, event, deliveryId, idempotencyKey, wakeReason, prNumber, repoFullName, runId, wakeupRequestId.
  • server/src/__tests__/github-webhook.test.ts — a DB-backed test on the github_pr_opened branch asserting the line and its full field set, including that runId equals the id of the run actually queued.

Two fields are load-bearing and the rest are context. idempotencyKey makes the line greppable from a PR number. runId is the join key from the webhook line into the run's own lifecycle logs — that join is what converts "no Ally response" into a terminal state (served / deadline-killed / still queued).

No control-flow change, no gate change, no schema change. Log-only.

Verification

pnpm --filter @paperclipai/server typecheck                        EXIT=0
npx vitest run server/src/__tests__/github-webhook.test.ts \
  -t "reviewer-wake enqueue"                                       1 passed

Mutation-tested. A test written alongside a fix asserts on output the fix already produces — that proves the fix works, not that the test would notice its removal. Reverting the logger.info alone, test untouched:

AssertionError: expected [] to have a length of 1 but got +0
  3208|       expect(enqueueLogs).toHaveLength(1);
Tests  1 failed | 267 skipped

One behaviour the test pins deliberately: for github_pr_opened the key is PR-scoped with no delivery suffix (pr_review:<repo>:<n>:github_pr_opened), so an opened redelivery coalesces onto the same wake, where comment- and head-scoped reasons carry a suffix. My first assertion guessed a suffixed key and failed, which is how the property got pinned.

Not run: repo-wide typecheck/test/build. Per AGENTS.md §7 ("run the smallest relevant verification first") this is a two-file, log-only change.

Risks

Low risk. The statement is a logger.info on a path that already commits a durable wake row; it cannot change dispatch, dedup, or gating. The only plausible downside is log volume — bounded by one line per successfully enqueued reviewer wake, which is strictly fewer than the duplicate lines already emitted on the same path.

No secrets or tokens are in the logged fields: ids, a repo name, a PR number, and the idempotency key, which is derived from repo + PR number + wake reason.

Model Used

  • Claude Opus 4.5 (claude-opus-5[1m] as configured for this agent), 1M context, extended thinking, with tool use and code execution. Authored by the PlatformSREEngineer Paperclip agent.

Checklist

  • I have included a thinking path that traces from project context to this change
  • I have specified the model used (with version and capability details)
  • I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work — this is an observability bug fix, not core feature work
  • I have searched GitHub for duplicate or related PRs and linked them above — searched open PRs touching github-webhook.ts (fix(github-webhook): require review structure before an App-seat comment is review feedback (PEN-3383) #1940 review-structure classification, refactor(db): export DbTransaction and drop 20 re-derivations (BLO-34656) #1932 DB type refactor; neither touches attemptPrReviewerWake's outcome branches) and for existing "reviewer wake enqueue" work; none found. grep -rn "reviewer wake enqueued" server/src at master returns nothing.
  • I have either (a) linked existing issues with Fixes: # / Closes # / Refs # OR (b) described the issue in-PR following the relevant issue template
  • I have run tests locally and they pass
  • I have added or updated tests where applicable
  • If this change affects the UI, I have included before/after screenshots — n/a, no UI surface
  • I have updated relevant documentation to reflect my changes — n/a; the log line is self-describing and no doc enumerates webhook log signatures
  • I have considered and documented any risks above
  • All Paperclip CI gates are green — pending; will not request merge until they are
  • Greptile is 5/5 with no open P2s, recommendations, or follow-ups — not yet run
  • I will address all Greptile and reviewer comments before requesting merge

`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.
@allyblockcast

allyblockcast Bot commented Sep 20, 2026

Copy link
Copy Markdown
Author

🔗 Paperclip issue: BLO-18859
🔗 Paperclip issue: BLO-22758
🔗 Paperclip issue: BLO-34554
🔗 Paperclip issue: BLO-34349
🔗 Paperclip issue: BLO-34506
🔗 Paperclip issue: BLO-34393

1 similar comment
@allyblockcast

allyblockcast Bot commented Sep 20, 2026

Copy link
Copy Markdown
Author

🔗 Paperclip issue: BLO-18859
🔗 Paperclip issue: BLO-22758
🔗 Paperclip issue: BLO-34554
🔗 Paperclip issue: BLO-34349
🔗 Paperclip issue: BLO-34506
🔗 Paperclip issue: BLO-34393

@allyblockcast

allyblockcast Bot commented Sep 20, 2026 •

Copy link
Copy Markdown
Author

✅ All checks passing — ready for Greptile review and maintainer approval.

— commitperclip

@github-actions

Copy link
Copy Markdown

@ally head 16358bf has been awaiting review for 1.6h with no review on either surface (pulls/1952/reviews carries no consolidated report for this head, no ## Ally comment either) -- automated sweep (BLO-22892 / BLO-28203), not a human/agent re-ask.

Requested a review from @allyblockcast directly (native GitHub review request, not just this comment) against current head 16358bf.

@github-actions
github-actions Bot requested review from allyblockcast and removed request for allyblockcast September 20, 2026 08:29
@github-actions

Copy link
Copy Markdown

@ally head 16358bf has been awaiting review for 4.4h with no review on either surface (pulls/1952/reviews carries no consolidated report for this head, no ## Ally comment either) -- automated sweep (BLO-22892 / BLO-28203), not a human/agent re-ask.

Requested a review from @allyblockcast directly (native GitHub review request, not just this comment) against current head 16358bf.

@github-actions
github-actions Bot requested review from allyblockcast and removed request for allyblockcast September 20, 2026 13:24
@github-actions

Copy link
Copy Markdown

@ally head 16358bf has been awaiting review for 6.5h with no review on either surface (pulls/1952/reviews carries no consolidated report for this head, no ## Ally comment either) -- automated sweep (BLO-22892 / BLO-28203), not a human/agent re-ask.

Requested a review from @allyblockcast directly (native GitHub review request, not just this comment) against current head 16358bf.

@allyblockcast allyblockcast Bot left a comment

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ally — Consolidated PR Review

Lenses: pr-review-toolkit (code, tests, comments, errors, types) + gstack/review + native-codex.
Reviewed head: 16358bf

Looks good. The change is tightly scoped to the one branch of attemptPrReviewerWake that
was silent, and the accompanying test pins the fields that make the line useful rather than
just asserting the message fired.

Verified against the head tree rather than the diff alone:

  • The premise in the comment holds. duplicate (:3132), no_reviewer (:3158) and
    declined (:3231) all log; the wakeResult truthy branch was the only outcome of this
    function that emitted nothing, so a served PR and a never-enqueued wake were in fact
    indistinguishable in the webhook trail.
  • Placement is correct: inside if (wakeResult), after the queued counter increment and
    before return "queued", so it cannot fire on the null-result gate-declined path that
    the surrounding comment carefully distinguishes.
  • runId: wakeResult.id is asserted in the test against a row selected from heartbeatRuns,
    so the claim that it joins to the run's own lifecycle logs is checked, not just stated.
  • No secret or user-content field is logged — repoFullName and prNumber only, no title or
    body. Volume is bounded by PR events, so info is the right level.
  • Typecheck and all four server test shards are green at this head, so the property access on
    wakeResult and the vi.spyOn(logger, "info") interception both resolve against the real
    module instance.

Critical Issues (0)

Important Issues (0)

Suggestions (2)

  • [native-codex] server/src/routes/github-webhook.ts:3204 — the new line uses deliveryId,
    matching the duplicate branch, but the sibling declined warn just below this hunk uses
    githubDeliveryId for the same value, and the no_reviewer warn omits it entirely. Since the
    stated goal is reconstructing one PR's wake outcome from logs, a field-name filter on
    deliveryId silently misses the declined case. Pre-existing and not introduced here, but this
    PR is the one that completes the diagnostic story, so it is the natural place to normalise it.
  • [pr-review-toolkit/tests] server/src/__tests__/github-webhook.test.ts:3187 — this is the
    only vi.spyOn in an 11k-line file, so the finally { infoSpy.mockRestore() } is carrying the
    whole isolation guarantee for a pattern nothing else here establishes. It is correct as written;
    worth keeping the restore in finally if this test is ever refactored into a beforeEach.

Strengths

  • The test asserts the idempotency key literal rather than a shape, and the comment explains
    that this deliberately pins which scope the opened branch dedups on — so a future change to
    key scoping breaks a test that says why it cares, instead of silently changing coalescing.
  • wakeupRequestId is asserted as expect.any(String) rather than merely present, with the
    reasoning given: a null there would leave the durable request row unreachable from the log,
    which is half the point of the line.
  • Comment density and the "why, with the ticket and the incident" style match the surrounding
    code exactly; this reads as the same author as the neighbouring BLO-18859 and BLO-32198 blocks.

Recommended Action

  1. No blocking changes requested.
  2. Merge once the remaining required CI checks finish green.

@kkroo
kkroo added this pull request to the merge queue Sep 20, 2026
@allyblockcast

allyblockcast Bot commented Sep 20, 2026

Copy link
Copy Markdown
Author

This PR is clean at its current head but still has an outstanding code-owner review request (allyblockcast). GitHub does not enforce CODEOWNERS on this repository, so the landing routine holds it here rather than enqueuing it.

@github-merge-queue
github-merge-queue Bot removed this pull request from the merge queue due to failed status checks Sep 20, 2026
@kkroo
kkroo added this pull request to the merge queue Sep 21, 2026
@github-merge-queue
github-merge-queue Bot removed this pull request from the merge queue due to failed status checks Sep 21, 2026
@kkroo
kkroo added this pull request to the merge queue Sep 21, 2026
kkroo pushed a commit that referenced this pull request Sep 22, 2026
…e's 150ms budget

`GatewayState.upstreamTimeoutMs` is a single global budget, not per-upstream,
so the 150 ms this test set to trip the deliberately-hanging `stuck` upstream
was also the deadline for the healthy `alpha`. With `failureThreshold: 1`, one
`alpha` response slower than 150 ms opens its breaker for the rest of the test
and `tools/list` returns `[]`:

    AssertionError: expected [] to deeply equal [ 'alpha__search' ]
      packages/mcp-gateway/src/server.test.ts:1445

That ejected the merge group for #1952 on 2026-09-21. A local in-process
upstream is normally single-digit ms, but 150 ms is not much margin on a
runner losing ~50% of its cycles to hypervisor steal (BLO-35090).

Reproduced rather than inferred: squeezing the budget to 1 ms so the healthy
upstream also misses it produces that exact assertion locally.

`hanging` never answers at all, so raising the budget to 1 s does not weaken
what the test checks — the breaker still opens — it only costs wall-clock.
The `elapsed` assertion becomes proportional to the budget for the same
reason: an absolute 1000 ms bound re-introduces the steal sensitivity being
removed.

Verified: 52/52 in the file. Non-vacuity checked by re-squeezing the budget to
1 ms with the fix in place — still red, so the test has not been made blind.
Note the probe now trips the elapsed bound (`expected 64 to be less than 5`)
before reaching the tools assertion.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Merged via the queue into master with commit 82050fb Sep 23, 2026
23 of 24 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant