Skip to content

Commit 192e1b1

Browse files
TMHSDigitalclaude
andauthored
fix(testing): bound every smoke run with a timeout and decode output as UTF-8 (#416)
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 <noreply@anthropic.com>
1 parent 2cdde2c commit 192e1b1

5 files changed

Lines changed: 216 additions & 38 deletions

File tree

‎tests/check_falsifier_targets.py‎

Lines changed: 15 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -219,6 +219,9 @@ def check_static():
219219
return failures, undocumented_only, checked, pieces, undocumented_pieces
220220

221221

222+
RUN_TIMEOUT = 900 # seconds per Blender run, matching tests/smoke/run_example.py
223+
224+
222225
def check_runtime(blender, only=None):
223226
failures, checked = [], 0
224227
for name, readme, script in piece_paths():
@@ -227,11 +230,18 @@ def check_runtime(blender, only=None):
227230
falsifiers, _exits = parse_readme(readme)
228231
for flag, (want, _target) in sorted(falsifiers.items()):
229232
checked += 1
230-
proc = subprocess.run(
231-
[blender, "--background", "--python-exit-code", "1", "--python", script, "--", flag],
232-
capture_output=True,
233-
)
234-
got = proc.returncode
233+
try:
234+
proc = subprocess.run(
235+
[blender, "--background", "--python-exit-code", "1", "--python", script,
236+
"--", flag],
237+
capture_output=True,
238+
timeout=RUN_TIMEOUT,
239+
)
240+
got = proc.returncode
241+
except subprocess.TimeoutExpired:
242+
# subprocess.run kills Blender on expiry; record it and move on so
243+
# one hang cannot stall the weekly sweep.
244+
got = f"timeout after {RUN_TIMEOUT}s"
235245
status = "ok" if got == want else "MISMATCH"
236246
print(f" {status:9} {name} {flag}: want {want}, got {got}")
237247
if got != want:

‎tests/check_smoke_catalog.py‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,7 @@
2929
EXCLUDED: set[str] = set()
3030

3131
ROW_KEYS = {"name", "script", "args", "min_version", "expect_file",
32-
"expect_sidecar", "sidecar_contains", "falsifiers"}
32+
"expect_sidecar", "sidecar_contains", "falsifiers", "timeout"}
3333
FALSIFIER_KEYS = {"args", "expect_exit", "expect_sidecar_fail", "min_version"}
3434
# 2 is argparse's usage-error exit: an unknown or deleted flag also exits 2,
3535
# so a falsifier expecting 2 passes even when its flag no longer exists.
@@ -42,6 +42,9 @@ def check_schema(row: dict) -> list[str]:
4242
for k in ("name", "script"):
4343
if not isinstance(row.get(k), str):
4444
errors.append(f"catalog row {name!r}: {k!r} missing or not a string")
45+
t = row.get("timeout")
46+
if t is not None and (isinstance(t, bool) or not isinstance(t, (int, float)) or t <= 0):
47+
errors.append(f"catalog row {name!r}: timeout {t!r} must be a positive number of seconds")
4548
fz = row.get("falsifiers")
4649
if not isinstance(fz, list) or not fz:
4750
errors.append(f"catalog row {name!r} has no falsifiers: nothing proves its "

‎tests/smoke/run_catalog.py‎

Lines changed: 10 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,10 @@
99
(``expect_exit: N``, or ``expect_sidecar_fail: true`` for a falsifier the
1010
post-exit sidecar check catches). A check that can no longer fail turns the
1111
job red here instead of passing silently. ``--no-falsifiers`` skips them.
12+
13+
A row may set ``timeout`` (seconds) for an example that legitimately needs
14+
longer than run_example.py's default; a hung run is killed and reported as a
15+
failure, and the catalog moves on to the next row.
1216
"""
1317
from __future__ import annotations
1418

@@ -68,6 +72,8 @@ def row_cmd(item, run_name, extra, falsifier=None):
6872
])
6973
if item.get("sidecar_contains"):
7074
cmd.extend(["--sidecar-contains", item["sidecar_contains"]])
75+
if item.get("timeout"):
76+
cmd.extend(["--timeout", str(item["timeout"])])
7177
if falsifier is not None:
7278
if falsifier.get("expect_sidecar_fail"):
7379
cmd.append("--expect-sidecar-fail")
@@ -82,6 +88,10 @@ def row_cmd(item, run_name, extra, falsifier=None):
8288
n += 1
8389
name = item["name"]
8490
base_args = [a.replace("$OUT", args.out) for a in (item.get("args") or [])]
91+
expect = (item.get("expect_file") or "").replace("$OUT", args.out)
92+
if expect and os.path.isfile(expect):
93+
# A render left by an earlier local run must not satisfy this one.
94+
os.remove(expect)
8595
print(f"::group::{name}", flush=True)
8696
code = subprocess.call(row_cmd(item, name, base_args))
8797
print("::endgroup::", flush=True)
@@ -91,9 +101,7 @@ def row_cmd(item, run_name, extra, falsifier=None):
91101
if args.fail_fast:
92102
break
93103
else:
94-
expect = item.get("expect_file")
95104
if expect:
96-
expect = expect.replace("$OUT", args.out)
97105
if not os.path.isfile(expect) or os.path.getsize(expect) == 0:
98106
print(f"ERROR: expected output missing {expect}", file=sys.stderr)
99107
failures.append(f"{name} (missing {expect})")

‎tests/smoke/run_example.py‎

Lines changed: 90 additions & 30 deletions
Original file line numberDiff line numberDiff line change
@@ -4,16 +4,22 @@
44
python tests/smoke/run_example.py --name NAME --blender BIN --script PATH
55
[--series 5.2] [--min-version 5.0] [--xvfb]
66
[--expect-sidecar FILE] [--sidecar-contains TEXT]
7-
[--forbid-skip] [--status FILE]
7+
[--forbid-skip] [--status FILE] [--timeout SECONDS]
88
-- extra args passed after Blender's `--`
9+
10+
--timeout (default $BDT_SMOKE_TIMEOUT or 900 s) bounds one Blender run. On
11+
expiry the whole process group (xvfb-run and Blender) is killed and the run is
12+
recorded as FAIL "timeout after Ns", so one hang cannot eat the CI job.
913
"""
1014
from __future__ import annotations
1115

1216
import argparse
1317
import json
1418
import os
19+
import signal
1520
import subprocess
1621
import sys
22+
import threading
1723
from datetime import datetime, timezone
1824

1925
sys.path.insert(0, os.path.dirname(os.path.abspath(__file__)))
@@ -40,6 +46,66 @@ def build_cmd(args):
4046
return cmd
4147

4248

49+
DEFAULT_TIMEOUT = 900
50+
51+
52+
def _kill_tree(proc):
53+
"""Kill proc and everything it spawned (xvfb-run starts Blender as a child)."""
54+
try:
55+
if os.name == "posix":
56+
os.killpg(proc.pid, signal.SIGKILL)
57+
else:
58+
subprocess.run(["taskkill", "/F", "/T", "/PID", str(proc.pid)],
59+
capture_output=True, check=False)
60+
except (ProcessLookupError, PermissionError, OSError):
61+
pass
62+
try:
63+
proc.kill()
64+
except OSError:
65+
pass
66+
67+
68+
def stream(cmd, env=None, timeout=None):
69+
"""Run cmd, echo its combined output live, return (exit code or None, output).
70+
71+
None means the run was killed after `timeout` seconds. Output is decoded as
72+
UTF-8 with replacement: Blender writes UTF-8 whatever the host locale is,
73+
and a strict cp1252 decode would raise mid-run and orphan Blender.
74+
"""
75+
popen_kw = {"start_new_session": True} if os.name == "posix" else {
76+
"creationflags": subprocess.CREATE_NEW_PROCESS_GROUP}
77+
proc = subprocess.Popen(
78+
cmd,
79+
stdout=subprocess.PIPE,
80+
stderr=subprocess.STDOUT,
81+
text=True,
82+
encoding="utf-8",
83+
errors="replace",
84+
env=env,
85+
**popen_kw,
86+
)
87+
chunks = []
88+
89+
def pump():
90+
assert proc.stdout is not None
91+
for line in proc.stdout:
92+
sys.stdout.write(line)
93+
sys.stdout.flush()
94+
chunks.append(line)
95+
96+
reader = threading.Thread(target=pump, daemon=True)
97+
reader.start()
98+
try:
99+
proc.wait(timeout=timeout)
100+
code = proc.returncode
101+
except subprocess.TimeoutExpired:
102+
_kill_tree(proc)
103+
proc.wait()
104+
code = None
105+
reader.join(timeout=10)
106+
return code, "".join(chunks)
107+
108+
43109
def run(args):
44110
sidecar = args.expect_sidecar
45111
env = os.environ.copy()
@@ -55,35 +121,24 @@ def run(args):
55121
print(f"=== run_example {args.name} ===", flush=True)
56122
print(" ".join(cmd), flush=True)
57123

58-
proc = subprocess.Popen(
59-
cmd,
60-
stdout=subprocess.PIPE,
61-
stderr=subprocess.STDOUT,
62-
text=True,
63-
env=env,
64-
)
65-
chunks = []
66-
assert proc.stdout is not None
67-
for line in proc.stdout:
68-
sys.stdout.write(line)
69-
sys.stdout.flush()
70-
chunks.append(line)
71-
proc.wait()
72-
output = "".join(chunks)
73-
proc_exit = proc.returncode if proc.returncode is not None else 1
74-
75-
status, detail = classify(
76-
proc_exit=proc_exit,
77-
output=output,
78-
min_version=args.min_version,
79-
blender_version=args.series,
80-
forbid_skip=args.forbid_skip,
81-
expect_sidecar=bool(sidecar),
82-
sidecar_path=sidecar,
83-
sidecar_contains=args.sidecar_contains,
84-
expect_exit=args.expect_exit,
85-
expect_sidecar_fail=args.expect_sidecar_fail,
86-
)
124+
code, output = stream(cmd, env=env, timeout=args.timeout)
125+
if code is None:
126+
proc_exit = None
127+
status, detail = "FAIL", f"timeout after {args.timeout:g}s (process group killed)"
128+
else:
129+
proc_exit = code
130+
status, detail = classify(
131+
proc_exit=proc_exit,
132+
output=output,
133+
min_version=args.min_version,
134+
blender_version=args.series,
135+
forbid_skip=args.forbid_skip,
136+
expect_sidecar=bool(sidecar),
137+
sidecar_path=sidecar,
138+
sidecar_contains=args.sidecar_contains,
139+
expect_exit=args.expect_exit,
140+
expect_sidecar_fail=args.expect_sidecar_fail,
141+
)
87142
record = {
88143
"name": args.name,
89144
"status": status,
@@ -135,6 +190,11 @@ def main(argv=None):
135190
default=os.environ.get("BDT_SMOKE_STATUS"),
136191
help="JSONL status file (default $BDT_SMOKE_STATUS)",
137192
)
193+
p.add_argument(
194+
"--timeout", type=float,
195+
default=float(os.environ.get("BDT_SMOKE_TIMEOUT") or DEFAULT_TIMEOUT),
196+
help="seconds before the run is killed and recorded as FAIL",
197+
)
138198
p.add_argument("script_args", nargs=argparse.REMAINDER)
139199
args = p.parse_args(argv)
140200
if args.script_args and args.script_args[0] == "--":

‎tests/smoke/test_harness.py‎

Lines changed: 97 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -236,6 +236,59 @@ def test_xvfb_keeps_exit_code_flag(self):
236236
self.assertIn("--python-exit-code", self._cmd(xvfb=True))
237237

238238

239+
class Stream(unittest.TestCase):
240+
"""run_example.stream: a hung run is killed and reported, output is UTF-8."""
241+
242+
def _stream(self, code, timeout=30):
243+
import contextlib
244+
import io
245+
246+
import run_example
247+
248+
with contextlib.redirect_stdout(io.StringIO()):
249+
return run_example.stream([sys.executable, "-c", code], timeout=timeout)
250+
251+
def test_exit_code_is_returned(self):
252+
self.assertEqual(self._stream("import sys; sys.exit(3)")[0], 3)
253+
254+
def test_hang_is_killed_and_returns_none(self):
255+
import time
256+
257+
t0 = time.monotonic()
258+
code, out = self._stream(
259+
"import time; print('started', flush=True); time.sleep(120)", timeout=2)
260+
self.assertIsNone(code)
261+
self.assertIn("started", out)
262+
self.assertLess(time.monotonic() - t0, 30)
263+
264+
@unittest.skipUnless(os.name == "posix", "process groups (xvfb-run case) are POSIX")
265+
def test_hang_kills_grandchild(self):
266+
import time
267+
268+
with tempfile.TemporaryDirectory() as td:
269+
pidfile = os.path.join(td, "pid")
270+
child = ("import subprocess, sys, time; "
271+
"p = subprocess.Popen([sys.executable, '-c', 'import time; time.sleep(120)']); "
272+
f"open({pidfile!r}, 'w').write(str(p.pid)); time.sleep(120)")
273+
self.assertIsNone(self._stream(child, timeout=2)[0])
274+
pid = int(open(pidfile).read())
275+
for _ in range(50):
276+
try:
277+
os.kill(pid, 0)
278+
except ProcessLookupError:
279+
break
280+
time.sleep(0.1)
281+
else:
282+
self.fail("grandchild survived the timeout kill")
283+
284+
def test_utf8_output_survives_any_locale(self):
285+
# U+201D contains byte 0x9D, which a strict cp1252 decode rejects.
286+
code, out = self._stream(
287+
r"import sys; sys.stdout.buffer.write(b'\xe2\x80\x9d\n'); sys.stdout.flush()")
288+
self.assertEqual(code, 0)
289+
self.assertIn("”", out)
290+
291+
239292
class RunCatalog(unittest.TestCase):
240293
"""run_catalog runs every row and reports all failures; empty is red."""
241294

@@ -291,6 +344,50 @@ def test_falsifiers_run_after_each_row(self):
291344
self.assertEqual(code, 0)
292345
self.assertEqual(seen, ["a", "a [falsifier --break]", "expect 4"])
293346

347+
def test_row_timeout_is_forwarded(self):
348+
from unittest import mock
349+
350+
import run_catalog
351+
352+
got = []
353+
354+
def fake_call(cmd):
355+
got.append(cmd[cmd.index("--timeout") + 1] if "--timeout" in cmd else None)
356+
return 0
357+
358+
with tempfile.TemporaryDirectory() as td:
359+
cat = os.path.join(td, "catalog.json")
360+
with open(cat, "w", encoding="utf-8") as fh:
361+
json.dump([{"name": "a", "script": "a.py", "timeout": 1800}], fh)
362+
import contextlib
363+
import io
364+
with mock.patch.object(run_catalog.subprocess, "call", fake_call), contextlib.redirect_stdout(io.StringIO()):
365+
run_catalog.main(["--blender", "x", "--series", "5.2", "--out", td,
366+
"--catalog", cat])
367+
self.assertEqual(got, ["1800"])
368+
369+
def test_stale_expect_file_does_not_satisfy_row(self):
370+
import contextlib
371+
import io
372+
from unittest import mock
373+
374+
import run_catalog
375+
376+
with tempfile.TemporaryDirectory() as td:
377+
stale = os.path.join(td, "still.png")
378+
with open(stale, "wb") as fh:
379+
fh.write(b"old render")
380+
cat = os.path.join(td, "catalog.json")
381+
with open(cat, "w", encoding="utf-8") as fh:
382+
json.dump([{"name": "a", "script": "a.py",
383+
"expect_file": "$OUT/still.png"}], fh)
384+
err = io.StringIO()
385+
with mock.patch.object(run_catalog.subprocess, "call", lambda cmd: 0), contextlib.redirect_stderr(err), contextlib.redirect_stdout(io.StringIO()):
386+
code = run_catalog.main(["--blender", "x", "--series", "5.2", "--out", td,
387+
"--catalog", cat])
388+
self.assertEqual(code, 1)
389+
self.assertIn("missing", err.getvalue())
390+
294391
def test_failing_falsifier_is_red(self):
295392
rows = [{"name": "a", "script": "a.py",
296393
"falsifiers": [{"args": ["--break"], "expect_exit": 4}]}]

0 commit comments

Comments
 (0)