From 2f7cc78e3727059e6eb7925a7fdb941fa3db57e3 Mon Sep 17 00:00:00 2001 From: TMHSDigital <154358121+TMHSDigital@users.noreply.github.com> Date: Sun, 4 Oct 2026 19:59:29 -0400 Subject: [PATCH] fix(testing): bound every smoke run with a timeout and decode output as UTF-8 About 284 sequential Blender runs shared one 75-minute job timeout and no per-run limit, so a single hang (Cycles, xvfb, a stuck handler) ate the whole job, and because the status record was written only after wait(), the summary never named the example that hung. run_example.py now streams through a reader thread and waits with a timeout (--timeout, default $BDT_SMOKE_TIMEOUT or 900 s). On expiry it kills the whole process group (xvfb-run and Blender; taskkill /T on Windows), records FAIL "timeout after Ns", and the catalog moves on. A catalog row may set "timeout" for a legitimately slow example; the catalog lint validates it. The weekly falsifier sweep gets the same bound. Output is now decoded as UTF-8 with replacement. Blender writes UTF-8, and the locale codec (cp1252 on Windows) raised UnicodeDecodeError on bytes such as 0x9D, crashing the runner with Blender still alive. run_catalog also deletes a row's expect_file before running it, so a render left by an earlier local run cannot satisfy the check. Closes #402 Refs #403 Signed-off-by: TMHSDigital <154358121+TMHSDigital@users.noreply.github.com> Co-Authored-By: Claude Opus 5.5 --- tests/check_falsifier_targets.py | 20 ++++-- tests/check_smoke_catalog.py | 5 +- tests/smoke/run_catalog.py | 12 +++- tests/smoke/run_example.py | 120 +++++++++++++++++++++++-------- tests/smoke/test_harness.py | 97 +++++++++++++++++++++++++ 5 files changed, 216 insertions(+), 38 deletions(-) diff --git a/tests/check_falsifier_targets.py b/tests/check_falsifier_targets.py index 5163e631..dd71b0f3 100644 --- a/tests/check_falsifier_targets.py +++ b/tests/check_falsifier_targets.py @@ -219,6 +219,9 @@ def check_static(): return failures, undocumented_only, checked, pieces, undocumented_pieces +RUN_TIMEOUT = 900 # seconds per Blender run, matching tests/smoke/run_example.py + + def check_runtime(blender, only=None): failures, checked = [], 0 for name, readme, script in piece_paths(): @@ -227,11 +230,18 @@ def check_runtime(blender, only=None): falsifiers, _exits = parse_readme(readme) for flag, (want, _target) in sorted(falsifiers.items()): checked += 1 - proc = subprocess.run( - [blender, "--background", "--python-exit-code", "1", "--python", script, "--", flag], - capture_output=True, - ) - got = proc.returncode + try: + proc = subprocess.run( + [blender, "--background", "--python-exit-code", "1", "--python", script, + "--", flag], + capture_output=True, + timeout=RUN_TIMEOUT, + ) + got = proc.returncode + except subprocess.TimeoutExpired: + # subprocess.run kills Blender on expiry; record it and move on so + # one hang cannot stall the weekly sweep. + got = f"timeout after {RUN_TIMEOUT}s" status = "ok" if got == want else "MISMATCH" print(f" {status:9} {name} {flag}: want {want}, got {got}") if got != want: diff --git a/tests/check_smoke_catalog.py b/tests/check_smoke_catalog.py index 47732e4d..3d2671ee 100644 --- a/tests/check_smoke_catalog.py +++ b/tests/check_smoke_catalog.py @@ -29,7 +29,7 @@ EXCLUDED: set[str] = set() ROW_KEYS = {"name", "script", "args", "min_version", "expect_file", - "expect_sidecar", "sidecar_contains", "falsifiers"} + "expect_sidecar", "sidecar_contains", "falsifiers", "timeout"} FALSIFIER_KEYS = {"args", "expect_exit", "expect_sidecar_fail", "min_version"} # 2 is argparse's usage-error exit: an unknown or deleted flag also exits 2, # so a falsifier expecting 2 passes even when its flag no longer exists. @@ -42,6 +42,9 @@ def check_schema(row: dict) -> list[str]: for k in ("name", "script"): if not isinstance(row.get(k), str): errors.append(f"catalog row {name!r}: {k!r} missing or not a string") + t = row.get("timeout") + if t is not None and (isinstance(t, bool) or not isinstance(t, (int, float)) or t <= 0): + errors.append(f"catalog row {name!r}: timeout {t!r} must be a positive number of seconds") fz = row.get("falsifiers") if not isinstance(fz, list) or not fz: errors.append(f"catalog row {name!r} has no falsifiers: nothing proves its " diff --git a/tests/smoke/run_catalog.py b/tests/smoke/run_catalog.py index b3b402e1..703b874c 100644 --- a/tests/smoke/run_catalog.py +++ b/tests/smoke/run_catalog.py @@ -9,6 +9,10 @@ (``expect_exit: N``, or ``expect_sidecar_fail: true`` for a falsifier the post-exit sidecar check catches). A check that can no longer fail turns the job red here instead of passing silently. ``--no-falsifiers`` skips them. + +A row may set ``timeout`` (seconds) for an example that legitimately needs +longer than run_example.py's default; a hung run is killed and reported as a +failure, and the catalog moves on to the next row. """ from __future__ import annotations @@ -68,6 +72,8 @@ def row_cmd(item, run_name, extra, falsifier=None): ]) if item.get("sidecar_contains"): cmd.extend(["--sidecar-contains", item["sidecar_contains"]]) + if item.get("timeout"): + cmd.extend(["--timeout", str(item["timeout"])]) if falsifier is not None: if falsifier.get("expect_sidecar_fail"): cmd.append("--expect-sidecar-fail") @@ -82,6 +88,10 @@ def row_cmd(item, run_name, extra, falsifier=None): n += 1 name = item["name"] base_args = [a.replace("$OUT", args.out) for a in (item.get("args") or [])] + expect = (item.get("expect_file") or "").replace("$OUT", args.out) + if expect and os.path.isfile(expect): + # A render left by an earlier local run must not satisfy this one. + os.remove(expect) print(f"::group::{name}", flush=True) code = subprocess.call(row_cmd(item, name, base_args)) print("::endgroup::", flush=True) @@ -91,9 +101,7 @@ def row_cmd(item, run_name, extra, falsifier=None): if args.fail_fast: break else: - expect = item.get("expect_file") if expect: - expect = expect.replace("$OUT", args.out) if not os.path.isfile(expect) or os.path.getsize(expect) == 0: print(f"ERROR: expected output missing {expect}", file=sys.stderr) failures.append(f"{name} (missing {expect})") diff --git a/tests/smoke/run_example.py b/tests/smoke/run_example.py index 7925fd6d..0a37c790 100644 --- a/tests/smoke/run_example.py +++ b/tests/smoke/run_example.py @@ -4,16 +4,22 @@ python tests/smoke/run_example.py --name NAME --blender BIN --script PATH [--series 5.2] [--min-version 5.0] [--xvfb] [--expect-sidecar FILE] [--sidecar-contains TEXT] - [--forbid-skip] [--status FILE] + [--forbid-skip] [--status FILE] [--timeout SECONDS] -- extra args passed after Blender's `--` + +--timeout (default $BDT_SMOKE_TIMEOUT or 900 s) bounds one Blender run. On +expiry the whole process group (xvfb-run and Blender) is killed and the run is +recorded as FAIL "timeout after Ns", so one hang cannot eat the CI job. """ from __future__ import annotations import argparse import json import os +import signal import subprocess import sys +import threading from datetime import datetime, timezone sys.path.insert(0, os.path.dirname(os.path.abspath(__file__))) @@ -40,6 +46,66 @@ def build_cmd(args): return cmd +DEFAULT_TIMEOUT = 900 + + +def _kill_tree(proc): + """Kill proc and everything it spawned (xvfb-run starts Blender as a child).""" + try: + if os.name == "posix": + os.killpg(proc.pid, signal.SIGKILL) + else: + subprocess.run(["taskkill", "/F", "/T", "/PID", str(proc.pid)], + capture_output=True, check=False) + except (ProcessLookupError, PermissionError, OSError): + pass + try: + proc.kill() + except OSError: + pass + + +def stream(cmd, env=None, timeout=None): + """Run cmd, echo its combined output live, return (exit code or None, output). + + None means the run was killed after `timeout` seconds. Output is decoded as + UTF-8 with replacement: Blender writes UTF-8 whatever the host locale is, + and a strict cp1252 decode would raise mid-run and orphan Blender. + """ + popen_kw = {"start_new_session": True} if os.name == "posix" else { + "creationflags": subprocess.CREATE_NEW_PROCESS_GROUP} + proc = subprocess.Popen( + cmd, + stdout=subprocess.PIPE, + stderr=subprocess.STDOUT, + text=True, + encoding="utf-8", + errors="replace", + env=env, + **popen_kw, + ) + chunks = [] + + def pump(): + assert proc.stdout is not None + for line in proc.stdout: + sys.stdout.write(line) + sys.stdout.flush() + chunks.append(line) + + reader = threading.Thread(target=pump, daemon=True) + reader.start() + try: + proc.wait(timeout=timeout) + code = proc.returncode + except subprocess.TimeoutExpired: + _kill_tree(proc) + proc.wait() + code = None + reader.join(timeout=10) + return code, "".join(chunks) + + def run(args): sidecar = args.expect_sidecar env = os.environ.copy() @@ -55,35 +121,24 @@ def run(args): print(f"=== run_example {args.name} ===", flush=True) print(" ".join(cmd), flush=True) - proc = subprocess.Popen( - cmd, - stdout=subprocess.PIPE, - stderr=subprocess.STDOUT, - text=True, - env=env, - ) - chunks = [] - assert proc.stdout is not None - for line in proc.stdout: - sys.stdout.write(line) - sys.stdout.flush() - chunks.append(line) - proc.wait() - output = "".join(chunks) - proc_exit = proc.returncode if proc.returncode is not None else 1 - - status, detail = classify( - proc_exit=proc_exit, - output=output, - min_version=args.min_version, - blender_version=args.series, - forbid_skip=args.forbid_skip, - expect_sidecar=bool(sidecar), - sidecar_path=sidecar, - sidecar_contains=args.sidecar_contains, - expect_exit=args.expect_exit, - expect_sidecar_fail=args.expect_sidecar_fail, - ) + code, output = stream(cmd, env=env, timeout=args.timeout) + if code is None: + proc_exit = None + status, detail = "FAIL", f"timeout after {args.timeout:g}s (process group killed)" + else: + proc_exit = code + status, detail = classify( + proc_exit=proc_exit, + output=output, + min_version=args.min_version, + blender_version=args.series, + forbid_skip=args.forbid_skip, + expect_sidecar=bool(sidecar), + sidecar_path=sidecar, + sidecar_contains=args.sidecar_contains, + expect_exit=args.expect_exit, + expect_sidecar_fail=args.expect_sidecar_fail, + ) record = { "name": args.name, "status": status, @@ -135,6 +190,11 @@ def main(argv=None): default=os.environ.get("BDT_SMOKE_STATUS"), help="JSONL status file (default $BDT_SMOKE_STATUS)", ) + p.add_argument( + "--timeout", type=float, + default=float(os.environ.get("BDT_SMOKE_TIMEOUT") or DEFAULT_TIMEOUT), + help="seconds before the run is killed and recorded as FAIL", + ) p.add_argument("script_args", nargs=argparse.REMAINDER) args = p.parse_args(argv) if args.script_args and args.script_args[0] == "--": diff --git a/tests/smoke/test_harness.py b/tests/smoke/test_harness.py index a2093d34..49bb84ed 100644 --- a/tests/smoke/test_harness.py +++ b/tests/smoke/test_harness.py @@ -236,6 +236,59 @@ def test_xvfb_keeps_exit_code_flag(self): self.assertIn("--python-exit-code", self._cmd(xvfb=True)) +class Stream(unittest.TestCase): + """run_example.stream: a hung run is killed and reported, output is UTF-8.""" + + def _stream(self, code, timeout=30): + import contextlib + import io + + import run_example + + with contextlib.redirect_stdout(io.StringIO()): + return run_example.stream([sys.executable, "-c", code], timeout=timeout) + + def test_exit_code_is_returned(self): + self.assertEqual(self._stream("import sys; sys.exit(3)")[0], 3) + + def test_hang_is_killed_and_returns_none(self): + import time + + t0 = time.monotonic() + code, out = self._stream( + "import time; print('started', flush=True); time.sleep(120)", timeout=2) + self.assertIsNone(code) + self.assertIn("started", out) + self.assertLess(time.monotonic() - t0, 30) + + @unittest.skipUnless(os.name == "posix", "process groups (xvfb-run case) are POSIX") + def test_hang_kills_grandchild(self): + import time + + with tempfile.TemporaryDirectory() as td: + pidfile = os.path.join(td, "pid") + child = ("import subprocess, sys, time; " + "p = subprocess.Popen([sys.executable, '-c', 'import time; time.sleep(120)']); " + f"open({pidfile!r}, 'w').write(str(p.pid)); time.sleep(120)") + self.assertIsNone(self._stream(child, timeout=2)[0]) + pid = int(open(pidfile).read()) + for _ in range(50): + try: + os.kill(pid, 0) + except ProcessLookupError: + break + time.sleep(0.1) + else: + self.fail("grandchild survived the timeout kill") + + def test_utf8_output_survives_any_locale(self): + # U+201D contains byte 0x9D, which a strict cp1252 decode rejects. + code, out = self._stream( + r"import sys; sys.stdout.buffer.write(b'\xe2\x80\x9d\n'); sys.stdout.flush()") + self.assertEqual(code, 0) + self.assertIn("”", out) + + class RunCatalog(unittest.TestCase): """run_catalog runs every row and reports all failures; empty is red.""" @@ -291,6 +344,50 @@ def test_falsifiers_run_after_each_row(self): self.assertEqual(code, 0) self.assertEqual(seen, ["a", "a [falsifier --break]", "expect 4"]) + def test_row_timeout_is_forwarded(self): + from unittest import mock + + import run_catalog + + got = [] + + def fake_call(cmd): + got.append(cmd[cmd.index("--timeout") + 1] if "--timeout" in cmd else None) + return 0 + + with tempfile.TemporaryDirectory() as td: + cat = os.path.join(td, "catalog.json") + with open(cat, "w", encoding="utf-8") as fh: + json.dump([{"name": "a", "script": "a.py", "timeout": 1800}], fh) + import contextlib + import io + with mock.patch.object(run_catalog.subprocess, "call", fake_call), contextlib.redirect_stdout(io.StringIO()): + run_catalog.main(["--blender", "x", "--series", "5.2", "--out", td, + "--catalog", cat]) + self.assertEqual(got, ["1800"]) + + def test_stale_expect_file_does_not_satisfy_row(self): + import contextlib + import io + from unittest import mock + + import run_catalog + + with tempfile.TemporaryDirectory() as td: + stale = os.path.join(td, "still.png") + with open(stale, "wb") as fh: + fh.write(b"old render") + cat = os.path.join(td, "catalog.json") + with open(cat, "w", encoding="utf-8") as fh: + json.dump([{"name": "a", "script": "a.py", + "expect_file": "$OUT/still.png"}], fh) + err = io.StringIO() + with mock.patch.object(run_catalog.subprocess, "call", lambda cmd: 0), contextlib.redirect_stderr(err), contextlib.redirect_stdout(io.StringIO()): + code = run_catalog.main(["--blender", "x", "--series", "5.2", "--out", td, + "--catalog", cat]) + self.assertEqual(code, 1) + self.assertIn("missing", err.getvalue()) + def test_failing_falsifier_is_red(self): rows = [{"name": "a", "script": "a.py", "falsifiers": [{"args": ["--break"], "expect_exit": 4}]}]