diff --git a/TESTING.md b/TESTING.md index a34c51ba..6a0fd43a 100644 --- a/TESTING.md +++ b/TESTING.md @@ -212,25 +212,28 @@ need targeted validation. CI and the pre-push hook run the Python suite as `python -m tests.run_suite` (`-v`, `-q`, `-s START` and `-p PATTERN` as in `unittest discover`), and the coverage job as `python -m coverage run -m tests.run_suite`. The runner -(`tests/run_suite.py`) discovers the same tests with the same `sys.path` and exit -codes as `python -m unittest discover -s tests` (5 when no tests ran), and adds a -watchdog: it writes `start: ` to stderr before every test, at every +(`tests/run_suite.py`) discovers the same tests with the same `sys.path` and +warning filters as `python -m unittest discover -s tests`, exits 0, 1, or 5 when +no tests ran (Python 3.12+ behaviour, on every version), and adds a watchdog: it writes `start: ` to stderr before every test, at every verbosity, and arms `faulthandler.dump_traceback_later`. If a test, its teardown, its event-loop shutdown or interpreter exit stops making progress, the stack of every thread goes to stderr (`Timeout (0:02:00)!` then `Thread 0x...` blocks) and the process exits non-zero. - `PM_TEST_HANG_LIMIT` (default 120 s) bounds each test from its `start:` line to - the next one. `PM_TEST_SHUTDOWN_LIMIT` (default 120 s) bounds what follows the - summary: module teardown, non-daemon threads and atexit handlers. Both must be + the next one, including the class and module fixtures (`tearDownClass`, + `setUpModule`, ...) that run in between. `PM_TEST_SHUTDOWN_LIMIT` (default + 120 s) bounds the end of the run: the summary, non-daemon threads, atexit + handlers and coverage's save. Both must be positive integers; anything else stops the runner with exit 2. 120 s stays below asyncio's 300 s wait for default-executor threads on Python 3.12 and 3.13 (3.10 and 3.11 wait without limit), 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. An `ok` after it means - the test passed and the hang is in its teardown or event-loop shutdown (where - `IsolatedAsyncioTestCase` joins executor threads); a dump after the summary is - a hang at interpreter exit. The dump shows thread stacks, not asyncio task + the test body passed and the hang came after it: in its teardown or event-loop + shutdown (where `IsolatedAsyncioTestCase` joins executor threads), or in a + class or module fixture before the next test; the stack shows which. A dump + after the summary is a hang at interpreter exit. The dump shows thread stacks, not asyncio task stacks. - When the watchdog fires under coverage, that run's coverage data is lost; the job fails anyway and the dump is what matters. diff --git a/tests/run_suite.py b/tests/run_suite.py index ad459fd2..14a83f8e 100644 --- a/tests/run_suite.py +++ b/tests/run_suite.py @@ -3,23 +3,28 @@ 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 +``sys.path`` when started with ``-m`` from the repo root, same warning +filters, and the exit codes of Python 3.12+ on every version: 0, 1, and 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 +PM_TEST_SHUTDOWN_LIMIT seconds (default 120) to cover interpreter exit +(non-daemon threads, atexit handlers, coverage's save). It is never +cancelled. Class and module fixtures (setUpClass, tearDownModule, ...) run +between two ``start:`` lines, so they count toward the test before them. +120 s stays below asyncio's 300 s wait for default-executor threads on Python +3.12 and 3.13 (3.10 and 3.11 wait without limit), 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). +"ok" line comes after it, the hang is after the test body: its teardown or +event-loop shutdown, or a class/module fixture before the next test (the +stack shows which). 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"). @@ -48,7 +53,7 @@ def read_limit(name, default): if raw is None: return default text = raw.strip() - if not text.isdigit() or int(text) <= 0: + if not (text.isascii() and text.isdigit()) or int(text) <= 0: raise LimitError(f"run_suite: {name} must be a positive integer, got {raw!r}") return int(text) @@ -61,7 +66,9 @@ def make_result_class(stream, per_test_limit, shutdown_limit): class WatchdogResult(unittest.TextTestResult): def startTest(self, test): - stream.write(f"start: {test.id()}\n") + # At default verbosity the progress dots share a line; start ours. + prefix = "\n" if self.dots else "" + stream.write(f"{prefix}start: {test.id()}\n") stream.flush() super().startTest(test) arm(per_test_limit) @@ -126,6 +133,8 @@ def main(argv=None): runner = unittest.TextTestRunner( stream=stream, verbosity=args.verbosity, + # As unittest.main does: show warnings unless -W/PYTHONWARNINGS set them. + warnings=None if sys.warnoptions else "default", resultclass=make_result_class(stream, per_test_limit, shutdown_limit), ) result = runner.run(suite) diff --git a/tests/test_run_suite.py b/tests/test_run_suite.py index 311ea807..3ae20442 100644 --- a/tests/test_run_suite.py +++ b/tests/test_run_suite.py @@ -20,12 +20,13 @@ SUBPROCESS_TIMEOUT = 60 WATCHDOG_ENV = ("PM_TEST_HANG_LIMIT", "PM_TEST_SHUTDOWN_LIMIT") -def run_suite(folder, extra_env=None, *args): +def run_suite(folder, extra_env=None, *args, verbosity=("-v",)): """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 {}) + command = [sys.executable, "-m", "tests.run_suite", "-s", str(folder)] return subprocess.run( - [sys.executable, "-m", "tests.run_suite", "-s", str(folder), "-v", *args], + [*command, *verbosity, *args], cwd=REPO_ROOT, env=env, capture_output=True, @@ -82,6 +83,43 @@ class RunSuiteTests(unittest.TestCase): self.assertEqual(result.returncode, 0, result.stderr) self.assertIn("start: test_probe_quiet.Probe.test_ok", result.stderr) + def test_start_line_begins_its_own_line_at_default_verbosity(self): + self.write( + "test_probe_dots.py", + """ + import unittest + + class Probe(unittest.TestCase): + def test_a(self): + pass + + def test_b(self): + pass + """, + ) + result = run_suite(self.folder, verbosity=()) + self.assertEqual(result.returncode, 0, result.stderr) + lines = result.stderr.splitlines() + for name in ("test_a", "test_b"): + self.assertIn(f"start: test_probe_dots.Probe.{name}", lines) + + def test_warnings_are_shown_as_with_unittest_discover(self): + self.write( + "test_probe_warn.py", + """ + import unittest + import warnings + + class Probe(unittest.TestCase): + def test_warns(self): + warnings.warn("probe-deprecated", DeprecationWarning) + """, + ) + env = {"PYTHONWARNINGS": ""} + result = run_suite(self.folder, env) + self.assertEqual(result.returncode, 0, result.stderr) + self.assertIn("probe-deprecated", result.stderr) + def test_failing_test_exits_one(self): self.write( "test_probe_fail.py", @@ -206,7 +244,7 @@ class RunSuiteTests(unittest.TestCase): def test_invalid_limit_is_a_usage_error(self): for name in WATCHDOG_ENV: - for value in ("abc", "0", "-3", "1.5"): + for value in ("abc", "0", "-3", "1.5", "\u00b2"): with self.subTest(name=name, value=value): result = run_suite(self.folder, {name: value}) self.assertEqual(result.returncode, 2, result.stderr)