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..f0eb0e3 100644 --- a/src/github_cron_trigger/github.py +++ b/src/github_cron_trigger/github.py @@ -15,17 +15,26 @@ # 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) - -# `gh api`'s stderr line for a failed HTTP request. The response body goes to +# 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 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 @@ -38,6 +47,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" @@ -53,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 @@ -61,48 +77,71 @@ 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: - """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 +153,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..e31f09a 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,9 @@ 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, and the bare 500 from a live + check's ref delete. """ def test_refusals_are_not_retried(self) -> None: @@ -530,16 +542,19 @@ 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)" - ), + # 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 + # 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 +580,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):