diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index d7efa4e6..ca3295df 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -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] diff --git a/tests/run_suite.py b/tests/run_suite.py new file mode 100644 index 00000000..ad459fd2 --- /dev/null +++ b/tests/run_suite.py @@ -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: `` 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()) diff --git a/tests/test_run_suite.py b/tests/test_run_suite.py new file mode 100644 index 00000000..311ea807 --- /dev/null +++ b/tests/test_run_suite.py @@ -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 -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()