diff --git a/scripts/read-run-failure.py b/scripts/read-run-failure.py index 3b4cd95f..592705d5 100644 --- a/scripts/read-run-failure.py +++ b/scripts/read-run-failure.py @@ -46,11 +46,15 @@ Exit codes ---------- - 0 a failed job was found and its cause was printed - 1 the run has no failed job - a determinate reading, not a failure to measure + 0 a failed job was found and its cause was printed, **or** the run failed while no job + did, and the job that accounts for it was printed instead (a job cancelled before it + was assigned a runner is that case: it never started, so there is no step output) + 1 the run has no failed job **and** no unstarted job to blame - a determinate reading, + not a failure to measure 2 the question could not be answered (bad run id, gh failed, no jobs listed, a job's - log could not be fetched or came back empty) - fail loud; never report "no cause" - for a log nobody read + log could not be fetched or came back empty, a run whose own conclusion could not be + read while a job had not succeeded) - fail loud; never report "no cause" for a log + nobody read The empty-log case is the one that looks like a pass and is not: the fetch succeeded, so `gh` exits 0 and there is no error to surface, but a failed job with nothing in its log has @@ -95,6 +99,7 @@ from __future__ import annotations import argparse +import datetime import json import re import subprocess @@ -278,6 +283,93 @@ def _clean(line: str) -> str: return text if len(text) <= _MAX_LINE else text[: _MAX_LINE - 3] + "..." +def _run_conclusion(run_id: int, repo: str) -> str: + """The run's own `conclusion` - the field that says whether there is a failure at all. + + Read from the run, not inferred from its jobs: a run that succeeded while some jobs were + skipped (`workflow_dispatch` on a branch skips `verify-*` and `release` by design) and a + run that failed with a cancelled job have the same thing to see in the job list, and the + run's conclusion is what tells them apart. + """ + payload = json.loads(_gh_api(f"repos/{repo}/actions/runs/{run_id}")) + if not isinstance(payload, dict): + raise RuntimeError(f"the run object for {run_id} is not a mapping") + conclusion = payload.get("conclusion") + status = payload.get("status") + if conclusion is None: + raise RuntimeError( + f"run {run_id} reports status `{status}` and no conclusion yet" + ) + return str(conclusion) + + +def _elapsed(job: dict) -> str: + """How long the job held, from its own timestamps; `unknown` when they are absent.""" + started, ended = job.get("started_at"), job.get("completed_at") + if not isinstance(started, str) or not isinstance(ended, str): + return "unknown" + try: + seconds = int( + (datetime.datetime.fromisoformat(ended.replace("Z", "+00:00")) + - datetime.datetime.fromisoformat(started.replace("Z", "+00:00"))).total_seconds() + ) + except ValueError: + return "unknown" + if seconds < 0: + return "unknown" + return f"{seconds // 60}m{seconds % 60:02d}s" + + +def _otherwise_lines(job: dict) -> list[str]: + """The lines that explain a job which did not fail but accounts for a failed run. + + The distinction this keeps is the one that decides the remedy: a job **cancelled after a + step failed** is a code or environment problem with a log, while a job **cancelled with + no step executed and no runner assigned** never started at all - its cause is scheduling, + and no amount of reading its (nonexistent) output would find it. + """ + name = str(job.get("name")) + conclusion = str(job.get("conclusion") or "(none)") + steps = [step for step in (job.get("steps") or []) if isinstance(step, dict)] + runner = job.get("runner_name") + lines = [f" {name} [{conclusion}] held {_elapsed(job)}"] + if not steps: + lines.append( + " no step executed - the job never started, so there is no step output to read" + ) + else: + last = steps[-1] + lines.append( + f" {len(steps)} step(s) recorded; the last was {last.get('number')}. " + f"{last.get('name')} [{last.get('conclusion') or '(none)'}]" + ) + if not runner: + lines.append( + " no runner was ever assigned to it (runner_name is null) - this is a " + "scheduling outcome, not a step failure, and re-running is what asks the " + "scheduler again" + ) + else: + lines.append(f" it ran on {runner}") + return lines + + +def _otherwise_report(job: dict) -> dict: + """The same explanation, as data, for `--json`.""" + steps = [step for step in (job.get("steps") or []) if isinstance(step, dict)] + return { + "name": job.get("name"), + "conclusion": job.get("conclusion"), + "elapsed": _elapsed(job), + "runner_name": job.get("runner_name"), + "steps_executed": len(steps), + "last_step": ( + f"{steps[-1].get('number')}. {steps[-1].get('name')} " + f"[{steps[-1].get('conclusion') or '(none)'}]" if steps else None + ), + } + + def _step_cause(job: dict) -> tuple[list[str], list[str]]: """`(the steps that did not succeed, unknown conclusions)` for one job, as names. @@ -480,6 +572,73 @@ def main(argv: list[str] | None = None) -> int: print(f"transport: {', '.join(transports_used())}") if not failed_jobs: + # A run can conclude `failure` while **no job's** conclusion is a failure: a job that + # was cancelled before it was ever assigned a runner is that case, and it is not + # exotic - measured 2026-11-04 on run 41862508461 (the `v0.3.37` release), where + # `verify-credentials` was queued from the run's first second, never acquired a + # runner, and was cancelled after 15m02s; `build` then ran because its own `if:` + # admits a cancelled dependency, and `release` was skipped because it needs `build`, + # which needs that job. Answering "nothing to explain" there is the same defect as + # reporting "could not measure" as a pass, and it costs more, because the reading + # that recommends this command (`check-release-published.py`'s FAULT remedy) is the + # one an operator reaches *after* the run has already been reported as failed. + # + # The run's own conclusion is what separates this from a run that succeeded with + # some jobs skipped (`workflow_dispatch` on a branch skips `verify-*` and `release` + # by design). It is fetched only here, so the ordinary paths keep one request. + if other_jobs: + try: + run = _run_conclusion(args.run_id, args.repo) + except Exception as exc: # noqa: BLE001 - a report, not a crash + print( + f"error: run {args.run_id} lists {len(other_jobs)} job(s) that did not " + f"succeed and its own conclusion could not be read ({exc}) - whether this " + "run failed is exactly the question, so it is unmeasured rather than " + "'nothing to explain'", + file=sys.stderr, + ) + return 2 + if run != "success": + # A `skipped` job is a **consequence**, never a cause: `release` is skipped + # exactly because the job it needs did not succeed, and telling a reader that + # "re-running asks the scheduler again" about it would send them after the + # wrong job. The causes are the ones that were cancelled or otherwise ended + # without success; the skipped ones are named, once, as what followed. + blocking = [ + job for job in other_jobs + if str(job.get("conclusion") or "") != "skipped" + ] + consequent = [ + job for job in other_jobs + if str(job.get("conclusion") or "") == "skipped" + ] + if args.json: + print(json.dumps({ + "run": args.run_id, "repo": args.repo, "failed": True, + "run_conclusion": run, "transport": transports_used(), + "without_a_failed_job": [ + _otherwise_report(job) for job in blocking + ], + "skipped_as_a_consequence": [ + {"name": job.get("name"), + "conclusion": job.get("conclusion")} for job in consequent + ], + }, indent=2)) + else: + print( + f"no failed job in run {args.run_id} - the run itself concluded " + f"`{run}`, and the job(s) that account for it are:" + ) + for job in blocking: + for line in _otherwise_lines(job): + print(line) + if consequent: + names = ", ".join(str(job.get("name")) for job in consequent) + print( + f" {names} [skipped] - downstream of the job(s) above, which is " + "what skipping means here; the cause is not in them" + ) + return 0 # A determinate reading: nothing failed. Exit 1, not 0 - "no failure" is not the # answer this tool was asked for, and a caller scripting it should see the # difference rather than a silent success. diff --git a/tests/test_read_run_failure.py b/tests/test_read_run_failure.py index 07496b29..1e07eaac 100644 --- a/tests/test_read_run_failure.py +++ b/tests/test_read_run_failure.py @@ -110,11 +110,14 @@ class FakeGh: """ def __init__(self, jobs: list[dict], logs: dict[int, str] | None = None, - jobs_rc: int = 0, total_count: int | None = None): + jobs_rc: int = 0, total_count: int | None = None, + run_conclusion: str | None = "success", run_rc: int = 0): self.jobs = jobs self.logs = logs or {} self.jobs_rc = jobs_rc self.total_count = total_count + self.run_conclusion = run_conclusion + self.run_rc = run_rc self.calls: list[str] = [] def __call__(self, path: str) -> str: @@ -129,6 +132,14 @@ def __call__(self, path: str) -> str: if self.total_count is not None: payload["total_count"] = self.total_count return json.dumps(payload) + if re.search(r"/actions/runs/\d+$", path): + if self.run_rc: + raise RuntimeError( + f"gh api {path} failed (rc=1): gh: Server Error (HTTP 502)" + ) + return json.dumps( + {"id": 42, "status": "completed", "conclusion": self.run_conclusion} + ) if "/logs" in path: job_id = int(path.split("/actions/jobs/")[1].split("/")[0]) if job_id not in self.logs: @@ -191,6 +202,130 @@ def test_a_silent_step_is_still_named_by_the_job_payload(mod, monkeypatch, capsy assert "APPLE_ID: ***" in out, "the step's own block is what got printed" +# --- a run that failed with no failed job ----------------------------------- +# +# Measured 2026-11-04 on run 41862508461 (the v0.3.37 release): `verify-credentials` was +# queued from the run's first second, never acquired a runner, and was cancelled after +# 15m02s. `build` ran anyway - its own `if:` admits a cancelled dependency - and `release` +# was skipped because it needs `build`, which needs that job. Every job's own conclusion was +# therefore success, cancelled or skipped, so `failed_jobs` was empty and the tool answered +# "nothing to explain" about a run whose conclusion is `failure`. The reading that sends an +# operator here (`check-release-published.py`'s FAULT remedy) is the one reached *after* the +# failure, so that answer is the whole cause they get. + +#: The starved job exactly as the API reports it: no steps, no runner, 15m02s held. +_STARVED = { + "id": 9, + "name": "verify-credentials", + "conclusion": "cancelled", + "runner_name": None, + "started_at": "2026-11-04T19:05:01Z", + "completed_at": "2026-11-04T19:20:03Z", + "steps": [], +} + + +def test_a_failed_run_whose_only_other_job_never_started_is_explained( + mod, monkeypatch, capsys +): + """The run failed, no job did: the unstarted job is the cause, and it must be named. + + Exit 0 because the question *was* answered - not 1, which means "there is nothing to + explain". + """ + fake = FakeGh( + [_job(name="verify-tag", conclusion="success"), _STARVED], + run_conclusion="failure", + ) + rc = _run(mod, monkeypatch, fake, ["42"]) + out = capsys.readouterr().out + assert rc == 0, f"a failed run was reported as having nothing to explain:\n{out}" + assert "verify-credentials [cancelled]" in out + assert "15m02s" in out, "the elapsed time is the reading that says it was starved" + assert "no step executed" in out + assert "no runner was ever assigned" in out, ( + "the distinction that decides the remedy is scheduling, not a step failure, so " + "the runner field is the fact to print" + ) + assert "nothing to explain" not in out + + +def test_a_run_that_succeeded_with_skipped_jobs_still_says_nothing_to_explain( + mod, monkeypatch, capsys +): + """The control: a branch dispatch skips `verify-*` and `release` by design. + + Without this leg the new branch would fire on every `workflow_dispatch` run and turn a + normal skip into a reported failure. + """ + fake = FakeGh( + [_job(conclusion="success"), _job(name="release", conclusion="skipped", job_id=2)], + run_conclusion="success", + ) + rc = _run(mod, monkeypatch, fake, ["42"]) + out = capsys.readouterr().out + assert rc == 1, "a run that succeeded has no failure to explain" + assert "nothing to explain" in out + + +def test_an_unreadable_run_conclusion_is_unmeasured_not_explained( + mod, monkeypatch, capsys +): + """Whether the run failed is the question, so failing to read it is exit 2. + + Without this the tool would fall through to "nothing to explain" whenever the second + request failed - the same shape as the defect the branch exists to remove. + """ + fake = FakeGh( + [_job(conclusion="success"), _STARVED], + run_conclusion="failure", + run_rc=1, + ) + rc = _run(mod, monkeypatch, fake, ["42"]) + captured = capsys.readouterr() + assert rc == 2, f"an unread run conclusion was answered as a verdict:\n{captured.out}" + assert "unmeasured" in captured.err + assert "nothing to explain" not in captured.out + + +def test_a_skipped_job_is_named_as_a_consequence_not_a_cause( + mod, monkeypatch, capsys +): + """`release` is skipped *because* the job it needs did not succeed. + + Reported as a cause it would send the reader after the wrong job: the line that explains + a starved job says re-running asks the scheduler again, which is true of the cancelled + preflight and false of a job the graph skipped. + """ + skipped = _job(name="release", conclusion="skipped", job_id=3) + skipped["steps"] = [] + fake = FakeGh([_STARVED, skipped], run_conclusion="failure") + rc = _run(mod, monkeypatch, fake, ["42"]) + out = capsys.readouterr().out + assert rc == 0 + assert "verify-credentials [cancelled]" in out + assert "release [skipped]" in out and "downstream" in out + consequence_at = out.index("release [skipped]") + assert "no runner was ever assigned" not in out[consequence_at:], ( + "the skipped job was explained with the starved job's reasoning:\n" + out + ) + + +def test_the_explanation_is_machine_readable(mod, monkeypatch, capsys): + """`--json` carries the same facts, so a caller need not parse the prose.""" + fake = FakeGh([_STARVED], run_conclusion="failure") + rc = _run(mod, monkeypatch, fake, ["42", "--json"]) + out = capsys.readouterr().out + assert rc == 0 + payload = json.loads(out) + assert payload["failed"] is True and payload["run_conclusion"] == "failure" + job = payload["without_a_failed_job"][0] + assert job["name"] == "verify-credentials" + assert job["runner_name"] is None + assert job["steps_executed"] == 0 + assert job["elapsed"] == "15m02s" + + # --- the three-valued outcome ----------------------------------------------