diff --git a/quest/m0/helpers/README.md b/quest/m0/helpers/README.md index e806f712..701f3ea4 100644 --- a/quest/m0/helpers/README.md +++ b/quest/m0/helpers/README.md @@ -59,7 +59,6 @@ commands from Sep-Oct. Session counts in each child come from that window. - [PR state commands](/quest/m0/helpers/pr-states.md) - `quest iterate`, `ready`, `merge`, and `release` label the one owner of a PR - [Complete loop](/quest/m0/helpers/complete-loop.md) - `/quest-complete` re-scans PRs, keeps picks and holds, and counts rounds per PR - [Headless agents](/quest/m0/helpers/headless-agents.md) - `/quest-spawn api` launches, resumes, and stops billed agents through one command auto mode allows -- [Wait gaps](/quest/m0/helpers/wait-gaps.md) - `quest wait` reports every event after its starting point exactly once ## Related diff --git a/quest/m0/helpers/wait-gaps.md b/quest/m0/helpers/wait-gaps.md deleted file mode 100644 index ced7ad96..00000000 --- a/quest/m0/helpers/wait-gaps.md +++ /dev/null @@ -1,25 +0,0 @@ -# [S] Never miss events in quest wait - -## Goal - -Every review, comment, and check result after the wait's starting point is -reported exactly once, however long after a push the wait starts and however -close to its timeout the event lands. - -## Plan - -Decided 2026-10-21 from merge agents' reports that day: - -- A wait started without `--since` about a minute after a push timed out after - 540 s without reporting a Codex review that landed in that window - ([kixelated/quest#127](https://github.com/kixelated/quest/pull/127)). Waits - started with `--since` from before the push reported it every time. - Reproduce it, find the root cause (for example the default point resolving to - the wrong push time, or update-time filtering), and fix it. -- Check that an event landing in the last poll interval before the timeout is - either reported or left for the returned cursor, never dropped. -- A merge agent saw the resume cursor as `Q1.` while the CLI accepts only - `q1.` ([kixelated/quest#172](https://github.com/kixelated/quest/pull/172)). - Confirm whether `quest wait` ever prints it that way; if not, record it as a - display quirk and change nothing. -- Add regression tests for each confirmed cause. diff --git a/src/cli/main.ts b/src/cli/main.ts index c908ae36..10604ee5 100644 --- a/src/cli/main.ts +++ b/src/cli/main.ts @@ -312,7 +312,7 @@ export function main(argv: string[], out: Output): number | Promise { .summary("Wait for pull request activity on GitHub") .description( "Wait for a review, comment, review-thread reply, reaction to the PR or a review, push, merge, close, " + - "merge-queue removal, disabled auto-merge, or required CI result. Polls every 5 minutes; rate limits delay requests. No timeout by default.\n\n" + + "merge-queue removal, disabled auto-merge, or required CI result. Polls every 5 minutes, and once more 30 seconds before the timeout; rate limits and longer GitHub poll intervals delay requests. No timeout by default.\n\n" + "Prints one plain line per event: timestamp (or commit SHA), type, actor, URL; the last line adds a resume cursor. " + "Reactions print as reacted:, such as reacted:thumbs_up. " + "The head's first failing required check prints as checks:failed, and every required check passing as checks:passed, " + diff --git a/src/cli/wait.ts b/src/cli/wait.ts index 5ee98532..0bc2306f 100644 --- a/src/cli/wait.ts +++ b/src/cli/wait.ts @@ -14,6 +14,14 @@ import { import { classifyCheck } from "./status"; const POLL = 5 * 60_000; +/** + * The last poll before a timeout starts this long before it, leaving time for its few requests; + * activity after it is left for the returned cursor. Polling only on the 5-minute schedule left + * up to 5 minutes before a timeout unread. A longer X-Poll-Interval from GitHub still wins. + */ +const FINAL_POLL = 30_000; +/** The REST page size. A full last page cannot show by itself that a next page has appeared. */ +const PAGE = 100; const SHA = /^[a-f\d]{7,40}$/i; /** The timeline records a force push a few seconds after repository activity (1-2s observed). */ const TIMELINE_LAG = 60_000; @@ -264,7 +272,11 @@ async function watch( const mark = cursor.marks[source]; return event.time > mark.time || (event.time === mark.time && !seen[source].has(event.id)); }; - /** Read every page once, then poll the last page conditionally, following it when it fills. */ + /** + * Read every page once, then poll the last page conditionally, following it when it fills. A 304 + * has no Link header and the ETag covers only the body, so a full last page is reread whole to + * learn of a next one. + */ const pager = (first: string) => { let path = first; let etag: string | undefined; @@ -276,10 +288,11 @@ async function watch( if (!etag) throw new Error("unexpected GitHub 304 without a cached response"); return rows; } - rows.push(...array(await response.json())); + const page = array(await response.json()); + rows.push(...page); const next = link(response, "next"); if (!next) { - etag = response.headers.get("etag") ?? undefined; + etag = page.length < PAGE ? (response.headers.get("etag") ?? undefined) : undefined; return rows; } path = next; @@ -365,15 +378,15 @@ async function watch( return found; }; - const timeline = pager(`${base}/issues/${pr.number}/timeline?per_page=100`); + const timeline = pager(`${base}/issues/${pr.number}/timeline?per_page=${PAGE}`); // `since` excludes its own instant and filters by update time, which is never before // creation; start a second early so unseen replies at the mark's second are still read. const comments = pager( - `${base}/pulls/${pr.number}/comments?per_page=100&since=${new Date(cursor.marks.replies.time - 1000).toISOString()}`, + `${base}/pulls/${pr.number}/comments?per_page=${PAGE}&since=${new Date(cursor.marks.replies.time - 1000).toISOString()}`, ); const found: Record = { timeline: historical, replies: [], reactions: [] }; for (;;) { - github.pollInterval = POLL; + github.pollInterval = 0; for (const row of await timeline()) { const type = string(row.event); if (type === "committed") { @@ -455,7 +468,11 @@ async function watch( `${event.point} ${event.type} ${event.actor} ${event.url}${index === unique.length - 1 ? ` ${nextCursor}` : ""}`, ); } - await github.pause(github.pollInterval); + // GitHub's X-Poll-Interval is a floor: the final poll shortens only the default schedule, + // and is skipped when that interval runs past it. + const remaining = deadline - deps.now(); + const next = Math.min(Math.max(POLL, github.pollInterval), remaining - FINAL_POLL); + await github.pause(next > 0 && next >= github.pollInterval ? next : remaining); } } diff --git a/test/wait.test.ts b/test/wait.test.ts index 9c9da9b4..aa0934d7 100644 --- a/test/wait.test.ts +++ b/test/wait.test.ts @@ -482,6 +482,55 @@ test("all initial timeline pages are read, and the last known page is polled bef expect(fixture.calls.at(-1)!.headers.has("if-none-match")).toBe(false); }); +test("a full last page is reread whole, since a 304 cannot show that a next page appeared", async () => { + const labeled = Array.from({ length: 99 }, (_, id) => ({ event: "labeled", id, created_at: POINT })); + const full = [committed(A), ...labeled]; + const page2 = `https://api.github.com${timeline}&page=2`; + const fixture = setup([ + pull(), + response([pushed()]), + response(full, { etag: '"full"' }), + response(full, { etag: '"full"', link: `<${page2}>; rel="next"` }), + response([reviewed(1, "2026-10-07T12:12:00Z")]), + ]); + const lines = await waitForActivity(pr, {}, fixture.deps); + expect(lines).toHaveLength(1); + expect(lines[0]).toMatch(/^2026-10-07T12:12:00Z reviewed /); + expect(fixture.calls[4].headers.has("if-none-match")).toBe(false); +}); + +test("a review landing after the last scheduled poll is reported by a final poll before the timeout", async () => { + // 540 s polls at 0 and 300 s; the final poll at 510 s reads a review from 480 s. + const fixture = setup([ + pull(), + response([pushed()]), + response([committed(A)], { etag: '"e"' }), + response(null, {}, 304), + response([committed(A), reviewed(1, "2026-10-07T12:18:00Z")]), + ]); + const lines = await waitForActivity(pr, { timeout: 540 }, fixture.deps); + expect(lines).toHaveLength(1); + expect(lines[0]).toMatch(/^2026-10-07T12:18:00Z reviewed /); + expect(fixture.sleeps).toEqual([300_000, 210_000]); +}); + +test("a review landing after the final poll is left for the timeout's cursor, never dropped", async () => { + const first = setup([ + pull(), + response([pushed()]), + response([committed(A)], { etag: '"e"' }), + response(null, {}, 304), + response(null, {}, 304), + ]); + const timeout = await waitForActivity(pr, { timeout: 540 }, first.deps).catch((error: unknown) => error); + expect(timeout).toBeInstanceOf(WaitTimeout); + expect(first.sleeps).toEqual([300_000, 210_000, 30_000]); + const second = setup([response([committed(A), reviewed(1, "2026-10-07T12:18:50Z")])]); + const lines = await waitForActivity(pr, { since: (timeout as WaitTimeout).cursor }, second.deps); + expect(lines).toHaveLength(1); + expect(lines[0]).toMatch(/^2026-10-07T12:18:50Z reviewed /); +}); + test("older initial pages are not skipped even when the last page has no recent activity", async () => { const page2 = `https://api.github.com${timeline}&page=2`; const fixture = setup( @@ -540,6 +589,13 @@ test("primary rate limit reset and server poll intervals are honored", async () expect(fixture.sleeps).toEqual([60_000, 600_000]); }); +test("a server poll interval past the final poll skips it rather than polling early", async () => { + // A 600 s X-Poll-Interval outlasts a 540 s timeout, so no final poll runs at 510 s. + const fixture = setup([pull(), response([pushed()]), response([], { "x-poll-interval": "600" })]); + await expect(waitForActivity(pr, { timeout: 540 }, fixture.deps)).rejects.toBeInstanceOf(WaitTimeout); + expect(fixture.sleeps).toEqual([540_000]); +}); + test("persistent rate limiting eventually fails loudly instead of masking an error", async () => { const fixture = setup(Array.from({ length: 7 }, () => response({ message: "secondary rate limit" }, {}, 403))); await expect(waitForActivity(pr, {}, fixture.deps)).rejects.toThrow("rate limit persisted");