test: run the suite through a watchdog that names a hang (#350)
tests/run_suite.py discovers the same tests as unittest discover -s tests, with the same sys.path and exit codes (5 when none ran), writes 'start: <test id>' to stderr before each test and arms faulthandler.dump_traceback_later: 120 s per test (PM_TEST_HANG_LIMIT) and 120 s after the run (PM_TEST_SHUTDOWN_LIMIT), never cancelled. A hang in a test, its teardown, its event-loop shutdown or interpreter exit prints every thread's stack and exits non-zero instead of running to the job limit. The pre-push hook now runs it too.
This commit is contained in:
Vito Sansevero
@@ -22,7 +22,7 @@ repos:
|
||||
|
||||
- id: tests
|
||||
name: tests
|
||||
entry: python -m unittest discover tests/ -v
|
||||
entry: python -m tests.run_suite -q
|
||||
language: system
|
||||
pass_filenames: false
|
||||
stages: [pre-push]
|
||||
|
||||
@@ -0,0 +1,138 @@
|
||||
"""Run the Python suite with a hang watchdog: ``python -m tests.run_suite``.
|
||||
|
||||
Why: on PR #349 a macOS job stopped inside the test suite and sat silent until
|
||||
GitHub cancelled it after six hours, with no stack to read. This runner does
|
||||
the same discovery as ``python -m unittest discover -s tests`` (same
|
||||
``sys.path`` when started with ``-m`` from the repo root, same exit codes,
|
||||
including 5 when no tests ran), and adds a watchdog built on
|
||||
``faulthandler.dump_traceback_later``: when the timer is not re-armed in time,
|
||||
every thread's stack goes to stderr and the process exits non-zero. It works
|
||||
the same on Linux, macOS and Windows.
|
||||
|
||||
The timer is armed before discovery, re-armed at the start of every test with
|
||||
PM_TEST_HANG_LIMIT seconds (default 120), and re-armed when the run ends with
|
||||
PM_TEST_SHUTDOWN_LIMIT seconds (default 120) to cover module teardown and
|
||||
interpreter exit. It is never cancelled. 120 s stays below asyncio's 300 s
|
||||
wait for default-executor threads on Python 3.12 and 3.13, so a hang in an
|
||||
``IsolatedAsyncioTestCase`` loop shutdown is dumped inside the test that hung.
|
||||
|
||||
Reading a dump: the last ``start: <test id>`` line names the test. If its
|
||||
"ok" line comes after it, the hang is in that test's teardown or event-loop
|
||||
shutdown; a dump after the summary is a hang at interpreter exit (a
|
||||
non-daemon thread or an atexit handler).
|
||||
|
||||
A limit is a measurement, not a dial: change it only with new measurements
|
||||
written next to it (TESTING.md "Time limits and hangs").
|
||||
"""
|
||||
|
||||
import argparse
|
||||
import faulthandler
|
||||
import os
|
||||
import sys
|
||||
import unittest
|
||||
from pathlib import Path
|
||||
|
||||
DEFAULT_PER_TEST_LIMIT = 120
|
||||
DEFAULT_SHUTDOWN_LIMIT = 120
|
||||
NO_TESTS_EXIT = 5
|
||||
USAGE_EXIT = 2
|
||||
|
||||
|
||||
class LimitError(ValueError):
|
||||
"""An environment limit is not a positive integer."""
|
||||
|
||||
|
||||
def read_limit(name, default):
|
||||
"""Return the positive integer in env var ``name``, or ``default``."""
|
||||
raw = os.environ.get(name)
|
||||
if raw is None:
|
||||
return default
|
||||
text = raw.strip()
|
||||
if not text.isdigit() or int(text) <= 0:
|
||||
raise LimitError(f"run_suite: {name} must be a positive integer, got {raw!r}")
|
||||
return int(text)
|
||||
|
||||
|
||||
def make_result_class(stream, per_test_limit, shutdown_limit):
|
||||
"""Build a TextTestResult that names each test and re-arms the watchdog."""
|
||||
|
||||
def arm(seconds):
|
||||
faulthandler.dump_traceback_later(seconds, exit=True, file=stream)
|
||||
|
||||
class WatchdogResult(unittest.TextTestResult):
|
||||
def startTest(self, test):
|
||||
stream.write(f"start: {test.id()}\n")
|
||||
stream.flush()
|
||||
super().startTest(test)
|
||||
arm(per_test_limit)
|
||||
|
||||
def stopTestRun(self):
|
||||
super().stopTestRun()
|
||||
arm(shutdown_limit)
|
||||
|
||||
return WatchdogResult
|
||||
|
||||
|
||||
def parse_args(argv):
|
||||
parser = argparse.ArgumentParser(
|
||||
prog="python -m tests.run_suite",
|
||||
description="Discover and run the tests with a hang watchdog.",
|
||||
)
|
||||
# As in unittest, -v and -q share one setting and the last one wins.
|
||||
parser.set_defaults(verbosity=1)
|
||||
parser.add_argument(
|
||||
"-v",
|
||||
"--verbose",
|
||||
dest="verbosity",
|
||||
action="store_const",
|
||||
const=2,
|
||||
help="verbose output",
|
||||
)
|
||||
parser.add_argument(
|
||||
"-q",
|
||||
"--quiet",
|
||||
dest="verbosity",
|
||||
action="store_const",
|
||||
const=0,
|
||||
help="quiet output",
|
||||
)
|
||||
parser.add_argument(
|
||||
"-s",
|
||||
"--start-directory",
|
||||
default=str(Path(__file__).resolve().parent),
|
||||
help="directory to start discovery (default: this tests folder)",
|
||||
)
|
||||
parser.add_argument(
|
||||
"-p", "--pattern", default="test*.py", help="pattern to match test files"
|
||||
)
|
||||
return parser.parse_args(argv)
|
||||
|
||||
|
||||
def main(argv=None):
|
||||
args = parse_args(sys.argv[1:] if argv is None else argv)
|
||||
# Keep the real stderr: a test may replace sys.stderr, and the watchdog
|
||||
# needs a stream with a file descriptor.
|
||||
stream = sys.stderr
|
||||
try:
|
||||
per_test_limit = read_limit("PM_TEST_HANG_LIMIT", DEFAULT_PER_TEST_LIMIT)
|
||||
shutdown_limit = read_limit("PM_TEST_SHUTDOWN_LIMIT", DEFAULT_SHUTDOWN_LIMIT)
|
||||
except LimitError as error:
|
||||
stream.write(f"{error}\n")
|
||||
return USAGE_EXIT
|
||||
|
||||
faulthandler.dump_traceback_later(per_test_limit, exit=True, file=stream)
|
||||
start = os.path.abspath(args.start_directory)
|
||||
suite = unittest.TestLoader().discover(start, args.pattern, top_level_dir=start)
|
||||
runner = unittest.TextTestRunner(
|
||||
stream=stream,
|
||||
verbosity=args.verbosity,
|
||||
resultclass=make_result_class(stream, per_test_limit, shutdown_limit),
|
||||
)
|
||||
result = runner.run(suite)
|
||||
if result.testsRun == 0 and not result.skipped:
|
||||
return NO_TESTS_EXIT
|
||||
return 0 if result.wasSuccessful() else 1
|
||||
|
||||
|
||||
if __name__ == "__main__":
|
||||
sys.exit(main())
|
||||
@@ -0,0 +1,220 @@
|
||||
"""Tests for tests/run_suite.py, the CI test runner and its hang watchdog (#350).
|
||||
|
||||
Each test writes a temporary folder of tiny test modules and runs
|
||||
``python -m tests.run_suite -s <folder> -v`` in a subprocess from the repo
|
||||
root. Every subprocess call has a timeout, so a broken watchdog fails this
|
||||
file instead of hanging the suite. Probes that should hang wait a bounded
|
||||
time, so a watchdog that never fires shows up as a plain assertion failure.
|
||||
"""
|
||||
|
||||
import os
|
||||
import subprocess
|
||||
import sys
|
||||
import tempfile
|
||||
import textwrap
|
||||
import unittest
|
||||
from pathlib import Path
|
||||
|
||||
REPO_ROOT = Path(__file__).resolve().parent.parent
|
||||
SUBPROCESS_TIMEOUT = 60
|
||||
WATCHDOG_ENV = ("PM_TEST_HANG_LIMIT", "PM_TEST_SHUTDOWN_LIMIT")
|
||||
|
||||
|
||||
def run_suite(folder, extra_env=None, *args):
|
||||
"""Run the runner on ``folder`` and return the completed process."""
|
||||
env = {k: v for k, v in os.environ.items() if k not in WATCHDOG_ENV}
|
||||
env.update(extra_env or {})
|
||||
return subprocess.run(
|
||||
[sys.executable, "-m", "tests.run_suite", "-s", str(folder), "-v", *args],
|
||||
cwd=REPO_ROOT,
|
||||
env=env,
|
||||
capture_output=True,
|
||||
text=True,
|
||||
encoding="utf-8",
|
||||
errors="replace",
|
||||
timeout=SUBPROCESS_TIMEOUT,
|
||||
)
|
||||
|
||||
|
||||
class RunSuiteTests(unittest.TestCase):
|
||||
def setUp(self):
|
||||
self._tmp = tempfile.TemporaryDirectory(prefix="pm-run-suite-")
|
||||
self.addCleanup(self._tmp.cleanup)
|
||||
self.folder = Path(self._tmp.name)
|
||||
|
||||
def write(self, name, source):
|
||||
(self.folder / name).write_text(textwrap.dedent(source), encoding="utf-8")
|
||||
|
||||
def assertDumped(self, result, test_id):
|
||||
detail = result.stderr[-4000:]
|
||||
self.assertNotEqual(result.returncode, 0, detail)
|
||||
self.assertIn(f"start: {test_id}", result.stderr, detail)
|
||||
self.assertIn("Timeout (", result.stderr, detail)
|
||||
self.assertIn("Thread 0x", result.stderr, detail)
|
||||
|
||||
def test_passing_test_exits_zero_and_names_each_start(self):
|
||||
self.write(
|
||||
"test_probe_pass.py",
|
||||
"""
|
||||
import unittest
|
||||
|
||||
class Probe(unittest.TestCase):
|
||||
def test_ok(self):
|
||||
pass
|
||||
""",
|
||||
)
|
||||
result = run_suite(self.folder)
|
||||
self.assertEqual(result.returncode, 0, result.stderr)
|
||||
self.assertIn("start: test_probe_pass.Probe.test_ok", result.stderr)
|
||||
|
||||
def test_start_line_is_written_at_quiet_verbosity_too(self):
|
||||
self.write(
|
||||
"test_probe_quiet.py",
|
||||
"""
|
||||
import unittest
|
||||
|
||||
class Probe(unittest.TestCase):
|
||||
def test_ok(self):
|
||||
pass
|
||||
""",
|
||||
)
|
||||
result = run_suite(self.folder, None, "-q")
|
||||
self.assertEqual(result.returncode, 0, result.stderr)
|
||||
self.assertIn("start: test_probe_quiet.Probe.test_ok", result.stderr)
|
||||
|
||||
def test_failing_test_exits_one(self):
|
||||
self.write(
|
||||
"test_probe_fail.py",
|
||||
"""
|
||||
import unittest
|
||||
|
||||
class Probe(unittest.TestCase):
|
||||
def test_fails(self):
|
||||
self.fail("expected")
|
||||
""",
|
||||
)
|
||||
result = run_suite(self.folder)
|
||||
self.assertEqual(result.returncode, 1, result.stderr)
|
||||
|
||||
def test_pattern_option_selects_modules(self):
|
||||
self.write(
|
||||
"check_probe.py",
|
||||
"""
|
||||
import unittest
|
||||
|
||||
class Probe(unittest.TestCase):
|
||||
def test_fails(self):
|
||||
self.fail("selected by -p")
|
||||
""",
|
||||
)
|
||||
self.assertEqual(run_suite(self.folder).returncode, 5)
|
||||
result = run_suite(self.folder, None, "-p", "check_*.py")
|
||||
self.assertEqual(result.returncode, 1, result.stderr)
|
||||
|
||||
def test_empty_folder_exits_five(self):
|
||||
result = run_suite(self.folder)
|
||||
self.assertEqual(result.returncode, 5, result.stderr)
|
||||
|
||||
def test_repo_root_modules_import_as_with_unittest_discover(self):
|
||||
self.write(
|
||||
"test_probe_import.py",
|
||||
"""
|
||||
import unittest
|
||||
|
||||
from utils.hashing import generate_prompt_hash
|
||||
|
||||
class Probe(unittest.TestCase):
|
||||
def test_import(self):
|
||||
same = generate_prompt_hash(" A ") == generate_prompt_hash("a")
|
||||
self.assertTrue(same)
|
||||
""",
|
||||
)
|
||||
result = run_suite(self.folder)
|
||||
self.assertEqual(result.returncode, 0, result.stderr)
|
||||
|
||||
def test_hung_test_dumps_every_thread_and_exits(self):
|
||||
self.write(
|
||||
"test_probe_hang.py",
|
||||
"""
|
||||
import time
|
||||
import unittest
|
||||
|
||||
class Probe(unittest.TestCase):
|
||||
def test_hangs(self):
|
||||
time.sleep(30)
|
||||
""",
|
||||
)
|
||||
result = run_suite(self.folder, {"PM_TEST_HANG_LIMIT": "2"})
|
||||
self.assertDumped(result, "test_probe_hang.Probe.test_hangs")
|
||||
|
||||
def test_hang_in_async_teardown_dumps_and_exits(self):
|
||||
self.write(
|
||||
"test_probe_teardown.py",
|
||||
"""
|
||||
import threading
|
||||
import unittest
|
||||
|
||||
class Probe(unittest.IsolatedAsyncioTestCase):
|
||||
async def asyncTearDown(self):
|
||||
threading.Event().wait(30)
|
||||
|
||||
async def test_body_passes(self):
|
||||
pass
|
||||
""",
|
||||
)
|
||||
result = run_suite(self.folder, {"PM_TEST_HANG_LIMIT": "2"})
|
||||
self.assertDumped(result, "test_probe_teardown.Probe.test_body_passes")
|
||||
|
||||
def test_hang_in_event_loop_shutdown_after_ok_dumps_and_exits(self):
|
||||
# The #349 shape: the test passes ("ok" is printed), then the loop's
|
||||
# shutdown waits for a default-executor thread that never finishes.
|
||||
self.write(
|
||||
"test_probe_loop.py",
|
||||
"""
|
||||
import asyncio
|
||||
import threading
|
||||
import unittest
|
||||
|
||||
class Probe(unittest.IsolatedAsyncioTestCase):
|
||||
async def test_leaves_executor_busy(self):
|
||||
loop = asyncio.get_running_loop()
|
||||
loop.run_in_executor(None, threading.Event().wait, 30)
|
||||
""",
|
||||
)
|
||||
result = run_suite(self.folder, {"PM_TEST_HANG_LIMIT": "2"})
|
||||
self.assertDumped(result, "test_probe_loop.Probe.test_leaves_executor_busy")
|
||||
start = result.stderr.index("start: test_probe_loop")
|
||||
self.assertIn("ok", result.stderr[start:], result.stderr[-4000:])
|
||||
|
||||
def test_hang_at_interpreter_exit_dumps_and_exits(self):
|
||||
self.write(
|
||||
"test_probe_exit.py",
|
||||
"""
|
||||
import threading
|
||||
import unittest
|
||||
|
||||
class Probe(unittest.TestCase):
|
||||
def test_leaves_thread(self):
|
||||
threading.Thread(target=threading.Event().wait, args=(30,)).start()
|
||||
""",
|
||||
)
|
||||
result = run_suite(self.folder, {"PM_TEST_SHUTDOWN_LIMIT": "2"})
|
||||
detail = result.stderr[-4000:]
|
||||
self.assertNotEqual(result.returncode, 0, detail)
|
||||
self.assertIn("ok", result.stderr, detail)
|
||||
self.assertIn("Timeout (", result.stderr, detail)
|
||||
|
||||
def test_invalid_limit_is_a_usage_error(self):
|
||||
for name in WATCHDOG_ENV:
|
||||
for value in ("abc", "0", "-3", "1.5"):
|
||||
with self.subTest(name=name, value=value):
|
||||
result = run_suite(self.folder, {name: value})
|
||||
self.assertEqual(result.returncode, 2, result.stderr)
|
||||
lines = result.stderr.strip().splitlines()
|
||||
self.assertEqual(len(lines), 1, result.stderr)
|
||||
self.assertIn(name, lines[0])
|
||||
self.assertIn(repr(value), lines[0])
|
||||
|
||||
|
||||
if __name__ == "__main__":
|
||||
unittest.main()
|
||||
Reference in New Issue
Block a user