From 8824000eee8c317213bddc31069411e6b6ab16b7 Mon Sep 17 00:00:00 2001 From: Jeffrey Wall <265409180+jeffwall-curlewlabs@users.noreply.github.com> Date: Tue, 13 Oct 2026 18:50:23 -0700 Subject: [PATCH 1/2] Retry a cut-off answer, and wait out a rate limit on its own gh_api retried a busy or unreachable API, but not an answer that arrived empty or cut off. gh decodes an answer before it reports a status whenever it filters one with --jq, reads a GraphQL answer, or reads a JSON error body, so such an answer fails with Go's decoder error and nothing else: unexpected end of JSON input That counted as a refusal and failed on the first attempt. On a clock host it happened to the mark read, so the tick sent nothing and exited 1; the same read succeeded minutes later. It is now retried like a request that got no answer, and its callers already cover a request that applied before its answer was lost: a mark claim reads back whose blob the mark holds, a ledger create or delete takes its 422 as done, and a second dispatch of a slot is one more delivery, which the concurrency group and slot action run once. The busy ladder also gets shorter waits, 1, 2, 4, 8, 10, 10 and 10 seconds, since most of these failures are one lost answer that the next attempt gets. Its old last step was 60s because that is GitHub's documented minimum wait after a secondary rate limit, which the new ladder no longer reaches, so a rate limit now has its own path: one retry, after 60s. Retrying it on the short waits would spend the attempts with no chance of clearing the limit, while sending the requests GitHub warns can get an integration banned. A call can now spend longer before it fails, so the live job's cap moves from 20 to 25 minutes to keep holding it twice, for the check and for its cleanup. The version goes to 0.2.3. --- .github/workflows/ci.yml | 11 ++-- README.md | 2 +- pyproject.toml | 2 +- src/github_cron_trigger/github.py | 91 ++++++++++++++++++++++--------- tests/test_steps.py | 84 +++++++++++++++++++++++++--- 5 files changed, 150 insertions(+), 40 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 1788f2f..a058df4 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -84,11 +84,12 @@ jobs: concurrency: group: live-check cancel-in-progress: false - # Holds the full retry ladder of a failing `gh` call (github.py's - # GH_TIMEOUT_SECONDS and RETRY_DELAYS_SECONDS) for the check and again for - # its cleanup, so an API outage ends in a failed step with its message - # rather than a job cancelled at the cap. The healthy path takes seconds. - timeout-minutes: 20 + # Holds the full retries of a failing `gh` call (github.py's + # GH_TIMEOUT_SECONDS, RETRY_DELAYS_SECONDS and RATE_LIMIT_DELAY_SECONDS) + # for the check and again for its cleanup, so an API outage ends in a failed + # step with its message rather than a job cancelled at the cap. The healthy + # path takes seconds. + timeout-minutes: 25 steps: - uses: actions/checkout@v7.0.1 diff --git a/README.md b/README.md index 65c8b92..c2c4590 100644 --- a/README.md +++ b/README.md @@ -362,7 +362,7 @@ Any host that can reach `api.github.com` will do, and more than one is better. Install a release, which puts `github-cron-trigger` on PATH: ```sh -pip install "github-cron-trigger @ git+https://github.com/curlewlabs-com/github-cron-trigger@v0.2.2" +pip install "github-cron-trigger @ git+https://github.com/curlewlabs-com/github-cron-trigger@v0.2.3" ``` Or check out a release tag and run it as `PYTHONPATH=src python3 -m diff --git a/pyproject.toml b/pyproject.toml index cccacf8..4e34102 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "flit_core.buildapi" [project] name = "github-cron-trigger" -version = "0.2.2" +version = "0.2.3" description = "Run each scheduled slot of a GitHub Actions workflow on time and exactly once, with GitHub's schedule as the backstop." readme = "README.md" license = "MIT" diff --git a/src/github_cron_trigger/github.py b/src/github_cron_trigger/github.py index 9e4506a..b93ffd7 100644 --- a/src/github_cron_trigger/github.py +++ b/src/github_cron_trigger/github.py @@ -15,11 +15,17 @@ # unattended clock tick open until an outer timeout kills it without a report. GH_TIMEOUT_SECONDS = 60 -# Waits between attempts on a transient failure, one attempt per entry plus a -# final one. The first two ride out a gateway blip; the last is 60s because that -# is GitHub's documented minimum wait after a secondary rate limit, so a shorter -# final wait would spend the attempt with no chance of clearing it. -RETRY_DELAYS_SECONDS = (5, 20, 60) +# Waits between attempts on a busy or unreachable API, one attempt per entry +# plus a final one. Most such failures are a single lost answer that the next +# attempt gets, so the first waits are short; they level off so that an outage +# still fails the call in under a minute of waiting. +RETRY_DELAYS_SECONDS = (1, 2, 4, 8, 10, 10, 10) + +# The wait before the one retry of a rate-limited call: GitHub's documented +# minimum wait after a secondary rate limit. A shorter wait spends the retry +# with no chance of clearing the limit, and GitHub warns that requests sent +# while limited can get an integration banned. +RATE_LIMIT_DELAY_SECONDS = 60 # `gh api`'s stderr line for a failed HTTP request. The response body goes to # stdout and often carries the status too, but not every error body does, so @@ -38,6 +44,13 @@ _CONNECT_FAILURE = "error connecting to " _NO_ANSWER = re.compile(r'^(?:Get|Head|Post|Put|Patch|Delete) "[^"]*": ') +# What gh prints when the answer it read was empty or cut off: Go's JSON decoder +# ran out of input. gh decodes an answer before it reports a status whenever it +# filters one with `--jq`, reads a GraphQL answer, or reads a JSON error body, so +# this carries no status, and the request may have applied, as with one that got +# no answer at all. +_CUT_OFF_ANSWER = "unexpected end of JSON input" + # GitHub answers a secondary rate limit with a 403 whose message says so. Every # other 403 is a refusal, so the message is the only way to tell them apart. _SECONDARY_RATE_LIMIT = "secondary rate limit" @@ -73,36 +86,57 @@ def classify(stderr: str) -> tuple[int | None, str]: def transient(status: int | None, message: str) -> bool: - """Whether a failure is worth retrying: the API was busy or unreachable.""" + """Whether a failure is worth retrying soon: the API was busy or + unreachable, or its answer was lost.""" if status is None: - return message.startswith(_CONNECT_FAILURE) or bool(_NO_ANSWER.match(message)) - if status >= 500 or status == 429: + return ( + message.startswith(_CONNECT_FAILURE) + or bool(_NO_ANSWER.match(message)) + or message == _CUT_OFF_ANSWER + ) + return status >= 500 + + +def rate_limited(status: int | None, message: str) -> bool: + """Whether GitHub refused a call for its rate limit, which waiting can clear.""" + if status == 429: return True return status == 403 and _SECONDARY_RATE_LIMIT in message.lower() -def gh_api(args: Sequence[str], sleep: Callable[[float], None] = time.sleep) -> str: +def _run_gh(command: Sequence[str]) -> subprocess.CompletedProcess[str]: + return subprocess.run( + command, + capture_output=True, + # gh writes UTF-8 whatever the host's locale, and a runner's locale is + # often C, which would refuse a workflow file's non-ASCII text. + encoding="utf-8", + timeout=GH_TIMEOUT_SECONDS, + check=False, + ) + + +def gh_api( + args: Sequence[str], + sleep: Callable[[float], None] = time.sleep, + run: Callable[[Sequence[str]], subprocess.CompletedProcess[str]] = _run_gh, +) -> str: """Run `gh api` with the given arguments and return its stdout. - Retries a transient failure on RETRY_DELAYS_SECONDS; any other failure, or a - transient one that outlasts the ladder, raises. A retried POST can find its - own earlier attempt already applied - slot_ledger.record treats the - resulting 422 as success for exactly that reason. + Retries a busy or unreachable API on RETRY_DELAYS_SECONDS, and a rate limit + once, after RATE_LIMIT_DELAY_SECONDS; any other failure, or one that + outlasts its retries, raises. A retried POST can find its own earlier + attempt already applied - slot_ledger.record treats the resulting 422 as + success for exactly that reason. """ command = ["gh", "api", *args] - for delay in (*RETRY_DELAYS_SECONDS, None): + busy_waits = iter(RETRY_DELAYS_SECONDS) + rate_limit_waits = iter((RATE_LIMIT_DELAY_SECONDS,)) + while True: try: - completed = subprocess.run( - command, - capture_output=True, - # gh writes UTF-8 whatever the host's locale, and a runner's - # locale is often C, which would refuse a workflow file's - # non-ASCII text. - encoding="utf-8", - timeout=GH_TIMEOUT_SECONDS, - check=False, - ) + completed = run(command) except subprocess.TimeoutExpired: + delay = next(busy_waits, None) if delay is None: raise GitHubError( f"`{' '.join(command)}` timed out after {GH_TIMEOUT_SECONDS}s" @@ -114,12 +148,17 @@ def gh_api(args: Sequence[str], sleep: Callable[[float], None] = time.sleep) -> if completed.returncode == 0: return completed.stdout status, message = classify(completed.stderr) - if delay is None or not transient(status, message): + if rate_limited(status, message): + delay = next(rate_limit_waits, None) + elif transient(status, message): + delay = next(busy_waits, None) + else: + delay = None + if delay is None: if status is None: raise GitHubError(f"`{' '.join(command)}` failed: {message}") raise HttpError(status, message) sleep(delay) - raise AssertionError("unreachable: the retry loop returns or raises") def check_repo(repo: str) -> str: diff --git a/tests/test_steps.py b/tests/test_steps.py index 3b86de9..d04bd50 100644 --- a/tests/test_steps.py +++ b/tests/test_steps.py @@ -13,15 +13,25 @@ """ import io +import subprocess import tempfile import unittest +from collections.abc import Sequence from contextlib import redirect_stdout from datetime import datetime from pathlib import Path from github_cron_trigger import steps, workflow_files from github_cron_trigger.cron_slots import UTC, UnsupportedCron, parse_cron -from github_cron_trigger.github import HttpError, classify, transient +from github_cron_trigger.github import ( + RATE_LIMIT_DELAY_SECONDS, + RETRY_DELAYS_SECONDS, + HttpError, + classify, + gh_api, + rate_limited, + transient, +) from github_cron_trigger.slot_ledger import ( cron_segment, record_slot_key, @@ -514,7 +524,8 @@ class GhFailureClassificationTest(unittest.TestCase): secondary-rate-limit and name-lookup lines are the forms GitHub and `gh` print for those failures. The unanswered-request lines are `gh api` output too: the timeouts from a clock host's log, with the repository renamed, and - the proxy line from pointing HTTPS_PROXY at a closed port. + the proxy line from pointing HTTPS_PROXY at a closed port. The cut-off + answer line is from the same clock host's log. """ def test_refusals_are_not_retried(self) -> None: @@ -530,16 +541,16 @@ def test_refusals_are_not_retried(self) -> None: with self.subTest(stderr=stderr): self.assertEqual(classify(stderr)[0], status) self.assertFalse(transient(*classify(stderr))) + self.assertFalse(rate_limited(*classify(stderr))) def test_busy_and_unreachable_are_retried(self) -> None: for stderr in ( "gh: Server Error (HTTP 502)", - "gh: API rate limit exceeded (HTTP 429)", - ( - "gh: You have exceeded a secondary rate limit. Please wait a few" - " minutes before you try again. (HTTP 403)" - ), "error connecting to api.github.com\ncheck your internet connection", + # An answer that arrived empty or cut off, which gh reports with no + # status whether it came from a `--jq` read, a GraphQL query or an + # error body. Unretried, it cost a clock tick on the mark read. + "unexpected end of JSON input", # Requests gh sent and got no answer to. Unretried, one dropped # connection on the mark read cost a whole tick, since a tick # with no marks sends nothing. @@ -565,6 +576,65 @@ def test_busy_and_unreachable_are_retried(self) -> None: ): with self.subTest(stderr=stderr): self.assertTrue(transient(*classify(stderr))) + self.assertFalse(rate_limited(*classify(stderr))) + + def test_rate_limits_are_told_apart_from_a_busy_api(self) -> None: + for stderr in ( + "gh: API rate limit exceeded (HTTP 429)", + ( + "gh: You have exceeded a secondary rate limit. Please wait a few" + " minutes before you try again. (HTTP 403)" + ), + ): + with self.subTest(stderr=stderr): + self.assertTrue(rate_limited(*classify(stderr))) + self.assertFalse(transient(*classify(stderr))) + + +class GhRetryTest(unittest.TestCase): + """Which wait a failed `gh` call takes before its retry. + + A busy or unreachable API is retried after short waits, so one lost answer + costs seconds rather than a failed run. A rate limit must wait GitHub's + documented minimum instead: the busy ladder's short waits would spend its + retries with no chance of clearing the limit, while sending the requests + GitHub warns can get an integration banned. Only `gh` itself is replaced, + by one that fails with each given stderr in turn and then answers. + """ + + ANSWER = "answer\n" + RATE_LIMIT = ( + "gh: You have exceeded a secondary rate limit. Please wait a few minutes" + " before you try again. (HTTP 403)" + ) + + def call(self, *failures: str) -> str: + pending = list(failures) + + def run(command: Sequence[str]) -> subprocess.CompletedProcess[str]: + if pending: + return subprocess.CompletedProcess(command, 1, "", pending.pop(0)) + return subprocess.CompletedProcess(command, 0, self.ANSWER, "") + + self.waits: list[float] = [] + return gh_api(["repos/owner/name"], sleep=self.waits.append, run=run) + + def test_a_cut_off_answer_is_retried_soon(self) -> None: + self.assertEqual(self.call("unexpected end of JSON input"), self.ANSWER) + self.assertEqual(self.waits, [RETRY_DELAYS_SECONDS[0]]) + + def test_a_busy_api_is_retried_until_its_ladder_is_spent(self) -> None: + busy = ["gh: Server Error (HTTP 502)"] * (len(RETRY_DELAYS_SECONDS) + 1) + with self.assertRaises(HttpError): + self.call(*busy) + self.assertEqual(self.waits, list(RETRY_DELAYS_SECONDS)) + + def test_a_rate_limit_waits_the_minimum_and_is_retried_once(self) -> None: + self.assertEqual(self.call(self.RATE_LIMIT), self.ANSWER) + self.assertEqual(self.waits, [RATE_LIMIT_DELAY_SECONDS]) + with self.assertRaises(HttpError): + self.call(self.RATE_LIMIT, self.RATE_LIMIT) + self.assertEqual(self.waits, [RATE_LIMIT_DELAY_SECONDS]) class LedgerPathTest(unittest.TestCase): From cce9f592d3c695c72344cdca74ccc9f8817e0f5f Mon Sep 17 00:00:00 2001 From: Jeffrey Wall <265409180+jeffwall-curlewlabs@users.noreply.github.com> Date: Tue, 13 Oct 2026 18:53:57 -0700 Subject: [PATCH 2/2] Read gh's status line when the error body held no message gh reports a failed request's status in one of two forms. With a message from the error body it prints `gh: (HTTP )`; with none, as for a 5xx whose body is empty or not JSON, it falls back to the status alone (gh 2.101.0's processResponse): gh: HTTP 500 classify only read the first form, so the second came back status-less, counted as a refusal, and failed on the first attempt. The live check on this branch hit it on a ref delete during its cleanup. Both forms now yield the status, so a bare 5xx gets the busy ladder, and a bare 404 or 422 reaches the callers that act on those statuses as an HttpError. A status without a message has an empty one, and HttpError's text leaves the empty message out. --- src/github_cron_trigger/github.py | 19 ++++++++++++------- tests/test_steps.py | 6 +++++- 2 files changed, 17 insertions(+), 8 deletions(-) diff --git a/src/github_cron_trigger/github.py b/src/github_cron_trigger/github.py index b93ffd7..f0eb0e3 100644 --- a/src/github_cron_trigger/github.py +++ b/src/github_cron_trigger/github.py @@ -27,11 +27,14 @@ # while limited can get an integration banned. RATE_LIMIT_DELAY_SECONDS = 60 -# `gh api`'s stderr line for a failed HTTP request. The response body goes to +# `gh api`'s stderr line for a failed HTTP request: the error body's message +# and the status, or the status alone when the body held no message gh could +# read, as a 5xx with an empty or non-JSON body does. The response body goes to # stdout and often carries the status too, but not every error body does, so # the stderr line is what classification reads. _GH_API_ERROR = re.compile( - r"^gh: (?P.*) \(HTTP (?P\d{3})\)$", re.MULTILINE + r"^gh: (?:(?P.*) \(HTTP (?P\d{3})\)|HTTP (?P\d{3}))$", + re.MULTILINE, ) # The failures that carry no status, because `gh` got no answer. A failed name @@ -66,7 +69,7 @@ class HttpError(GitHubError): """GitHub answered with a non-success status after any retries.""" def __init__(self, status: int, message: str) -> None: - super().__init__(f"HTTP {status}: {message}") + super().__init__(f"HTTP {status}: {message}" if message else f"HTTP {status}") self.status = status self.message = message @@ -74,15 +77,17 @@ def __init__(self, status: int, message: str) -> None: def classify(stderr: str) -> tuple[int | None, str]: """The HTTP status and message of a failed `gh api` call, from its stderr. - The status is None when `gh` reported no HTTP exchange (a connection - failure, or a failure before any request); the message is then the whole - stderr. + The status is None when `gh` reported none (a connection failure, an + answer it could not decode, or a failure before any request); the message + is then the whole stderr. A status reported without a message has an empty + one. """ text = stderr.strip() match = _GH_API_ERROR.search(text) if match is None: return None, text - return int(match.group("status")), match.group("message") + status = match.group("status") or match.group("bare") + return int(status), match.group("message") or "" def transient(status: int | None, message: str) -> bool: diff --git a/tests/test_steps.py b/tests/test_steps.py index d04bd50..e31f09a 100644 --- a/tests/test_steps.py +++ b/tests/test_steps.py @@ -525,7 +525,8 @@ class GhFailureClassificationTest(unittest.TestCase): print for those failures. The unanswered-request lines are `gh api` output too: the timeouts from a clock host's log, with the repository renamed, and the proxy line from pointing HTTPS_PROXY at a closed port. The cut-off - answer line is from the same clock host's log. + answer line is from the same clock host's log, and the bare 500 from a live + check's ref delete. """ def test_refusals_are_not_retried(self) -> None: @@ -546,6 +547,9 @@ def test_refusals_are_not_retried(self) -> None: def test_busy_and_unreachable_are_retried(self) -> None: for stderr in ( "gh: Server Error (HTTP 502)", + # A 5xx whose body held no message: gh prints the status alone. + # Read as status-less, it failed a ref delete on the first attempt. + "gh: HTTP 500", "error connecting to api.github.com\ncheck your internet connection", # An answer that arrived empty or cut off, which gh reports with no # status whether it came from a `--jq` read, a GraphQL query or an