Retry a cut-off answer, and wait out a rate limit on its own

.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
 

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

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"

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<message>.*) \(HTTP (?P<status>\d{3})\)$", re.MULTILINE
+    r"^gh: (?:(?P<message>.*) \(HTTP (?P<status>\d{3})\)|HTTP (?P<bare>\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,56 +69,79 @@ 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
 
 
 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:

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):