From 75fe7ccafb01cc72148f6c2ef0cd41df3b0ee320 Mon Sep 17 00:00:00 2001
From: Kevin Veen-Birkenbach <kevin@veen.world>
Date: Fri, 4 Sep 2026 16:31:17 +0200
Subject: [PATCH] fix(swarm-matrix): make every phase report what it cost

The step banner announced a start and nothing else, so a phase duration had to be read off the next banner, and a phase with no output of its own was invisible. In the budget-killed Nextcloud#0 of run 33828309745 the credential rotation spent 17 minutes with nothing but the 30-second sampler between its banner and the next one, and reconstructing the split between provisioning, both passes, the DR drill and the rotation meant subtracting timestamps by hand.

The watch loop moves unchanged into _run_watched. _run now brackets it and prints the elapsed time and the exit code, so this holds for every phase, not only the rotation.

The test stubs _run_watched and pins the three things that matter: the exit code passes through, the opening banner is printed, and the closing line carries duration and rc. It is the first test over this module, whose absence was named earlier as the reason a wrong change to the pass sequence would turn nothing red.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
---
 .../tests/swarm/test_matrix_run_reporting.py  | 42 +++++++++++++++++++
 utils/tests/swarm/matrix.py                   | 32 +++++++++++++-
 2 files changed, 72 insertions(+), 2 deletions(-)
 create mode 100644 tests/unit/python/utils/tests/swarm/test_matrix_run_reporting.py

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: