fix(github-webhook): log the reviewer-wake enqueue (BLO-22758) - #1952
Conversation
`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.
1 similar comment
|
✅ All checks passing — ready for Greptile review and maintainer approval. — commitperclip |
|
@ally head Requested a review from @allyblockcast directly (native GitHub review request, not just this comment) against current head |
|
@ally head Requested a review from @allyblockcast directly (native GitHub review request, not just this comment) against current head |
|
@ally head Requested a review from @allyblockcast directly (native GitHub review request, not just this comment) against current head |
There was a problem hiding this comment.
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; thewakeResulttruthy 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 thequeuedcounter increment and
beforereturn "queued", so it cannot fire on thenull-result gate-declined path that
the surrounding comment carefully distinguishes. runId: wakeResult.idis asserted in the test against a row selected fromheartbeatRuns,
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 —
repoFullNameandprNumberonly, no title or
body. Volume is bounded by PR events, soinfois the right level. - Typecheck and all four server test shards are green at this head, so the property access on
wakeResultand thevi.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 usesdeliveryId,
matching theduplicatebranch, but the siblingdeclinedwarn just below this hunk uses
githubDeliveryIdfor the same value, and theno_reviewerwarn omits it entirely. Since the
stated goal is reconstructing one PR's wake outcome from logs, a field-name filter on
deliveryIdsilently 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
onlyvi.spyOnin an 11k-line file, so thefinally { infoSpy.mockRestore() }is carrying the
whole isolation guarantee for a pattern nothing else here establishes. It is correct as written;
worth keeping the restore infinallyif this test is ever refactored into abeforeEach.
Strengths
- The test asserts the idempotency key literal rather than a shape, and the comment explains
that this deliberately pins which scope theopenedbranch dedups on — so a future change to
key scoping breaks a test that says why it cares, instead of silently changing coalescing. wakeupRequestIdis asserted asexpect.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
- No blocking changes requested.
- Merge once the remaining required CI checks finish green.
|
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. |
…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>
Thinking Path
Linked Issues or Issue Description
received/queueddelivery counters this PR complements with a per-PR signalWhat Changed
server/src/routes/github-webhook.ts— onelogger.info("github webhook reviewer wake enqueued")in thequeuedbranch ofattemptPrReviewerWake, carryingagentId,event,deliveryId,idempotencyKey,wakeReason,prNumber,repoFullName,runId,wakeupRequestId.server/src/__tests__/github-webhook.test.ts— a DB-backed test on thegithub_pr_openedbranch asserting the line and its full field set, including thatrunIdequals the id of the run actually queued.Two fields are load-bearing and the rest are context.
idempotencyKeymakes the line greppable from a PR number.runIdis 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
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.infoalone, test untouched:One behaviour the test pins deliberately: for
github_pr_openedthe key is PR-scoped with no delivery suffix (pr_review:<repo>:<n>:github_pr_opened), so anopenedredelivery 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.infoon 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 theduplicatelines 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-5[1m]as configured for this agent), 1M context, extended thinking, with tool use and code execution. Authored by the PlatformSREEngineer Paperclip agent.Checklist
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 touchesattemptPrReviewerWake's outcome branches) and for existing "reviewer wake enqueue" work; none found.grep -rn "reviewer wake enqueued" server/srcat master returns nothing.Fixes: #/Closes #/Refs #OR (b) described the issue in-PR following the relevant issue template