From 29a521d3e507f27d38a3e0aef53da64c5854c23f Mon Sep 17 00:00:00 2001 From: Pieter Viljoen Date: Mon, 3 Aug 2026 06:20:45 -0700 Subject: [PATCH 1/4] Read the pickup event, so a dead request stops looking like patience A request the reviewer never picks up produces exactly what a slow review produces, which is nothing, and one sat for thirteen and a half hours while the pull request read as waiting on the reviewer. Elapsed time cannot separate them, since a genuinely slow round shows no review either, so the wait reads `copilot_work_started` instead of the clock. A request with no pickup after it ends the wait with exit 50 and the timestamp, because waiting on does not start what nothing is acting on. Two readings this depended on were wrong. `gh pr view --json reviewRequests` omits a Bot reviewer outright, reporting an empty set while the reviewer sits in it, so the pending set is read through GraphQL. And the runbook called removal impossible for want of a named mutation, where `requestReviews` replaces the set when `union` is false, which is the clear half of the recovery it now documents. Recovery stays out of the script, which keeps its no-mutation contract. The digest names the state and the runbook carries the two mutations. Co-Authored-By: Claude Opus 5 (1M context) --- .github/copilot-instructions.md | 37 ++++++++++++- scripts/README.md | 4 +- scripts/pr_review.py | 95 ++++++++++++++++++++++++++++++--- scripts/test_pr_review.py | 83 +++++++++++++++++++++++++++- 4 files changed, 207 insertions(+), 12 deletions(-) diff --git a/.github/copilot-instructions.md b/.github/copilot-instructions.md index c0aace38..9e981eeb 100644 --- a/.github/copilot-instructions.md +++ b/.github/copilot-instructions.md @@ -116,7 +116,8 @@ Known non-working request paths (don't rely on them, and use the `requestReviews - `copilot-pull-request-reviewer` as a requested reviewer slug returns 422. - `requestReviews` with the reviewer's bot node id in **`userIds`** fails with `Could not resolve to User node`, because the Copilot reviewer is a **Bot**, so its node id goes in **`botIds`** (as in the mutation above), never `userIds`. - `suggestedActors(capabilities: [CAN_BE_ASSIGNED])` lists `copilot-swe-agent` (the coding agent), not `copilot-pull-request-reviewer`, so do not source the reviewer's bot node id there. Read it from an existing review per step 1 above. -- There is no `removePullRequestFromReviewRequest` mutation, and removing the reviewer to force a fresh pass is unnecessary anyway, since `requestReviews` with `union: true` re-fires the review on the current head. +- There is no `removePullRequestFromReviewRequest` mutation, but removal is not therefore impossible: `requestReviews` **replaces** the reviewer set when `union` is false (the schema describes `union` as "add users to the set rather than replace"), so an empty `botIds` with `union: false` removes the pending request. Reach for it only in the stuck case below, since `union: true` re-fires a review on the current head without it. +- `gh pr view --json reviewRequests` **omits a Bot reviewer entirely**, reporting an empty set while Copilot sits in it. Read the pending set through GraphQL `reviewRequests`, which returns the `Bot` node, because the REST-backed projection makes a pending request read as no request at all. ### Verify Review Covered Current Head @@ -150,6 +151,40 @@ This path is only for a **genuinely missing** review, meaning no Copilot review **Bound each wait, and read what Copilot actually posted before opening another one.** A poll that widens forever is indistinguishable from a poll that has stopped, and "still pending" is the honest report for exactly as long as evidence supports it. Two readings decide whether waiting again is warranted. Compare the request's timestamp against the newest Copilot activity of **any** kind on the pull request, since a reviewer that has already answered on a later head, or that posted an issue comment instead of a formal review, is not a reviewer running late, and a wait that keeps reporting "pending" against a landed review is a broken wait rather than a slow reviewer. Then read that newest response, because a Copilot answer naming a quota or a rate limit is a **terminal** outcome rather than a pending one: no formal review will land, so path (1) never matches the head and path (2) is correctly never confirmed, both paths behave exactly as specified, and the agent waits for something that is not coming. The fix is account-side and re-requesting does not change it, so report it to the maintainer and stop waiting. Where the newest response is neither a review nor a refusal you recognize, that too goes to the maintainer with its text, rather than being waited through. +**A pending request nothing picked up is a third state, and it is the one that looks most like patience.** Copilot raises a `copilot_work_started` timeline event within about half a minute of accepting a request, and submits its review a few minutes later. A request that never draws one is not a slow review, it is a request nothing is acting on, and it stays that way indefinitely: one sat for thirteen and a half hours while the pull request read as waiting on the reviewer. Elapsed time cannot tell the two apart, since a genuinely slow round also shows no review, so read the event rather than the clock. `copilot_work_started` appears in the REST timeline only, and no GraphQL timeline item carries it: + +```sh +# The pending set (GraphQL, since the `gh pr view` projection cannot see a Bot reviewer). +gh api graphql -f query=' +{ repository(owner:"",name:""){ pullRequest(number:){ + reviewRequests(first:10){ totalCount + nodes{ requestedReviewer{ __typename ... on Bot{login} ... on User{login} } } } } } }' + +# The request and pickup events, newest last. A `review_requested` with no later +# `copilot_work_started` is the stuck state. +gh api --paginate repos///issues//timeline \ + --jq '.[] | select(.event == "copilot_work_started" or .event == "review_requested") + | "\(.event) \(.created_at)"' +``` + +**Recover it by clearing the request and requesting again**, because the pull request UI offers no re-request control while a request is pending, and `requestReviews` with `union: true` adds a reviewer already in the set, which changes nothing. Read the pending set first, since `union: false` replaces the whole set and would drop a human reviewer requested alongside the bot. Where the clear-and-request does not draw a `copilot_work_started` within a minute or so, push a commit instead, since a new head raises a fresh request rather than poking a stale one. + +```sh +PR_NODE=$(gh pr view --json id --jq '.id') +# 1. Clear. `union: false` replaces the set, so an empty botIds removes the pending request. +gh api graphql -f query=' +mutation($pr: ID!) { + requestReviews(input: { pullRequestId: $pr, botIds: [], union: false }) { + pullRequest { reviewRequests(first: 10) { totalCount } } } +}' -F pr="$PR_NODE" +# 2. Request again, against a now-empty set, with $BOT_ID read as in "Triggering and Polling". +gh api graphql -f query=' +mutation($pr: ID!, $bot: ID!) { + requestReviews(input: { pullRequestId: $pr, botIds: [$bot], union: true }) { + pullRequest { reviewRequests(first: 10) { totalCount } } } +}' -F pr="$PR_NODE" -F bot="$BOT_ID" +``` + If a review did not run on the current head, retry: 1. Wait briefly and check head-SHA coverage (see above). diff --git a/scripts/README.md b/scripts/README.md index 4e27b4ba..ed2d073a 100644 --- a/scripts/README.md +++ b/scripts/README.md @@ -95,7 +95,9 @@ python3 scripts/pr_review.py wait 452 --timeout 2700 `wait` exits `40` when Copilot answers the request with a plain comment rather than a review, meaning a comment of its own that postdates its newest review on the pull request. The test is the **shape** of that answer and not its cause, which the script reads nothing of: a comment carries no commit, so it satisfies no coverage check whatever it says, and a wait reading formal reviews alone treats it as an unmet condition and then polls out its whole timeout against an answer that already arrived. A refusal is the case that makes this worth catching, a quota or rate-limit message among them, and `40` neither asserts nor detects one. The comment prints whole because its wording is the only thing separating a refusal, which is terminal since no review follows it and re-requesting does not clear it, from an ordinary remark that is not, so `40` ends the wait and hands the text to the reader who can tell them apart. A comment **older** than the newest review is spent rather than terminal, because the review it preceded did land. Every connection reads the newest `WINDOW` nodes rather than the reviewer's own, since GraphQL offers no author filter, so ordinary traffic is what pushes theirs out of reach. `window_blind` is the one guard over both sides, and each side fails differently. Blind on **comments** means an answer could be back there unseen, which reads as `answered_outside_review=unknown` rather than `no`. Blind on **reviews** is worse, because the newest review in view is then not the newest there is, and an empty baseline dates every comment as newer so each one reads as an answer: a false `40` that stops the loop on a pull request whose review actually landed. That case reports nothing and lets the wait keep polling, since a wait that runs on is visible where a wrong terminal is not. -Everything else is decidable and says so. One of the reviewer's own nodes in view, even a **spent** one, settles the question, because nodes arrive in creation order, so anything behind the window is older than everything inside it. A window holding every node the pull request has is settled too, which is why the guard reads `pageInfo.hasPreviousPage` rather than the node count: a full window and a complete one are the same length, so length alone would report a gap where none exists. Cases hold `WINDOW` equal across all four windows and hold all four to asking for `hasPreviousPage`, since a connection that stops asking reports `no` instead of `unknown`, the silent narrowing one level up. The timeout path prints the full digest for the same reason, as a bare `PENDING` line reports a slow reviewer and a broken poll identically, which is the reading that turns a stalled watcher into a watcher nobody notices is stalled. +Everything else is decidable and says so. One of the reviewer's own nodes in view, even a **spent** one, settles the question, because nodes arrive in creation order, so anything behind the window is older than everything inside it. A window holding every node the pull request has is settled too, which is why the guard reads `pageInfo.hasPreviousPage` rather than the node count: a full window and a complete one are the same length, so length alone would report a gap where none exists. Cases hold `WINDOW` equal across all four windows and hold all four to asking for `hasPreviousPage`, since a connection that stops asking reports `no` instead of `unknown`, the silent narrowing one level up. `wait` exits `50` when the reviewer sits in the pending request set and no `copilot_work_started` follows the newest request, meaning nothing is acting on it and waiting on will not start it. That state is invisible from the reviews alone and indistinguishable from patience: one request sat thirteen and a half hours while the pull request read as waiting on the reviewer. Elapsed time cannot separate it from a slow round either, so the pickup event decides. It is the one thing here read over REST, since no GraphQL timeline item carries it, and it is read only after `--pickup-grace` (default five minutes) rather than per poll, because inside that grace a pending request is simply a review being worked on. The pickup is checked **before** the timeout, so the stall reports as itself instead of as `PENDING` once the clock runs out. Recovery stays out of this script, which holds its no-mutation contract: the digest names the state and the runbook carries the two mutations that clear and re-raise the request. The pending set is read through GraphQL rather than `gh pr view --json reviewRequests`, which omits a Bot reviewer outright and reports an empty set while Copilot sits in it. + +The timeout path prints the full digest for the same reason, as a bare `PENDING` line reports a slow reviewer and a broken poll identically, which is the reading that turns a stalled watcher into a watcher nobody notices is stalled. The digest also reports the **suppressed findings** a review body collapses into a `
` block. Those reach no review thread, so a loop that polls threads alone reports a clean pass while they stand, and the [merge gate][governance] counts them as outstanding findings either way. `suppressed=N` counts findings rather than blocks, reading the `(N)` the heading carries, since one body holds one block per round and counting blocks reports two findings as one. It covers **every** round rather than the current head, because a suppressed finding has no resolved state for a push to retire: head-scoping read "superseded by a push" as "answered", and a finding nobody replied to left the digest the moment the branch moved, so the run reported zero. That is how four rounds went unanswered across three pull requests in one day, each found by the maintainer rather than by this script. The summary line splits the count as `suppressed=N (on_head=N earlier=N)` and each block is marked with the round that raised it, since a finding on an older round may since be moot and deciding that is the reader's call rather than one the count should make for them. Each block prints whole where a thread body truncates, because a thread can be re-read at its id and a suppressed finding cannot, and it prints under a marker naming what closing it takes: no thread exists to reply on or resolve, so the answer goes in the PR conversation. diff --git a/scripts/pr_review.py b/scripts/pr_review.py index 2e86796d..705bff10 100644 --- a/scripts/pr_review.py +++ b/scripts/pr_review.py @@ -15,6 +15,8 @@ 40 = Copilot answered outside a formal review, so read the printed body. 40 reports the shape of that answer and reads nothing of its cause: an answer carrying no commit covers no head, so the wait ends and the reader decides. + 50 = the request is pending and nothing picked it up, which no amount of + waiting changes. Recovery is two mutations, and they stay in the runbook. Read-only by design. Mutations (re-request review, reply, resolve thread) are deliberately NOT implemented here - they are state-changing calls that must stay @@ -51,6 +53,7 @@ headRefOid reviews(last:100){ nodes{ author{login} state commit{oid} submittedAt } pageInfo{ hasPreviousPage } } comments(last:100){ nodes{ author{login} createdAt } pageInfo{ hasPreviousPage } } + reviewRequests(first:10){ nodes{ requestedReviewer{ __typename ... on Bot{login} ... on User{login} } } } }}} """ @@ -63,6 +66,7 @@ reviewThreads(first:100){ nodes{ id isResolved comments(first:1){ nodes{ author{login} path line body } } }} comments(last:100){ nodes{ author{login} createdAt body } pageInfo{ hasPreviousPage } } + reviewRequests(first:10){ nodes{ requestedReviewer{ __typename ... on Bot{login} ... on User{login} } } } }}} """ @@ -78,6 +82,52 @@ def gql(query: str, owner: str, repo: str, num: int) -> dict: return json.loads(r.stdout)['data']['repository']['pullRequest'] +def timeline(owner: str, repo: str, num: int) -> list[tuple[str, str]]: + """The request and pickup events, oldest first, as (event, timestamp). + + GraphQL carries no `copilot_work_started`, so this is the one REST reader here. + `--jq` projects inside gh rather than after it, since `--paginate` without one emits a + concatenated array per page that is not valid JSON on every gh a fleet machine may carry. + """ + r = subprocess.run( + ['gh', 'api', '--paginate', f'repos/{owner}/{repo}/issues/{num}/timeline', + '--jq', '.[] | select(.event == "copilot_work_started" or .event == "review_requested")' + ' | "\\(.event) \\(.created_at)"'], + capture_output=True, text=True) + if r.returncode != 0: + sys.stderr.write(r.stderr[:800]) + raise SystemExit(f'gh timeline failed rc={r.returncode}') + return [(ln.split(' ', 1)[0], ln.split(' ', 1)[1]) + for ln in r.stdout.splitlines() if ' ' in ln] + + +def never_picked_up(events: list[tuple[str, str]]) -> str: + """The newest request's timestamp where no pickup followed it, otherwise the empty string. + + A request the reviewer accepts raises `copilot_work_started` within about half a minute, so + a request with no pickup after it is not a slow review, it is a request nothing is acting on. + The two states look identical from the reviews alone, which is how one sat for thirteen hours + reading as pending. Elapsed time cannot separate them either, since a genuinely slow round + also produces no review, and only the pickup event says whether anything is working. + """ + requested = [t for e, t in events if e == 'review_requested'] + started = [t for e, t in events if e == 'copilot_work_started'] + if not requested: + return '' + newest = max(requested) + return '' if any(t >= newest for t in started) else newest + + +def reviewer_requested(pr: dict) -> bool: + """True where the reviewer sits in the pending request set. + + Read from GraphQL rather than `gh pr view --json reviewRequests`, which omits a Bot + reviewer entirely and reports an empty set while the reviewer is sitting in it. + """ + return any((n.get('requestedReviewer') or {}).get('login') == REVIEWER + for n in ((pr.get('reviewRequests') or {}).get('nodes') or [])) + + def reviewer_nodes(pr: dict, field: str) -> list[dict]: """The reviewer's own nodes under `field`, oldest first as the API returns them.""" return [n for n in ((pr.get(field) or {}).get('nodes') or []) @@ -118,13 +168,17 @@ def window_blind(pr: dict, field: str) -> bool: return bool(older) and not reviewer_nodes(pr, field) +def reviewed_head(pr: dict) -> bool: + """True where one of the reviewer's own reviews carries the current head's commit.""" + head = pr['headRefOid'] + return any((n.get('commit') or {}).get('oid') == head + for n in reviewer_nodes(pr, 'reviews')) + + def live_state(owner: str, repo: str, num: int) -> tuple[str, bool, dict | None]: """Return (head_sha, copilot_reviewed_current_head, copilot_answer_outside_a_review).""" pr = gql(Q_LIVE, owner, repo, num) - head = pr['headRefOid'] - done = any((n.get('commit') or {}).get('oid') == head - for n in reviewer_nodes(pr, 'reviews')) - return head, done, answered_outside_review(pr) + return pr['headRefOid'], reviewed_head(pr), answered_outside_review(pr) def heading_of(block: str) -> str: @@ -192,8 +246,14 @@ def digest(owner: str, repo: str, num: int, seen: set[str] | None = None) -> tup f'suppressed={sum(finding_count(b) for n, b in blocks)} ' f'(on_head={sum(finding_count(b) for b in on_head_blocks)} earlier={stale}) ' f'answered_outside_review={answered} ' + f'requested={"yes" if reviewer_requested(pr) else "no"} ' f'merge={pr.get("mergeStateStatus")}' ] + if reviewer_requested(pr) and not on_head: + stalled = never_picked_up(timeline(owner, repo, num)) + if stalled: + lines.append(f' REQUEST NOT PICKED UP (requested {stalled}, no copilot_work_started ' + 'since): clear the request and re-request, per the runbook') if blind: lines.append(f' BEHIND THE WINDOW ({" and ".join(blind)}): the newest {WINDOW} carry ' 'none from the reviewer and older ones exist, so this cannot decide') @@ -245,6 +305,8 @@ def main(argv: list[str] | None = None) -> int: ap.add_argument('number', type=int) ap.add_argument('--repo', default='ptr727/ProjectTemplate') ap.add_argument('--timeout', type=int, default=2700, help='seconds (default 45m)') + ap.add_argument('--pickup-grace', type=int, default=300, + help='seconds before a pending request is read for pickup (default 5m)') a = ap.parse_args(argv) owner, repo = a.repo.split('/', 1) @@ -256,23 +318,40 @@ def main(argv: list[str] | None = None) -> int: # In-process backoff, so the whole wait costs one agent turn. delays = [15, 20, 30, 45, 60, 120] start = time.monotonic() - _, done, answer = live_state(owner, repo, a.number) + pr = gql(Q_LIVE, owner, repo, a.number) + done, answer = reviewed_head(pr), answered_outside_review(pr) + stalled = '' i = 0 while not done and not answer: - if time.monotonic() - start > a.timeout: + elapsed = time.monotonic() - start + # Read the pickup before the clock, so a request nothing acted on reports as itself. + # Running the clock out instead would report it exactly as a slow reviewer. + # The read costs a second call, so it waits out the grace rather than running per poll. + # Inside the grace a pending request is simply a review being worked on. + if elapsed > a.pickup_grace and reviewer_requested(pr): + stalled = never_picked_up(timeline(owner, repo, a.number)) + if stalled: + break + if elapsed > a.timeout: # The timeout is where the digest's one extra call is worth most. # A bare PENDING line reports a broken wait and a slow reviewer identically. out, _ = digest(owner, repo, a.number) print(out) - print(f'status=PENDING waited={int(time.monotonic()-start)}s') + print(f'status=PENDING waited={int(elapsed)}s') return 30 time.sleep(delays[min(i, len(delays) - 1)]) i += 1 # Re-read head each iteration: a push during the wait moves it. - _, done, answer = live_state(owner, repo, a.number) + pr = gql(Q_LIVE, owner, repo, a.number) + done, answer = reviewed_head(pr), answered_outside_review(pr) out, _ = digest(owner, repo, a.number) print(out) print(f'waited={int(time.monotonic()-start)}s') + if stalled and not done: + print(f'status=REQUEST_NOT_PICKED_UP requested {stalled} and no copilot_work_started ' + 'followed it, so nothing is working on this and waiting on will not start it: ' + 'clear the request and re-request, per the runbook') + return 50 if not done: print('status=ANSWERED_OUTSIDE_REVIEW the reviewer answered without reviewing, ' 'so read the comment above and decide, since where it declines or names a limit ' diff --git a/scripts/test_pr_review.py b/scripts/test_pr_review.py index b032bfbf..9bfc44dc 100644 --- a/scripts/test_pr_review.py +++ b/scripts/test_pr_review.py @@ -52,11 +52,14 @@ def thread(tid: str, resolved: bool = False, login: str = pr_review.REVIEWER, def payload(reviews: list[dict], threads: list[dict] | None = None, merge: str = 'CLEAN', comments: list[dict] | None = None, - older: bool = False, older_reviews: bool = False) -> dict: + older: bool = False, older_reviews: bool = False, pending: bool = False) -> dict: + requested = ([{'requestedReviewer': {'__typename': 'Bot', 'login': pr_review.REVIEWER}}] + if pending else []) return {'headRefOid': HEAD, 'mergeable': 'MERGEABLE', 'mergeStateStatus': merge, 'reviews': {'nodes': reviews, 'pageInfo': {'hasPreviousPage': older_reviews}}, 'reviewThreads': {'nodes': threads or []}, - 'comments': {'nodes': comments or [], 'pageInfo': {'hasPreviousPage': older}}} + 'comments': {'nodes': comments or [], 'pageInfo': {'hasPreviousPage': older}}, + 'reviewRequests': {'nodes': requested}} class GqlCase(unittest.TestCase): @@ -163,6 +166,47 @@ def test_one_spent_reviewer_comment_in_view_settles_the_question(self) -> None: self.assertFalse(pr_review.window_blind(pr, 'comments')) +class TestPickup(unittest.TestCase): + """A request nothing acted on and a review being worked on are one reading from the reviews.""" + + def test_a_request_with_no_pickup_after_it_is_named_by_its_timestamp(self) -> None: + """The shape that sat thirteen hours reading as pending: requested, never started.""" + events = [('review_requested', '2026-08-02T22:58:15Z'), + ('copilot_work_started', '2026-08-02T22:58:45Z'), + ('review_requested', '2026-08-03T00:15:00Z')] + self.assertEqual('2026-08-03T00:15:00Z', pr_review.never_picked_up(events)) + + def test_a_request_the_reviewer_took_up_is_not_stalled(self) -> None: + """Slow is not stuck, and only the pickup event tells them apart.""" + events = [('review_requested', '2026-08-03T13:09:19Z'), + ('copilot_work_started', '2026-08-03T13:09:54Z')] + self.assertEqual('', pr_review.never_picked_up(events)) + + def test_an_earlier_pickup_does_not_cover_a_later_request(self) -> None: + """Answering the last request is not answering this one, and order is what says so.""" + events = [('copilot_work_started', '2026-08-02T22:58:45Z'), + ('review_requested', '2026-08-02T23:31:44Z')] + self.assertEqual('2026-08-02T23:31:44Z', pr_review.never_picked_up(events)) + + def test_no_request_at_all_is_not_a_stall(self) -> None: + self.assertEqual('', pr_review.never_picked_up( + [('copilot_work_started', '2026-08-02T22:58:45Z')])) + self.assertEqual('', pr_review.never_picked_up([])) + + def test_the_pending_set_is_read_where_a_bot_reviewer_is_visible(self) -> None: + """`gh pr view --json reviewRequests` omits a Bot outright and reports an empty set.""" + pending = {'reviewRequests': {'nodes': [ + {'requestedReviewer': {'__typename': 'Bot', 'login': pr_review.REVIEWER}}]}} + self.assertTrue(pr_review.reviewer_requested(pending)) + human = {'reviewRequests': {'nodes': [ + {'requestedReviewer': {'__typename': 'User', 'login': 'ptr727'}}]}} + self.assertFalse(pr_review.reviewer_requested(human)) + self.assertFalse(pr_review.reviewer_requested({'reviewRequests': {'nodes': []}})) + # A null reviewer is what a deleted account leaves behind, and it must not raise. + self.assertFalse(pr_review.reviewer_requested( + {'reviewRequests': {'nodes': [{'requestedReviewer': None}]}})) + + class TestDigest(GqlCase): def test_the_summary_line_counts_what_it_names(self) -> None: self.answer(payload([review(), review(oid=OLD)], @@ -427,6 +471,41 @@ def test_a_landed_review_wins_over_an_older_answer(self) -> None: with mock.patch.object(pr_review.time, 'sleep'): self.assertEqual(0, pr_review.main(['wait', '7'])) + def test_wait_stops_on_a_request_nothing_picked_up(self) -> None: + """Waiting on cannot start a request nothing is acting on, so the wait says so and ends. + + The zero timeout is what this fails on rather than hangs on, and it also pins the order: + the pickup is read before the clock, so the stall reports as itself instead of as PENDING. + """ + self.answer(payload([review(oid=OLD)], pending=True)) + with mock.patch.object(pr_review, 'timeline', + return_value=[('review_requested', LATE)]), \ + mock.patch.object(pr_review.time, 'sleep'): + self.assertEqual(50, pr_review.main( + ['wait', '7', '--pickup-grace', '0', '--timeout', '0'])) + out = self.out.getvalue() + self.assertIn('status=REQUEST_NOT_PICKED_UP', out) + self.assertIn(LATE, out) + + def test_a_request_being_worked_on_is_not_stopped_on(self) -> None: + """A slow round is the case the grace exists for, and stopping on it loses the review.""" + self.answer(payload([review(oid=OLD)], pending=True), payload([review()], pending=True)) + with mock.patch.object(pr_review, 'timeline', + return_value=[('review_requested', EARLY), + ('copilot_work_started', LATE)]), \ + mock.patch.object(pr_review.time, 'sleep'): + self.assertEqual(0, pr_review.main( + ['wait', '7', '--pickup-grace', '0', '--timeout', '600'])) + + def test_the_pickup_read_waits_out_the_grace_rather_than_running_per_poll(self) -> None: + """It costs a second call, and inside the grace a pending request is just work in flight.""" + self.answer(payload([review(oid=OLD)], pending=True), payload([review()], pending=True)) + with mock.patch.object(pr_review, 'timeline', return_value=[]) as seen, \ + mock.patch.object(pr_review.time, 'sleep'): + self.assertEqual(0, pr_review.main( + ['wait', '7', '--pickup-grace', '9999', '--timeout', '600'])) + seen.assert_not_called() + def test_the_repo_argument_splits_into_owner_and_name(self) -> None: self.answer(payload([review()])) with mock.patch.object(pr_review, 'digest', return_value=('x', 0)) as dig: From 3c569bace7078489e916297d60aa6dc689573e18 Mon Sep 17 00:00:00 2001 From: Pieter Viljoen Date: Mon, 3 Aug 2026 06:28:49 -0700 Subject: [PATCH 2/4] Run the pickup read on an interval, as its comment already claimed The comment and the README said the read avoids running per poll, and past the grace it ran on every one. A forty-minute wait against a picked up request turned one REST reader into thirty-two, which is the rate limit exposure the design was written to avoid, and the documentation described the design rather than the code. The read now waits an interval between readings, the grace serving as both the first delay and the spacing. One reading settles the request in front of it, and the next covers a request a push raises mid-wait, so the later readings are not redundant. A case counts the readings against a stepped clock and was watched failing at thirty-two against the bound. Co-Authored-By: Claude Opus 5 (1M context) --- scripts/README.md | 2 +- scripts/pr_review.py | 10 ++++++---- scripts/test_pr_review.py | 18 ++++++++++++++++++ 3 files changed, 25 insertions(+), 5 deletions(-) diff --git a/scripts/README.md b/scripts/README.md index ed2d073a..dd555d23 100644 --- a/scripts/README.md +++ b/scripts/README.md @@ -95,7 +95,7 @@ python3 scripts/pr_review.py wait 452 --timeout 2700 `wait` exits `40` when Copilot answers the request with a plain comment rather than a review, meaning a comment of its own that postdates its newest review on the pull request. The test is the **shape** of that answer and not its cause, which the script reads nothing of: a comment carries no commit, so it satisfies no coverage check whatever it says, and a wait reading formal reviews alone treats it as an unmet condition and then polls out its whole timeout against an answer that already arrived. A refusal is the case that makes this worth catching, a quota or rate-limit message among them, and `40` neither asserts nor detects one. The comment prints whole because its wording is the only thing separating a refusal, which is terminal since no review follows it and re-requesting does not clear it, from an ordinary remark that is not, so `40` ends the wait and hands the text to the reader who can tell them apart. A comment **older** than the newest review is spent rather than terminal, because the review it preceded did land. Every connection reads the newest `WINDOW` nodes rather than the reviewer's own, since GraphQL offers no author filter, so ordinary traffic is what pushes theirs out of reach. `window_blind` is the one guard over both sides, and each side fails differently. Blind on **comments** means an answer could be back there unseen, which reads as `answered_outside_review=unknown` rather than `no`. Blind on **reviews** is worse, because the newest review in view is then not the newest there is, and an empty baseline dates every comment as newer so each one reads as an answer: a false `40` that stops the loop on a pull request whose review actually landed. That case reports nothing and lets the wait keep polling, since a wait that runs on is visible where a wrong terminal is not. -Everything else is decidable and says so. One of the reviewer's own nodes in view, even a **spent** one, settles the question, because nodes arrive in creation order, so anything behind the window is older than everything inside it. A window holding every node the pull request has is settled too, which is why the guard reads `pageInfo.hasPreviousPage` rather than the node count: a full window and a complete one are the same length, so length alone would report a gap where none exists. Cases hold `WINDOW` equal across all four windows and hold all four to asking for `hasPreviousPage`, since a connection that stops asking reports `no` instead of `unknown`, the silent narrowing one level up. `wait` exits `50` when the reviewer sits in the pending request set and no `copilot_work_started` follows the newest request, meaning nothing is acting on it and waiting on will not start it. That state is invisible from the reviews alone and indistinguishable from patience: one request sat thirteen and a half hours while the pull request read as waiting on the reviewer. Elapsed time cannot separate it from a slow round either, so the pickup event decides. It is the one thing here read over REST, since no GraphQL timeline item carries it, and it is read only after `--pickup-grace` (default five minutes) rather than per poll, because inside that grace a pending request is simply a review being worked on. The pickup is checked **before** the timeout, so the stall reports as itself instead of as `PENDING` once the clock runs out. Recovery stays out of this script, which holds its no-mutation contract: the digest names the state and the runbook carries the two mutations that clear and re-raise the request. The pending set is read through GraphQL rather than `gh pr view --json reviewRequests`, which omits a Bot reviewer outright and reports an empty set while Copilot sits in it. +Everything else is decidable and says so. One of the reviewer's own nodes in view, even a **spent** one, settles the question, because nodes arrive in creation order, so anything behind the window is older than everything inside it. A window holding every node the pull request has is settled too, which is why the guard reads `pageInfo.hasPreviousPage` rather than the node count: a full window and a complete one are the same length, so length alone would report a gap where none exists. Cases hold `WINDOW` equal across all four windows and hold all four to asking for `hasPreviousPage`, since a connection that stops asking reports `no` instead of `unknown`, the silent narrowing one level up. `wait` exits `50` when the reviewer sits in the pending request set and no `copilot_work_started` follows the newest request, meaning nothing is acting on it and waiting on will not start it. That state is invisible from the reviews alone and indistinguishable from patience: one request sat thirteen and a half hours while the pull request read as waiting on the reviewer. Elapsed time cannot separate it from a slow round either, so the pickup event decides. It is the one thing here read over REST, since no GraphQL timeline item carries it, and it runs on its own interval rather than per poll: the first read comes after `--pickup-grace` (default five minutes), because inside that window a pending request is simply a review being worked on, and each later read waits another interval. One reading settles the request in front of it, and the next covers a request a push raises mid-wait, so a long wait costs a handful of REST calls instead of one per poll. The pickup is checked **before** the timeout, so the stall reports as itself instead of as `PENDING` once the clock runs out. Recovery stays out of this script, which holds its no-mutation contract: the digest names the state and the runbook carries the two mutations that clear and re-raise the request. The pending set is read through GraphQL rather than `gh pr view --json reviewRequests`, which omits a Bot reviewer outright and reports an empty set while Copilot sits in it. The timeout path prints the full digest for the same reason, as a bare `PENDING` line reports a slow reviewer and a broken poll identically, which is the reading that turns a stalled watcher into a watcher nobody notices is stalled. diff --git a/scripts/pr_review.py b/scripts/pr_review.py index 705bff10..8fb7b3ca 100644 --- a/scripts/pr_review.py +++ b/scripts/pr_review.py @@ -306,7 +306,7 @@ def main(argv: list[str] | None = None) -> int: ap.add_argument('--repo', default='ptr727/ProjectTemplate') ap.add_argument('--timeout', type=int, default=2700, help='seconds (default 45m)') ap.add_argument('--pickup-grace', type=int, default=300, - help='seconds before a pending request is read for pickup (default 5m)') + help='seconds before the first pickup read, and between reads (default 5m)') a = ap.parse_args(argv) owner, repo = a.repo.split('/', 1) @@ -322,13 +322,15 @@ def main(argv: list[str] | None = None) -> int: done, answer = reviewed_head(pr), answered_outside_review(pr) stalled = '' i = 0 + next_pickup = a.pickup_grace while not done and not answer: elapsed = time.monotonic() - start # Read the pickup before the clock, so a request nothing acted on reports as itself. # Running the clock out instead would report it exactly as a slow reviewer. - # The read costs a second call, so it waits out the grace rather than running per poll. - # Inside the grace a pending request is simply a review being worked on. - if elapsed > a.pickup_grace and reviewer_requested(pr): + # The read costs a second call over REST, so it runs on its own interval, not per poll. + # One reading settles the current request, and the next covers a request a push raises. + if elapsed > next_pickup and reviewer_requested(pr): + next_pickup = elapsed + a.pickup_grace stalled = never_picked_up(timeline(owner, repo, a.number)) if stalled: break diff --git a/scripts/test_pr_review.py b/scripts/test_pr_review.py index 9bfc44dc..db12e803 100644 --- a/scripts/test_pr_review.py +++ b/scripts/test_pr_review.py @@ -10,6 +10,7 @@ """ from __future__ import annotations import contextlib, io, json, re, subprocess, sys, unittest +from itertools import count from pathlib import Path from unittest import mock @@ -506,6 +507,23 @@ def test_the_pickup_read_waits_out_the_grace_rather_than_running_per_poll(self) ['wait', '7', '--pickup-grace', '9999', '--timeout', '600'])) seen.assert_not_called() + def test_the_pickup_read_runs_on_its_own_interval_once_the_grace_is_out(self) -> None: + """Every poll past the grace is what the comment ruled out and the code did anyway. + + The clock advances a fixed step per reading, so the interval is counted rather than + waited: a long wait must not turn one REST reader into one per poll. + """ + picked_up = [('review_requested', EARLY), ('copilot_work_started', LATE)] + self.answer(payload([review(oid=OLD)], pending=True)) + with mock.patch.object(pr_review.time, 'monotonic', side_effect=count(0, 30)), \ + mock.patch.object(pr_review, 'timeline', return_value=picked_up) as seen, \ + mock.patch.object(pr_review.time, 'sleep'): + self.assertEqual(30, pr_review.main( + ['wait', '7', '--pickup-grace', '300', '--timeout', '1200'])) + # Roughly one read per grace interval over the wait, never one per poll. + self.assertGreaterEqual(seen.call_count, 1) + self.assertLessEqual(seen.call_count, 1200 // 300 + 1) + def test_the_repo_argument_splits_into_owner_and_name(self) -> None: self.answer(payload([review()])) with mock.patch.object(pr_review, 'digest', return_value=('x', 0)) as dig: From 93b3701ada366216b30ca3af8a532197524a33c3 Mon Sep 17 00:00:00 2001 From: Pieter Viljoen Date: Mon, 3 Aug 2026 06:33:48 -0700 Subject: [PATCH 3/4] Ask the timeline for the largest page, since pagination is the cost `--paginate` walks the default page size of 30, so the reader's cost scales with how long a pull request has run rather than with what it reads. The 168-event timeline this state was found on takes six requests a reading at 30 and two at 100, against a reader that repeats for the life of a wait. Two cases cover it, one holding the request to the largest page and to being a read, the other holding a failed read to raising rather than returning no events, since an empty list reads as no request pending, which is the false clean this reader exists to close. Co-Authored-By: Claude Opus 5 (1M context) --- scripts/pr_review.py | 4 +++- scripts/test_pr_review.py | 21 +++++++++++++++++++++ 2 files changed, 24 insertions(+), 1 deletion(-) diff --git a/scripts/pr_review.py b/scripts/pr_review.py index 8fb7b3ca..6ce53b14 100644 --- a/scripts/pr_review.py +++ b/scripts/pr_review.py @@ -88,9 +88,11 @@ def timeline(owner: str, repo: str, num: int) -> list[tuple[str, str]]: GraphQL carries no `copilot_work_started`, so this is the one REST reader here. `--jq` projects inside gh rather than after it, since `--paginate` without one emits a concatenated array per page that is not valid JSON on every gh a fleet machine may carry. + `per_page` is the page size the pagination actually costs, and the default of 30 turns a + long-running pull request into six requests a reading where the maximum makes it two. """ r = subprocess.run( - ['gh', 'api', '--paginate', f'repos/{owner}/{repo}/issues/{num}/timeline', + ['gh', 'api', '--paginate', f'repos/{owner}/{repo}/issues/{num}/timeline?per_page=100', '--jq', '.[] | select(.event == "copilot_work_started" or .event == "review_requested")' ' | "\\(.event) \\(.created_at)"'], capture_output=True, text=True) diff --git a/scripts/test_pr_review.py b/scripts/test_pr_review.py index db12e803..4d66caf3 100644 --- a/scripts/test_pr_review.py +++ b/scripts/test_pr_review.py @@ -566,6 +566,27 @@ def test_the_guard_tests_the_window_the_queries_actually_read(self) -> None: self.assertEqual(4, source.count('pageInfo{ hasPreviousPage }')) self.assertEqual(4, len(re.findall(r'(?:comments|reviews)\(last:\d+\)', source))) + def test_the_timeline_reader_asks_for_the_largest_page(self) -> None: + """The page size is what pagination costs, and the default of 30 triples the requests.""" + done = subprocess.CompletedProcess(args=[], returncode=0, stdout='', stderr='') + with mock.patch.object(pr_review.subprocess, 'run', return_value=done) as run: + pr_review.timeline('o', 'r', 7) + argv = run.call_args.args[0] + self.assertIn('repos/o/r/issues/7/timeline?per_page=100', argv) + self.assertIn('--paginate', argv) + # A read, and the guard against a write creeping into the one REST call here. + self.assertEqual(['gh', 'api'], argv[:2]) + self.assertFalse({'-X', '--method'} & set(argv)) + + def test_a_failed_timeline_read_raises_rather_than_reading_as_no_events(self) -> None: + """An empty list reads as no request pending, which is the false clean one level up.""" + failed = subprocess.CompletedProcess(args=[], returncode=1, stdout='', stderr='boom') + with mock.patch.object(pr_review.subprocess, 'run', return_value=failed), \ + contextlib.redirect_stderr(io.StringIO()) as err: + with self.assertRaises(SystemExit): + pr_review.timeline('o', 'r', 7) + self.assertIn('boom', err.getvalue()) + def test_the_backoff_is_bounded_and_non_decreasing(self) -> None: """A wait that sleeps zero seconds is a busy loop, and one that shrinks polls harder later.""" source = (REPO / 'scripts' / 'pr_review.py').read_text(encoding='utf-8') From 3766943f813895901d318f3dc976718d4cea1015 Mon Sep 17 00:00:00 2001 From: Pieter Viljoen Date: Mon, 3 Aug 2026 06:42:29 -0700 Subject: [PATCH 4/4] Take the reviewer's own requests, in the spelling the timeline uses Every `review_requested` event counted as the reviewer's, so a human requested after a review landed became the newest request with no pickup after it, and a picked-up review reported as never picked up. That is a false stop rather than a missed one, on a pull request whose review is sitting there. The timeline spells the reviewer a third way, login `Copilot` with type `Bot`, against GraphQL's `copilot-pull-request-reviewer` and the `[bot]` suffix REST user objects carry. Filtering on either of those two selects nothing, so the predicate is the type plus a loose login match, and the runbook records the third form beside the other two. A case drives the real jq over a crafted timeline rather than asserting on the filter text, which would pass on a filter matching nothing. A negative `--pickup-grace` is also rejected, since it leaves the next reading behind the clock and reinstates the per-poll reads by argument. Co-Authored-By: Claude Opus 5 (1M context) --- .github/copilot-instructions.md | 12 ++++++++---- scripts/pr_review.py | 19 ++++++++++++++++-- scripts/test_pr_review.py | 34 +++++++++++++++++++++++++++++++++ 3 files changed, 59 insertions(+), 6 deletions(-) diff --git a/.github/copilot-instructions.md b/.github/copilot-instructions.md index 9e981eeb..55f8dade 100644 --- a/.github/copilot-instructions.md +++ b/.github/copilot-instructions.md @@ -59,7 +59,7 @@ gh api repos///pulls//reviews --jq \ **Round 1 is normally auto-seeded, so poll for it before trying to self-trigger.** Auto-review-on-open supplies the first review with no `botIds` call needed, but it can lag one to three minutes. After opening a PR (or the first push), **poll** for a Copilot review on the head SHA (see [Verify Review Covered Current Head](#verify-review-covered-current-head)) before concluding none ran. The `requestReviews` mutation below is for **re-requesting on later pushes** (a new head SHA). By then a prior review exists, so its bot node id is readable. A missing bot node id on round 1 therefore means "the auto-review has not landed yet - wait and poll," **not** "ask the maintainer to kick it off." -> **The reviewer login differs by API.** In **GraphQL** (`gh api graphql` and `gh pr view --json reviews`, which is GraphQL-backed) the `Bot.login` is `copilot-pull-request-reviewer`, with **no `[bot]` suffix**. In the **REST** API (`gh api repos/.../issues|pulls/...`) the same account's `user.login` is `copilot-pull-request-reviewer[bot]`, **with** the suffix. Each query below uses the correct form for its API, so match the API, not a single spelling, when adapting them. +> **The reviewer login differs by API, in three forms rather than two.** In **GraphQL** (`gh api graphql` and `gh pr view --json reviews`, which is GraphQL-backed) the `Bot.login` is `copilot-pull-request-reviewer`, with **no `[bot]` suffix**. In the **REST** API (`gh api repos/.../issues|pulls/...`) the same account's `user.login` is `copilot-pull-request-reviewer[bot]`, **with** the suffix. In a REST **timeline** `review_requested` event the `requested_reviewer` is a third spelling again, login `Copilot` with `type` `Bot`, so a filter written against either of the other two selects nothing there and reports a pull request with requests as having none. Match on the type plus a loose login test rather than on any one spelling, and each query below uses the correct form for its API. ```sh # 1. PR node id + the Copilot reviewer's bot node id (read from any existing @@ -161,9 +161,13 @@ gh api graphql -f query=' nodes{ requestedReviewer{ __typename ... on Bot{login} ... on User{login} } } } } } }' # The request and pickup events, newest last. A `review_requested` with no later -# `copilot_work_started` is the stuck state. -gh api --paginate repos///issues//timeline \ - --jq '.[] | select(.event == "copilot_work_started" or .event == "review_requested") +# `copilot_work_started` is the stuck state. Requests are filtered to the reviewer's own, +# since a human requested afterwards is a different request and reading it as this one +# reports a picked-up review as never picked up. `per_page` is the pagination cost. +gh api --paginate 'repos///issues//timeline?per_page=100' \ + --jq '.[] | select(.event == "copilot_work_started" or (.event == "review_requested" + and .requested_reviewer.type == "Bot" + and ((.requested_reviewer.login // "") | ascii_downcase | test("copilot")))) | "\(.event) \(.created_at)"' ``` diff --git a/scripts/pr_review.py b/scripts/pr_review.py index 6ce53b14..b1c0275d 100644 --- a/scripts/pr_review.py +++ b/scripts/pr_review.py @@ -43,6 +43,18 @@ # A test holds this equal to the number the queries carry, since a drift between them reads clean. WINDOW = 100 +# The timeline spells the reviewer a third way, as login `Copilot` with type `Bot`. +# GraphQL says `copilot-pull-request-reviewer`, and REST user objects add a `[bot]` suffix. +# The predicate is the type plus a loose login match rather than any one spelling. +# Requests are the reviewer's own, since a human requested later is a different request. +# Reading one as the newest reports a picked-up review as never picked up. +TIMELINE_JQ = ( + '.[] | select(.event == "copilot_work_started" or (.event == "review_requested"' + ' and .requested_reviewer.type == "Bot"' + ' and ((.requested_reviewer.login // "") | ascii_downcase | test("copilot"))))' + ' | "\\(.event) \\(.created_at)"' +) + # Liveness query: timestamps and ids only, no comment or review bodies. # A liveness check does not need the finding text, and re-fetching bodies was 76% of polls. # It does need the reviewer's non-review answers. @@ -93,8 +105,7 @@ def timeline(owner: str, repo: str, num: int) -> list[tuple[str, str]]: """ r = subprocess.run( ['gh', 'api', '--paginate', f'repos/{owner}/{repo}/issues/{num}/timeline?per_page=100', - '--jq', '.[] | select(.event == "copilot_work_started" or .event == "review_requested")' - ' | "\\(.event) \\(.created_at)"'], + '--jq', TIMELINE_JQ], capture_output=True, text=True) if r.returncode != 0: sys.stderr.write(r.stderr[:800]) @@ -310,6 +321,10 @@ def main(argv: list[str] | None = None) -> int: ap.add_argument('--pickup-grace', type=int, default=300, help='seconds before the first pickup read, and between reads (default 5m)') a = ap.parse_args(argv) + # A negative grace leaves the next reading permanently behind the clock. + # That is the per-poll REST pattern the interval exists to prevent. + if a.pickup_grace < 0: + ap.error('--pickup-grace cannot be negative') owner, repo = a.repo.split('/', 1) if a.cmd == 'status': diff --git a/scripts/test_pr_review.py b/scripts/test_pr_review.py index 4d66caf3..718c7a7d 100644 --- a/scripts/test_pr_review.py +++ b/scripts/test_pr_review.py @@ -578,6 +578,40 @@ def test_the_timeline_reader_asks_for_the_largest_page(self) -> None: self.assertEqual(['gh', 'api'], argv[:2]) self.assertFalse({'-X', '--method'} & set(argv)) + def test_the_timeline_filter_takes_the_reviewer_s_own_requests_only(self) -> None: + """A human requested later is not this request, and reading it as one reports a stall. + + The filter runs inside gh, so this drives the real `jq` over a crafted timeline rather + than asserting on the filter's text, which would pass on a filter that matches nothing. + The timeline spells the reviewer `Copilot` with type `Bot`, a third form after GraphQL's + `copilot-pull-request-reviewer` and REST's `[bot]` suffix on that, so a filter keyed to + either of those two selects nothing here and the whole state reads as no request at all. + """ + events = [ + {'event': 'review_requested', 'created_at': '01', 'requested_reviewer': + {'login': 'Copilot', 'type': 'Bot'}}, + {'event': 'copilot_work_started', 'created_at': '02'}, + {'event': 'review_requested', 'created_at': '03', 'requested_reviewer': + {'login': 'ptr727', 'type': 'User'}}, + {'event': 'review_requested', 'created_at': '04', 'requested_reviewer': + {'login': 'some-other-bot', 'type': 'Bot'}}, + {'event': 'commented', 'created_at': '05'}, + ] + run = subprocess.run(['jq', '-r', pr_review.TIMELINE_JQ], + input=json.dumps(events), capture_output=True, text=True) + self.assertEqual(0, run.returncode, run.stderr) + self.assertEqual(['review_requested 01', 'copilot_work_started 02'], + run.stdout.split('\n')[:-1]) + # The reading that matters: the human request must not become the newest request. + parsed = [(ln.split(' ', 1)[0], ln.split(' ', 1)[1]) for ln in run.stdout.splitlines()] + self.assertEqual('', pr_review.never_picked_up(parsed)) + + def test_a_negative_pickup_grace_is_rejected_rather_than_read_as_every_poll(self) -> None: + """It leaves the next reading behind the clock, which is the per-poll pattern returning.""" + with contextlib.redirect_stderr(io.StringIO()): + with self.assertRaises(SystemExit): + pr_review.main(['wait', '7', '--pickup-grace', '-1']) + def test_a_failed_timeline_read_raises_rather_than_reading_as_no_events(self) -> None: """An empty list reads as no request pending, which is the false clean one level up.""" failed = subprocess.CompletedProcess(args=[], returncode=1, stdout='', stderr='boom')