From e153ad339189338fabcfdd23fa676e50247cc445 Mon Sep 17 00:00:00 2001 From: Edgar Arakelyan Date: Tue, 20 Oct 2026 17:06:07 -0700 Subject: [PATCH] fix(release): pass on a retried command's output and its retry warning as they come In the workflow, the script's stdout is a pipe, which Python holds until its buffer fills: a build's lines came through in bursts, and the warning that a rate-limited command would be tried again could stay hidden through the wait, so the job looked stuck. Each forwarded line and each warning is flushed. Co-Authored-By: Claude Opus 5.5 (1M context) --- .github/scripts/infra_build.py | 7 +++++-- tst/unit/test_infra_build_script.py | 27 +++++++++++++++++++++++++++ 2 files changed, 32 insertions(+), 2 deletions(-) diff --git a/.github/scripts/infra_build.py b/.github/scripts/infra_build.py index 561f078a..538c2b35 100644 --- a/.github/scripts/infra_build.py +++ b/.github/scripts/infra_build.py @@ -103,17 +103,20 @@ def _until_not_rate_limited(attempt: Callable[[], subprocess.CompletedProcess]) result = attempt() if result.returncode == 0 or not _RATE_LIMITED.search(f"{result.stdout}{result.stderr}"): return result - print(f"::warning::a registry rate-limited `{' '.join(result.args)[:_PRINTED_CHARS]}`; trying again in {wait}s") + print(f"::warning::a registry rate-limited `{' '.join(result.args)[:_PRINTED_CHARS]}`; trying again in {wait}s", + flush=True) time.sleep(wait) return attempt() def _streamed(argv: list[str]) -> subprocess.CompletedProcess: - """Run ``argv``, printing what it prints as it prints it, which is kept too, to look for a rate limit in.""" + """Run ``argv``, printing what it prints as it prints it, which is kept too, to look for a rate limit in. Each line is + flushed, since the workflow's log is a pipe, which Python would otherwise fill before passing on.""" process = subprocess.Popen(argv, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True) printed = [] for line in process.stdout: sys.stdout.write(line) + sys.stdout.flush() printed.append(line) return subprocess.CompletedProcess(argv, process.wait(), "".join(printed), "") diff --git a/tst/unit/test_infra_build_script.py b/tst/unit/test_infra_build_script.py index 63d57f0f..c6aa4199 100644 --- a/tst/unit/test_infra_build_script.py +++ b/tst/unit/test_infra_build_script.py @@ -290,3 +290,30 @@ def test_a_rate_limited_registry_lookup_is_tried_again(script, monkeypatch, caps monkeypatch.setattr(script.time, "sleep", lambda seconds: None) assert _run(script, monkeypatch, "exists", ref) == 0 + + +class _Log: + """A pipe standing in for the workflow's log: what was written, and what had been flushed each time.""" + + def __init__(self): + self.written, self.flushed = "", [] + + def write(self, text: str) -> int: + self.written += text + return len(text) + + def flush(self) -> None: + self.flushed.append(self.written) + + +def test_retry_passes_on_each_line_and_its_warning_as_it_goes(script, monkeypatch): + """Through a pipe, Python holds output until the buffer fills, so a build or a wait would look stuck.""" + runs, waits = _attempts(script, monkeypatch, [(_LIMITED, 1), ("#1 DONE\n#2 DONE\n", 0)]) + log = _Log() + monkeypatch.setattr(script.sys, "stdout", log) + + assert _run(script, monkeypatch, "retry", "docker", "build", ".") == 0 + + assert log.flushed[0] == _LIMITED + assert log.flushed[1].endswith("trying again in 30s\n") + assert log.flushed[2:] == [log.flushed[1] + "#1 DONE\n", log.flushed[1] + "#1 DONE\n#2 DONE\n"]