diff --git a/tests/unit/python/utils/tests/swarm/test_matrix_run_reporting.py b/tests/unit/python/utils/tests/swarm/test_matrix_run_reporting.py new file mode 100644 index 0000000000..4f27992dcb --- /dev/null +++ b/tests/unit/python/utils/tests/swarm/test_matrix_run_reporting.py @@ -0,0 +1,42 @@ +import contextlib +import io +import unittest +from unittest import mock + +from utils.tests.swarm import matrix + + +class TestRunReporting(unittest.TestCase): + """Every matrix phase must state what it cost. + + A phase that only announces its start leaves the reader subtracting + timestamps by hand, and a phase that produces no output of its own becomes + invisible: the credential rotation spent 17 minutes of a budget-killed job + with nothing but the 30-second sampler in between. + """ + + def _run_capturing(self, rc: int) -> tuple[int, str]: + buffer = io.StringIO() + with ( + mock.patch.object(matrix, "_run_watched", return_value=rc) as watched, + contextlib.redirect_stdout(buffer), + ): + returned = matrix._run(["true"], env={"A": "b"}, label="demo phase") + watched.assert_called_once_with(["true"], env={"A": "b"}) + return returned, buffer.getvalue() + + def test_the_exit_code_passes_through(self) -> None: + returned, _ = self._run_capturing(7) + self.assertEqual(returned, 7) + + def test_the_phase_announces_its_start(self) -> None: + _, output = self._run_capturing(0) + self.assertIn("=== swarm-matrix: demo phase ===", output) + + def test_the_phase_reports_its_duration_and_outcome(self) -> None: + _, output = self._run_capturing(124) + self.assertRegex(output, r"demo phase took \d+s \(rc=124\)") + + +if __name__ == "__main__": + unittest.main() diff --git a/utils/tests/swarm/matrix.py b/utils/tests/swarm/matrix.py index fff9f18533..c75ac88320 100644 --- a/utils/tests/swarm/matrix.py +++ b/utils/tests/swarm/matrix.py @@ -24,6 +24,7 @@ import os import shutil import subprocess import sys +import time from utils import PROJECT_ROOT from utils.env.runtime import mem_available_mb, mem_stall_pct, mem_total_mb @@ -52,13 +53,40 @@ def _abort(proc: subprocess.Popen[bytes], banner: str, probe: list[str]) -> int: def _run(cmd: list[str], *, env: dict[str, str], label: str) -> int: - """Run a matrix step, aborting visibly before the runner disk or RAM fills. + """Announce a matrix step, run it, and report what it cost. + + Args: + cmd: argv of the step. + env: environment the step runs with. + label: phase name for the banners. + + Returns: + The step's exit code. + """ + print(f"=== swarm-matrix: {label} ===", flush=True) + started = time.monotonic() + rc = _run_watched(cmd, env=env) + print( + f"=== swarm-matrix: {label} took {time.monotonic() - started:.0f}s (rc={rc}) ===", + flush=True, + ) + return rc + + +def _run_watched(cmd: list[str], *, env: dict[str, str]) -> int: + """Run a step, aborting visibly before the runner disk or RAM fills. The Actions Worker dies silently on ENOSPC while writing its own logs, so a full disk truncates the job without diagnostics; terminating the step at DISK_FLOOR_MB keeps enough room for rescue artifacts and the log upload. + + Args: + cmd: argv of the step. + env: environment the step runs with. + + Returns: + The step's exit code, or the abort code when a floor was hit. """ - print(f"=== swarm-matrix: {label} ===", flush=True) proc = subprocess.Popen(cmd, cwd=str(PROJECT_ROOT), env=env) while True: try: