diff --git a/autohands/build_util.py b/autohands/build_util.py index 5dbed48..4489e33 100644 --- a/autohands/build_util.py +++ b/autohands/build_util.py @@ -14,6 +14,78 @@ BUILD_PYTHON_INTERPRETER = os.environ.get("BUILD_PYTHON_INTERPRETER", "python3") +# Characters of captured child output kept from each stream when a run times +# out. A timed-out script is killed mid-flight, so its tail is the only clue to +# which block was executing — enough to name the block, not so much that a +# chatty script floods the report. +TIMEOUT_OUTPUT_TAIL_CHARS = 2000 + + +def timeout_for(env=None) -> int: + """Return the per-run timeout in seconds for a script or notebook. + + ``TIMEOUT_SECS`` is read once at import from the parent's own environment, + so on its own it can only ever express ONE cap for a whole run. The + per-script environment built by ``env_config.build_env_for_script`` is + handed to the child, and a profile may set ``BUILD_SCRIPT_TIMEOUT`` on it + for a matching pattern — but the ``subprocess.run(timeout=...)`` kill timer + lives in the PARENT, so that value has no effect unless the parent reads it + back out. This resolves it. + + Precedence (highest first): + + 1. ``BUILD_SCRIPT_TIMEOUT`` on the per-script ``env`` (a profile override), + 2. ``TIMEOUT_SECS`` — the ambient/global value at import. + + A profile value deliberately wins over the ambient global. The alternative + ("an explicitly supplied global always wins") is unimplementable here: + ``run_all`` exports ``BUILD_SCRIPT_TIMEOUT`` unconditionally, even when 300 + was merely its CLI default, so the parent cannot tell an operator's + deliberate cap from the default. Under that rule per-script budgets would + work in CI (which does not go through ``run_all``) and be silently ignored + locally — the exact silent-divergence class this function exists to remove. + + Malformed, zero or negative values fall back to ``TIMEOUT_SECS``: a bad + profile entry must not disable the cap altogether. + """ + if not env: + return TIMEOUT_SECS + raw = env.get("BUILD_SCRIPT_TIMEOUT") + if raw is None: + return TIMEOUT_SECS + try: + value = int(raw) + except (TypeError, ValueError): + return TIMEOUT_SECS + return value if value > 0 else TIMEOUT_SECS + + +def _timeout_output(e: subprocess.TimeoutExpired) -> str: + """Render the tail of a timed-out child's captured output. + + ``subprocess.TimeoutExpired`` carries whatever was captured before the kill, + but only when the call captured it (``capture_output``/``stdout=PIPE``); + otherwise both attributes are None and the child wrote straight to the + console. Streams may be bytes or str depending on ``text=``. + """ + + def tail(stream) -> str: + if not stream: + return "" + if isinstance(stream, bytes): + stream = stream.decode("utf-8", errors="replace") + stream = stream.strip() + if len(stream) > TIMEOUT_OUTPUT_TAIL_CHARS: + return "...[truncated]...\n" + stream[-TIMEOUT_OUTPUT_TAIL_CHARS:] + return stream + + parts = [] + for label, stream in (("stdout", e.stdout), ("stderr", e.stderr)): + text = tail(stream) + if text: + parts.append(f"--- last {label} before timeout ---\n{text}") + return "\n".join(parts) + def py_to_notebook(filename: Path): subprocess.run( @@ -220,6 +292,8 @@ def is_clean_skip_exit(output: str) -> bool: def execute_notebook(f, report=None, env=None): print(f"Running <{f}> at {datetime.datetime.now().isoformat()}") + timeout_secs = timeout_for(env) + start = time.time() try: # stderr is always captured so a clean `sys.exit(0)` skip guard can be @@ -239,7 +313,7 @@ def execute_notebook(f, report=None, env=None): str(Path.cwd()), ], check=True, - timeout=TIMEOUT_SECS, + timeout=timeout_secs, stdout=subprocess.PIPE if report is not None else None, stderr=subprocess.PIPE, text=True, @@ -250,11 +324,17 @@ def execute_notebook(f, report=None, env=None): if report is not None: from result_collector import ScriptResult, Status print(f" TIMEOUT ({duration:.0f}s)") + # Same reasoning as execute_script: stderr is always piped here, so + # the failing cell's tail survives the kill and reaches the report. + message = "Timed out after {:.0f}s (cap {}s)".format(duration, timeout_secs) + captured = _timeout_output(e) + if captured: + message = f"{message}\n{captured}" report.results.append(ScriptResult( file=str(f), status=Status.TIMEOUT, duration_seconds=duration, - error_message="Timed out after {:.0f}s".format(duration), + error_message=message, )) return logging.exception(e) @@ -371,13 +451,15 @@ def execute_script(f, report=None, env=None, extra_args=None): script_name = Path(f).relative_to(Path.cwd()) if Path(f).is_relative_to(Path.cwd()) else Path(f).name print(f" {script_name} ...", end=" ", flush=True) + timeout_secs = timeout_for(env) + start = time.time() try: if report is not None: result = subprocess.run( args, check=True, - timeout=TIMEOUT_SECS, + timeout=timeout_secs, capture_output=True, text=True, env=env, @@ -386,7 +468,7 @@ def execute_script(f, report=None, env=None, extra_args=None): subprocess.run( args, check=True, - timeout=TIMEOUT_SECS, + timeout=timeout_secs, env=env, ) except subprocess.TimeoutExpired as e: @@ -394,11 +476,18 @@ def execute_script(f, report=None, env=None, extra_args=None): if report is not None: from result_collector import ScriptResult, Status print(f" TIMEOUT ({duration:.0f}s)") + # Keep the child's captured tail: a killed script never reports its + # own progress, so without this a TIMEOUT cannot say WHICH block was + # running and every diagnosis restarts from zero. + message = "Timed out after {:.0f}s (cap {}s)".format(duration, timeout_secs) + captured = _timeout_output(e) + if captured: + message = f"{message}\n{captured}" report.results.append(ScriptResult( file=str(f), status=Status.TIMEOUT, duration_seconds=duration, - error_message="Timed out after {:.0f}s".format(duration), + error_message=message, )) return logging.exception(e) diff --git a/autohands/slow_skip_check.py b/autohands/slow_skip_check.py index f9e2fb3..061ee3e 100644 --- a/autohands/slow_skip_check.py +++ b/autohands/slow_skip_check.py @@ -19,7 +19,17 @@ a performance fix. The cap is `build_util.TIMEOUT_SECS` — 300s by default, raised to 1800s for `mode=release` runs via BUILD_SCRIPT_TIMEOUT — and is never hardcoded here, so the reported figure cannot drift away from the -enforced one. NEEDS_FIX entries indicate scripts that are broken and parked +enforced one. + +That figure is the run-wide DEFAULT, not necessarily the cap a given script +ran under: an env profile may set `BUILD_SCRIPT_TIMEOUT` on an `overrides` +pattern, which `build_util.timeout_for` resolves per script. The banner +therefore says "default" rather than asserting one cap for every script. +Understating a cap is not cosmetic — a quoted figure below the enforced one +biases every "is this script too slow to un-skip?" call toward parking +scripts that would in fact pass (the 60s-cap myth, PyAutoHands#172). + +NEEDS_FIX entries indicate scripts that are broken and parked for later investigation — a to-do list surfaced on every mega-run so fixes don't get forgotten. """ @@ -142,8 +152,9 @@ def find_needs_fix_skips(workspace_dirs: List[Path]) -> List[TaggedSkip]: "slow": { "header": "WARNING: {n} SLOW-SKIPPED SCRIPT(S) - needs performance fix", "footer": [ - " These scripts are skipped because they exceed the {t}s per-script", - " cap. Fix the performance issue and remove the SLOW marker from", + " These scripts are skipped because they exceed the {t}s default", + " per-script cap (an env profile may raise it for some scripts).", + " Fix the performance issue and remove the SLOW marker from", " the workspace's config/build/no_run.yaml.", ], }, @@ -162,7 +173,8 @@ def find_needs_fix_skips(workspace_dirs: List[Path]) -> List[TaggedSkip]: "title": "## Slow-Skipped Scripts (needs performance fix)", "intro": ( "**{n} script(s)** are being skipped because they exceed the {t}s " - "per-script timeout cap. These are NOT permanent skips — they need " + "default per-script timeout cap (an env profile may raise it for " + "some scripts). These are NOT permanent skips — they need " "the underlying performance issue fixed and the `SLOW` marker " "removed from the workspace's `config/build/no_run.yaml`." ), diff --git a/tests/test_script_timeout.py b/tests/test_script_timeout.py new file mode 100644 index 0000000..fd1504e --- /dev/null +++ b/tests/test_script_timeout.py @@ -0,0 +1,209 @@ +"""Unit tests for the per-script timeout budget. + +``BUILD_SCRIPT_TIMEOUT`` used to be read once at import into +``build_util.TIMEOUT_SECS`` and applied directly as the +``subprocess.run(timeout=...)`` kill timer. The per-script environment built by +``env_config.build_env_for_script`` is handed to the CHILD, so a profile that +set ``BUILD_SCRIPT_TIMEOUT`` on an ``overrides`` pattern was silently ignored: +the parent's timer never saw it. ``build_util.timeout_for`` closes that gap by +resolving the value parent-side. + +Two properties matter and are both covered end-to-end (a real subprocess that +sleeps past its cap), not just at the resolver: + +1. a matching script is killed at its OWN cap, not the global one, and +2. a non-matching script is unaffected. + +The timeout report also has to preserve the child's captured output. A killed +script cannot report its own progress, so without that tail a TIMEOUT cannot +say which block was executing — the reason the three jax_grad timeouts could +not be diagnosed from CI artefacts at all (PyAutoHands#226). +""" + +import os +import subprocess +import sys +from pathlib import Path + +import pytest + +PROJECT_ROOT = Path(__file__).parent.parent +AUTOHANDS_DIR = PROJECT_ROOT / "autohands" +sys.path.insert(0, str(AUTOHANDS_DIR)) + +import build_util # noqa: E402 +from build_util import _timeout_output, execute_script, timeout_for # noqa: E402 +from result_collector import RunReport, Status # noqa: E402 + + +class TestTimeoutFor: + """Resolution of the effective per-run cap.""" + + def test_no_env_uses_global(self): + assert timeout_for(None) == build_util.TIMEOUT_SECS + + def test_empty_env_uses_global(self): + assert timeout_for({}) == build_util.TIMEOUT_SECS + + def test_env_without_the_var_uses_global(self): + assert timeout_for({"PYAUTO_TEST_MODE": "2"}) == build_util.TIMEOUT_SECS + + def test_profile_value_wins(self): + assert timeout_for({"BUILD_SCRIPT_TIMEOUT": "1800"}) == 1800 + + def test_profile_value_may_lower_the_cap(self): + # Nothing special about raising: a profile may also tighten a cap. + assert timeout_for({"BUILD_SCRIPT_TIMEOUT": "5"}) == 5 + + @pytest.mark.parametrize("bad", ["", "abc", "12.5", "None", " "]) + def test_malformed_falls_back_to_global(self, bad): + # A bad profile entry must never disable the cap entirely. + assert timeout_for({"BUILD_SCRIPT_TIMEOUT": bad}) == build_util.TIMEOUT_SECS + + @pytest.mark.parametrize("bad", ["0", "-1", "-1800"]) + def test_zero_or_negative_falls_back_to_global(self, bad): + # subprocess.run(timeout=0) would kill instantly and timeout<0 raises; + # both must degrade to the global cap rather than break the run. + assert timeout_for({"BUILD_SCRIPT_TIMEOUT": bad}) == build_util.TIMEOUT_SECS + + def test_precedence_profile_over_ambient_global(self, monkeypatch): + # run_all exports BUILD_SCRIPT_TIMEOUT unconditionally, even when 300 + # was only its CLI default, so the parent cannot distinguish a + # deliberate operator cap from the default. The profile value therefore + # wins -- otherwise per-script budgets would work under CI and be + # silently ignored under run_all. + monkeypatch.setattr(build_util, "TIMEOUT_SECS", 300) + assert timeout_for({"BUILD_SCRIPT_TIMEOUT": "1800"}) == 1800 + + def test_release_global_applies_when_no_override_matches(self, monkeypatch): + # mode=release exports 1800 globally; a script with no profile override + # must still get 1800, not the 300 default. + monkeypatch.setattr(build_util, "TIMEOUT_SECS", 1800) + assert timeout_for({"PYAUTO_TEST_MODE": "0"}) == 1800 + + +class TestTimeoutOutput: + """The captured tail rendered into the TIMEOUT report.""" + + def test_none_streams_render_empty(self): + e = subprocess.TimeoutExpired(cmd="x", timeout=1) + assert _timeout_output(e) == "" + + def test_stdout_is_labelled(self): + e = subprocess.TimeoutExpired(cmd="x", timeout=1, output="=== variant 3 ===") + out = _timeout_output(e) + assert "last stdout before timeout" in out + assert "=== variant 3 ===" in out + + def test_bytes_are_decoded(self): + e = subprocess.TimeoutExpired(cmd="x", timeout=1, output=b"block C") + assert "block C" in _timeout_output(e) + + def test_undecodable_bytes_do_not_raise(self): + e = subprocess.TimeoutExpired(cmd="x", timeout=1, output=b"\xff\xfeblock C") + assert "block C" in _timeout_output(e) + + def test_long_output_is_truncated_keeping_the_tail(self): + # The TAIL is what identifies the block that was running when killed. + e = subprocess.TimeoutExpired( + cmd="x", + timeout=1, + output="A" * 50_000 + "THE-LAST-BLOCK", + ) + out = _timeout_output(e) + assert "THE-LAST-BLOCK" in out + assert "truncated" in out + assert len(out) < 50_000 + + def test_both_streams_present(self): + e = subprocess.TimeoutExpired( + cmd="x", timeout=1, output="on stdout", stderr="on stderr" + ) + out = _timeout_output(e) + assert "on stdout" in out + assert "on stderr" in out + + +def _write_script(tmp_path: Path, body: str) -> Path: + script = tmp_path / "script.py" + script.write_text(body) + return script + + +@pytest.fixture +def real_interpreter(monkeypatch): + """Run children with THIS interpreter. + + ``execute_script`` shells out to ``BUILD_PYTHON_INTERPRETER`` ("python3"), + which is resolved via PATH -- and these tests pass a deliberately minimal + env. Pin the absolute interpreter so the subprocess is found regardless. + """ + monkeypatch.setattr(build_util, "BUILD_PYTHON_INTERPRETER", sys.executable) + + +class TestExecuteScriptTimeout: + """End-to-end: a real subprocess killed at the resolved cap.""" + + def test_per_script_env_overrides_the_global_cap(self, tmp_path, monkeypatch, real_interpreter): + # Global cap is generous; the profile tightens it to 1s. If the parent + # ignored the per-script value (the bug), this script would run to + # completion and PASS instead of timing out. + monkeypatch.setattr(build_util, "TIMEOUT_SECS", 600) + script = _write_script(tmp_path, "import time\ntime.sleep(30)\n") + + report = RunReport(project="t", directory="d", run_type="script") + execute_script( + str(script), + report=report, + env={**dict(PATH=os.environ.get("PATH", "")), "BUILD_SCRIPT_TIMEOUT": "1"}, + ) + + assert len(report.results) == 1 + assert report.results[0].status == Status.TIMEOUT + + def test_non_matching_script_keeps_the_global_cap(self, tmp_path, monkeypatch, real_interpreter): + # The mirror of the test above: with no per-script value the generous + # global applies and a quick script simply passes. + monkeypatch.setattr(build_util, "TIMEOUT_SECS", 600) + script = _write_script(tmp_path, "print('done')\n") + + report = RunReport(project="t", directory="d", run_type="script") + execute_script(str(script), report=report, env=dict(PATH=os.environ.get("PATH", ""))) + + assert len(report.results) == 1 + assert report.results[0].status == Status.PASSED + + def test_timeout_message_records_the_cap_in_force(self, tmp_path, monkeypatch, real_interpreter): + # Which cap was enforced must be self-describing in the artefact -- + # otherwise a future TIMEOUT is as ambiguous as the ones that prompted + # this change. + monkeypatch.setattr(build_util, "TIMEOUT_SECS", 600) + script = _write_script(tmp_path, "import time\ntime.sleep(30)\n") + + report = RunReport(project="t", directory="d", run_type="script") + execute_script( + str(script), + report=report, + env={**dict(PATH=os.environ.get("PATH", "")), "BUILD_SCRIPT_TIMEOUT": "1"}, + ) + + assert "cap 1s" in report.results[0].error_message + + def test_timeout_preserves_child_stdout(self, tmp_path, monkeypatch, real_interpreter): + # The whole point: the tail names the block that was running. + monkeypatch.setattr(build_util, "TIMEOUT_SECS", 600) + script = _write_script( + tmp_path, + "import time\nprint('=== variant 3 ===', flush=True)\ntime.sleep(30)\n", + ) + + report = RunReport(project="t", directory="d", run_type="script") + execute_script( + str(script), + report=report, + env={**dict(PATH=os.environ.get("PATH", "")), "BUILD_SCRIPT_TIMEOUT": "2"}, + ) + + message = report.results[0].error_message + assert report.results[0].status == Status.TIMEOUT + assert "=== variant 3 ===" in message