diff --git a/.changes/source-control/fix-verdict-listing-truncated-retry-7c2e4b19.md b/.changes/source-control/fix-verdict-listing-truncated-retry-7c2e4b19.md new file mode 100644 index 00000000000..5508e573037 --- /dev/null +++ b/.changes/source-control/fix-verdict-listing-truncated-retry-7c2e4b19.md @@ -0,0 +1,16 @@ +--- +bump: patch +--- + +### Fixed + +- read a cut-short artifact listing again after every wait, as a 5xx is + + The verify-evidence reader read a whole listing cut short (`unexpected end + of JSON input`) once more at most, so two cut-short reads in a row refused + the pull request with `verify:unreadable`. It now reads it again after each + listing wait while time is left, and a page body cut short while gh exits 0 + (`page N is not JSON`) or that the reader cannot parse counts as cut short + too. A rate-limit answer is still never read again, and a listing that + keeps failing still refuses. A whole listing still cut short after its + waits is noted for the job, so later Readers refuse without paging it again. diff --git a/plugins/source-control/skills/babysit-prs/scripts/babysit_verify_evidence.py b/plugins/source-control/skills/babysit-prs/scripts/babysit_verify_evidence.py index 25155328de4..5d176b8ec04 100755 --- a/plugins/source-control/skills/babysit-prs/scripts/babysit_verify_evidence.py +++ b/plugins/source-control/skills/babysit-prs/scripts/babysit_verify_evidence.py @@ -567,9 +567,8 @@ def _overcount_refusal(outcome: str) -> str: "unexpected eof", "unexpected end of json input", ) -# A whole listing cut short has already paged up to every artifact, so it is -# read once more at most, not after every wait (`Reader._read_listing`). -CUT_SHORT = "unexpected end of json input" +# A page body cut short while gh exits 0, as babysit_gh._run_pages reports it. +PAGE_NOT_JSON = re.compile(r"\bpage \d+ is not json$") FAIL = "verify:fail" EARLIER_FAIL = "verify:earlier-fail" REPEATED_FAIL = "verify:repeated-fail" @@ -939,14 +938,22 @@ class _Transient(_Unreadable): """A failed read that may succeed if repeated.""" +class _CutShort(_Transient): + """A page body cut short: read again like a 5xx, but noted for the job + once its waits run out, since each later Reader would page the whole + listing again.""" + + def _transient(detail: str) -> bool: - """A 5xx, or a network error with no HTTP response. A rate limit is not: - a fixed short wait outlasts neither a Retry-After nor an hourly reset, and - more requests can extend a secondary limit.""" + """A 5xx, a network error with no HTTP response, or a page body cut + short. A rate limit is not: a fixed short wait outlasts neither a + Retry-After nor an hourly reset, and more requests can extend a secondary + limit.""" status = gh_http_status(detail) if status is not None: return status >= 500 - return any(phrase in detail.casefold() for phrase in NETWORK_ERRORS) + text = detail.casefold() + return any(p in text for p in NETWORK_ERRORS) or bool(PAGE_NOT_JSON.search(text)) def listing_pages(total_count: int) -> int: @@ -1459,7 +1466,9 @@ def _current_listing(self) -> list[dict[str, Any]]: self._listing_error = str(exc) if self._overcount_mine: self._note_overcount(self._listing_error) - if self._whole_paged and not isinstance(exc, _Transient): + if self._whole_paged and ( + isinstance(exc, _CutShort) or not isinstance(exc, _Transient) + ): self._note_failed_listing(self._listing_error) raise _Unreadable(self._listing_error) from exc if self._overcount_mine: @@ -2154,12 +2163,11 @@ def _live_count(self, timeout: float | None = None) -> int: def _read_listing( self, deadline: float | None = None, budget: float = LISTING_TIMEOUT_SECONDS ) -> Any: - """The listing payload, read again after a 5xx or a fast network - error while time is left: every page, read and wait fits in - `budget`, so a retry adds no time to the run's worst - case. A read cut short (`CUT_SHORT`) is read once more, and that - read's failure refuses. A `deadline` set by an earlier read is kept; - this read's is saved as `_read_deadline`.""" + """The listing payload, read again after each of `LISTING_WAITS` on a + 5xx, a fast network error or a page body cut short while time is + left: every page, read and wait fits in `budget`, so a retry adds no + time to the run's worst case. A `deadline` set by an earlier read is + kept; this read's is saved as `_read_deadline`.""" args = [ "api", f"repos/{self.repo}/actions/artifacts?per_page=100", @@ -2177,7 +2185,7 @@ def _read_listing( for wait in LISTING_WAITS: try: return self._actions(args, "repository artifacts", timeout) - except _Transient as exc: + except _Transient: if deadline - _listing_clock() - wait <= 0: raise _listing_sleep(wait) @@ -2185,8 +2193,6 @@ def _read_listing( timeout = deadline - _listing_clock() if timeout <= 0: raise - if CUT_SHORT in str(exc).casefold(): - break return self._actions(args, "repository artifacts", timeout) def _env(self) -> dict[str, str] | None: @@ -2206,11 +2212,16 @@ def _actions( raise _Unreadable(f"{label}: {exc}") from exc if proc.returncode != 0: detail = f"{label}: {(proc.stderr or '').strip() or proc.returncode}" - raise (_Transient if _transient(detail) else _Unreadable)(detail) + if not _transient(detail): + raise _Unreadable(detail) + text = detail.casefold() + cut = PAGE_NOT_JSON.search(text) or "unexpected end of json input" in text + raise (_CutShort if cut else _Transient)(detail) try: return json.loads(proc.stdout) if proc.stdout.strip() else None except ValueError as exc: - raise _Unreadable(f"{label}: {exc}") from exc + # A body cut short while gh exits 0. + raise _CutShort(f"{label}: {exc}") from exc def _contains(self, sha: str, *, shared: bool = False) -> bool: """Whether the branch holds `sha`, read under the Actions token (a diff --git a/plugins/source-control/skills/babysit-prs/scripts/tests/test_babysit_verify_evidence.py b/plugins/source-control/skills/babysit-prs/scripts/tests/test_babysit_verify_evidence.py index a899f47d6a3..ba084ca7251 100644 --- a/plugins/source-control/skills/babysit-prs/scripts/tests/test_babysit_verify_evidence.py +++ b/plugins/source-control/skills/babysit-prs/scripts/tests/test_babysit_verify_evidence.py @@ -3653,9 +3653,14 @@ def timed_out() -> RuntimeError: return error +class CutBody(str): + """A listing body gh printed cut short while exiting 0.""" + + class FlakyListing(FakeGitHub): """Fails the artifact listing with each of `errors` in turn: a string is - gh's stderr on exit 1, an exception is raised from `gh_capture`.""" + gh's stderr on exit 1, a `CutBody` is its stdout on exit 0, an exception + is raised from `gh_capture`.""" def __init__(self, errors: list[str | BaseException]): fake = passing() @@ -3673,6 +3678,8 @@ def __call__( error = self.errors.pop(0) if isinstance(error, BaseException): raise error + if isinstance(error, CutBody): + return subprocess.CompletedProcess(args, 0, error, "") return subprocess.CompletedProcess(args, 1, "", error) return super().__call__(args, **kwargs) @@ -3698,8 +3705,12 @@ class ATransientListingFailureIsReadAgain(unittest.TestCase): # A page body cut short: Go's JSON decoder error, as gh printed it in # pr-merge run 40819274416 (skip step, 2026-10-29T04:59:05Z). "unexpected end of JSON input", + # A page body cut short while gh exits 0 (babysit_gh._run_pages). + "page 2 is not JSON", ) NOT_TRANSIENT: tuple[str | BaseException, ...] = ( + # A rate limit stays a rate limit when gh also printed a parse error. + "unexpected end of JSON input\ngh: API rate limit exceeded (HTTP 403)", "gh: Not Found (HTTP 404)", "gh: Bad credentials (HTTP 401)", "gh: Validation Failed (HTTP 422)", @@ -3751,15 +3762,24 @@ def test_a_persistent_transient_failure_refuses_after_three_reads(self) -> None: self.assertEqual(fake.listings(), 3) self.assertEqual(sleeps, [2.0, 4.0]) - def test_a_whole_listing_cut_short_is_read_once_more_at_most(self) -> None: - # Each cut-short read may have paged every artifact: two whole reads, - # never three, then the refusal. + def test_a_whole_listing_cut_short_every_time_refuses_after_three_reads( + self, + ) -> None: + # ci-status run 41475913026 refused #12404 after two cut-short reads; + # a cut short is read again after every wait, as a 5xx is. fake = FlakyListing(["unexpected end of JSON input"] * 3) evidence, sleeps = self.judge(fake) self.assertEqual(evidence.refusal, "verify:unreadable") self.assertIn("unexpected end of JSON input", evidence.detail or "") - self.assertEqual(fake.listings(), 2) - self.assertEqual(sleeps, [2.0]) + self.assertEqual(fake.listings(), 3) + self.assertEqual(sleeps, [2.0, 4.0]) + + def test_two_cut_short_reads_then_a_listing_reads_the_verdict(self) -> None: + fake = FlakyListing(["unexpected end of JSON input"] * 2) + evidence, sleeps = self.judge(fake) + self.assertIsNone(evidence.refusal) + self.assertEqual(fake.listings(), 3) + self.assertEqual(sleeps, [2.0, 4.0]) def timed(self, clock: list[float]) -> FlakyListing: """Three 502s, the clock reading `clock` in turn, a 60s listing timeout @@ -3837,6 +3857,34 @@ def send(args, *, timeout_seconds, env_overrides, binary): self.assertEqual(len(pages), self.PAGES) self.assertEqual(len(sent), self.PAGES) + def test_a_page_body_cut_short_reads_the_listing_again(self) -> None: + # gh exits 0 with page 2's body cut short on the first listing only. + sent: list[str] = [] + + def send(args, *, timeout_seconds, env_overrides, binary): + sent.append(args[1]) + named = re.search(r"[?&]page=(\d+)", args[1]) + page = int(named[1]) if named else 1 + link = ( + "; rel="next"' + if page < 3 + else "" + ) + body = json.dumps({"total_count": 3, "artifacts": [{"id": page}]}) + if page == 2 and len(sent) == 2: + body = body[:20] + return subprocess.CompletedProcess(args, 0, body, ""), {"link": link} + + with ( + mock.patch.object(gh, "_send", side_effect=send), + mock.patch.object(ve, "_listing_sleep") as sleep, + ): + pages = ve.Reader(REPO, "main", now=NOW)._read_listing() + self.assertEqual([p["artifacts"][0]["id"] for p in pages], [1, 2, 3]) + self.assertEqual(len(sent), 5) + self.assertEqual([c.args[0] for c in sleep.call_args_list], [2.0]) + class TheWholeListingTimeoutGrowsWithItsPages(unittest.TestCase): """The whole listings' shared timeout comes from GitHub's live @@ -5133,6 +5181,24 @@ def test_a_whole_listing_lost_to_a_5xx_is_not_noted_for_the_job(self) -> None: self.assertIsNone(evidence.refusal, evidence.detail) self.assertEqual(fake.listings(), 4) + def test_a_whole_listing_cut_short_after_its_waits_is_noted(self) -> None: + # Each later Reader in the job would page the whole listing again. + for detail in ( + "unexpected end of JSON input", + "page 2 is not JSON", + CutBody('{"total_count": 1, "art'), + ): + with self.subTest(detail): + self.failed.unlink(missing_ok=True) + fake = FlakyListing([detail] * 6) + _, evidence = self.judge(fake) + self.assertEqual(evidence.refusal, "verify:unreadable") + self.assertEqual(fake.listings(), 3) + self.assertTrue(self.failed.exists()) + _, evidence = self.judge(fake) + self.assertEqual(evidence.refusal, "verify:unreadable") + self.assertEqual(fake.listings(), 3) + def test_a_whole_listing_failure_not_the_callers_is_noted(self) -> None: # A timeout of the whole cap's own budget (60 s for five artifacts), # and a top-up page 404, with or without a caller's time left.