From 386ea1fb74f6dbd66df8c3ae4cb2e2ffd7bc3bf9 Mon Sep 17 00:00:00 2001 From: lmoresi Date: Mon, 24 Aug 2026 08:06:44 +1000 Subject: [PATCH 1/2] Wait for the evidence, not for the clock The end-to-end hang-report test raced a fixed window against machine speed, and failed on CI twice. Both failures were true reports of a slower runner rather than defects: first the waiting group came back short because a rank had not been scheduled enough to dump, then the file filled with `importlib._bootstrap` frames because four oversubscribed ranks took longer to import than the 1 s watchdog allowed. Each time the fix was a bigger number tuned to a workstation, which is not a machine any CI runner resembles. Timing is now out of the test. The script arms its own watchdog AFTER import -- a known point in the program rather than a moment in the schedule -- and writes a marker. The test waits for those markers, then waits for the blocked ranks to have dumped twice, then kills. Import may take as long as it likes. The blocked ranks are blocked until killed, so the wait always completes; the caps are backstops against a broken run, set far above any plausible duration so that reaching one means something is wrong rather than slow. Two things follow. `sorted(biggest_ranks) == [0, 2, 3]` is a legitimate assertion again, because every blocked rank is now waited for by construction instead of hoped for -- the weaker "which rank is blamed" form was a concession to the race. And the test runs in 8.6 s instead of 86, because it kills as soon as the evidence exists rather than sitting out a window. Arming from the script leaves `UW_HANG_WATCHDOG` uncovered, so a separate single-rank test covers it: that entry point is the documented one, and the reason arming happens at import is that a rank which diverges before reaching a `watch()` call reports nothing. 8 passed. Underworld development team with AI support from Claude Code --- tests/test_0054_hang_report.py | 192 ++++++++++++++++++++++++--------- 1 file changed, 139 insertions(+), 53 deletions(-) diff --git a/tests/test_0054_hang_report.py b/tests/test_0054_hang_report.py index 8220e645..dca6c9e6 100644 --- a/tests/test_0054_hang_report.py +++ b/tests/test_0054_hang_report.py @@ -10,11 +10,13 @@ """ import os +import pathlib import shutil import signal import subprocess import sys import textwrap +import time import pytest @@ -154,27 +156,69 @@ def _launcher(ranks): return command -def _run_until_it_hangs(argv, ranks, seconds, environment): - """Launch under MPI, kill the whole job after `seconds`, return stderr. +def _wait_for(condition, what, cap=600.0, poll=0.25): + """Block until `condition()` is true. Returns how long it took. - The job under test is MEANT never to finish, so the time limit is the - normal exit path rather than an error. `start_new_session` puts the ranks in - their own process group so the kill reaches all of them -- terminating only - `mpirun` can leave orphaned ranks holding the dump files open. + The cap is a backstop against a genuinely broken run, not a measurement -- + it is set far above any plausible duration precisely so that reaching it + means something is wrong rather than something is slow. + """ + deadline = time.monotonic() + cap + while time.monotonic() < deadline: + if condition(): + return + time.sleep(poll) + raise AssertionError(f"gave up after {cap:g} s waiting for {what}") + + +def _dump_count(dumps, rank): + """How many times this rank has dumped so far.""" + path = dumps / f"rank{rank:04d}.log" + if not path.exists(): + return 0 + return path.read_text(errors="replace").count("Timeout (") + + +def _run_until_the_evidence_exists(argv, ranks, environment, dumps, ready, + blocked_ranks): + """Launch under MPI, wait for the evidence, then kill the job. + + Nothing here is timed against the clock, and that is the point. Two earlier + versions of this test raced a fixed window against machine speed and failed + on CI twice for reasons that were true reports of a slower runner rather + than defects: first the waiting group came back short because a rank had not + been scheduled enough to dump, then the whole file filled with + `importlib._bootstrap` frames because four oversubscribed ranks took longer + to import than the watchdog allowed. + + So the script signals when it has armed its watchdog -- after import, at a + known program point -- and this waits for that, then waits for the blocked + ranks to have dumped twice, then kills. Import may take as long as it likes. + The blocked ranks are blocked until killed, so the second wait always + completes; only a real failure reaches the cap. """ process = subprocess.Popen( _launcher(ranks) + argv, env=environment, text=True, stdout=subprocess.PIPE, stderr=subprocess.PIPE, start_new_session=True, ) try: - _out, err = process.communicate(timeout=seconds) - except subprocess.TimeoutExpired: + _wait_for(lambda: len(list(ready.glob("ready.*"))) == ranks + or process.poll() is not None, + f"all {ranks} ranks to import and arm the watchdog") + assert process.poll() is None, "the job exited before arming" + + # Two dumps, not one: one says "slow", two says "stuck", and the roll + # call places a rank by the mode of its recent dumps. + _wait_for(lambda: all(_dump_count(dumps, r) >= 2 for r in blocked_ranks), + f"ranks {sorted(blocked_ranks)} to dump twice while blocked") + finally: os.killpg(os.getpgid(process.pid), signal.SIGKILL) _out, err = process.communicate() return err or "" DIVERGENT = """ +import pathlib import time import underworld3 as uw @@ -186,6 +230,17 @@ def reduce_the_count(undecided): '''The un-noticed collective, behind a rank-local guard.''' return uw.mpi.comm.allreduce(len(undecided)) +# Armed HERE, not from the environment: at a known point in the program rather +# than at import, so how long the import took cannot decide what the dumps +# contain. +dumps = pathlib.Path(DUMPS) +dumps.mkdir(parents=True, exist_ok=True) +log = open(dumps / ("rank%04d.log" % uw.mpi.rank), "w", buffering=1) +uw.mpi.watch(seconds=1.0, stream=log) + +# Tell the test the watchdog is live. It waits for this instead of guessing. +(pathlib.Path(READY) / ("ready.%d" % uw.mpi.rank)).write_text("armed") + undecided = classify() if undecided: reduce_the_count(undecided) @@ -194,45 +249,38 @@ def reduce_the_count(undecided): """ -@pytest.mark.timeout(600) +@pytest.mark.timeout(900) @pytest.mark.skipif(shutil.which("mpirun") is None, reason="needs mpirun") def test_end_to_end_names_the_divergent_rank(tmp_path): """A real four-rank job that really hangs, killed, then analysed. - This is the workflow the tool is for: the job does NOT recover, mpirun - times it out, and the dumps are all that is left. An earlier version had - the divergent rank join late so the job exited cleanly, which tested a - situation nobody is ever in and made termination the flaky part. + This is the workflow the tool is for: the job does NOT recover, it is killed, + and the dumps are all that is left. - Ranks 0, 2 and 3 block in the collective; rank 1 branches around it and - sleeps. Both groups dump, so the roll call has to separate them. + Nothing is timed against the clock. The script arms its own watchdog after + import and writes a marker; the test waits for those markers, then waits for + the blocked ranks to have dumped twice, then kills. Two earlier versions + raced a fixed window against machine speed and failed on CI twice — both + times reporting a slower runner rather than a defect. """ - script = tmp_path / "divergent.py" - script.write_text(textwrap.dedent(DIVERGENT)) + ready = tmp_path / "ready" dumps = tmp_path / "uw-hang-dumps" + ready.mkdir() - # The watchdog must be longer than a plausible `import underworld3` and the - # window long enough for the blocked phase to dominate. At 1.0 s / 25 s this - # passed here and failed on CI with the majority located in - # `importlib._bootstrap`: four oversubscribed ranks take longer to import - # than the watchdog allowed, so the file filled with import dumps and the - # job was killed before the collective produced enough to outvote them. - environment = dict( - os.environ, - UW_HANG_WATCHDOG="5.0", - UW_HANG_WATCHDOG_DIR=str(dumps), - UW_NO_USAGE_METRICS="1", + script = tmp_path / "divergent.py" + script.write_text( + f"DUMPS = {str(dumps)!r}\nREADY = {str(ready)!r}\n" + + textwrap.dedent(DIVERGENT) ) - stderr = _run_until_it_hangs( - [sys.executable, "-u", str(script)], ranks=4, seconds=75, - environment=environment, + + stderr = _run_until_the_evidence_exists( + [sys.executable, "-u", str(script)], ranks=4, + environment=dict(os.environ, UW_NO_USAGE_METRICS="1"), + dumps=dumps, ready=ready, blocked_ranks=(0, 2, 3), ) if not dumps.is_dir(): - pytest.fail( - "the job wrote no dumps at all, so it never reached " - f"`import underworld3`:\n{stderr[-2000:]}" - ) + pytest.fail(f"the job wrote no dumps at all:\n{stderr[-2000:]}") states = hang_report.read_directory(dumps) assert len(states) == 4, f"expected four dump files, got {sorted(states)}" @@ -241,29 +289,67 @@ def test_end_to_end_names_the_divergent_rank(tmp_path): biggest_where, biggest_ranks, _stack = groups[0] report = hang_report.format_report(states) - # NOT `biggest_ranks == [0, 2, 3]`. On an oversubscribed runner a rank can - # be scheduled too little to dump inside the window, and requiring all three - # made this fail on CI with the waiting group [0] -- a true report of a - # slower machine, not a defect. What the tool must get right is WHICH RANK - # IS BLAMED, so that is what is asserted. assert biggest_where[2] == "reduce_the_count", ( f"the majority was located at {biggest_where[0]}:{biggest_where[1]} in " - f"{biggest_where[2]}, not at the collective. If that is an import frame " - f"the watchdog fired before the ranks got there.\n{report}" - ) - assert 1 not in biggest_ranks, ( - f"rank 1 branched around the collective and must not be in the waiting " - f"group {biggest_ranks}:\n{report}" + f"{biggest_where[2]}, not at the collective.\n{report}" ) - assert set(biggest_ranks) <= {0, 2, 3} and biggest_ranks, ( - f"the waiting group {biggest_ranks} contains a rank that never entered " - f"the collective:\n{report}" + assert sorted(biggest_ranks) == [0, 2, 3], ( + f"the waiting group was {biggest_ranks}; every blocked rank was waited " + f"for, so all three must be present.\n{report}" ) - odd_ones_out = sorted(r for _w, ranks, _s in groups[1:] for r in ranks) + moving - assert 1 in odd_ones_out, ( - f"rank 1 took the branch and must be named as the odd one out; the " - f"report blamed {odd_ones_out}:\n{report}" + assert odd_ones_out == [1], ( + f"rank 1 took the branch; the report blamed {odd_ones_out}.\n{report}" ) # The verdict has to point at the branch, not merely list stacks. assert "where the bug is" in report + + +ARMED_BY_ENVIRONMENT = """ +import time +import underworld3 as uw +time.sleep(3600) +""" + + +@pytest.mark.timeout(300) +def test_the_environment_variable_arms_the_watchdog_at_import(): + """`UW_HANG_WATCHDOG=...` must arm without the script asking. + + The end-to-end test above arms from the script, deliberately — that is what + makes it independent of how long the import takes. So this covers the other + entry point, which is the documented one and the reason arming happens at + import at all: a rank that diverges or dies before reaching a `watch()` call + reports nothing. + + One rank, no MPI launcher: this is about the environment being read, not + about ranks. + """ + import tempfile + + with tempfile.TemporaryDirectory() as workspace: + root = pathlib.Path(workspace) + script = root / "sleepy.py" + script.write_text(textwrap.dedent(ARMED_BY_ENVIRONMENT)) + dumps = root / "dumps" + + process = subprocess.Popen( + [sys.executable, "-u", str(script)], + env=dict(os.environ, UW_HANG_WATCHDOG="1.0", + UW_HANG_WATCHDOG_DIR=str(dumps), UW_NO_USAGE_METRICS="1"), + stdout=subprocess.PIPE, stderr=subprocess.PIPE, text=True, + start_new_session=True, + ) + try: + _wait_for( + lambda: _dump_count(dumps, 0) >= 2 or process.poll() is not None, + "the environment-armed watchdog to dump twice", + ) + assert process.poll() is None, "the script exited instead of hanging" + assert _dump_count(dumps, 0) >= 2 + assert "sleepy.py" in (dumps / "rank0000.log").read_text(), ( + "the dump did not carry the stack of the script that hung" + ) + finally: + os.killpg(os.getpgid(process.pid), signal.SIGKILL) + process.communicate() From c1a3c16de3e01d3aa2825a79600bf7a58cad6a8d Mon Sep 17 00:00:00 2001 From: lmoresi Date: Mon, 24 Aug 2026 10:54:37 +1000 Subject: [PATCH 2/2] Do not query a fieldsplit the rotated path never set up `_check_velocity_preconditioner` asked `self.snes` for its fieldsplit sub-KSPs. On the rotated free-slip path that KSP is never set up -- that path builds its own -- so PETSc printed a full error banner before the exception could be caught, making a healthy solve look broken. Skipped by path now. Suppressing it with `PETSc.Sys.pushErrorHandler('ignore')` was tried first: it is global state and broke 23 unrelated tests. 29 passed. Underworld development team with AI support from Claude Code --- src/underworld3/systems/solvers.py | 16 +++++++++++++--- 1 file changed, 13 insertions(+), 3 deletions(-) diff --git a/src/underworld3/systems/solvers.py b/src/underworld3/systems/solvers.py index 4c7b6fb4..8043975b 100644 --- a/src/underworld3/systems/solvers.py +++ b/src/underworld3/systems/solvers.py @@ -2225,11 +2225,21 @@ def _check_velocity_preconditioner(self): return # asked for, not fallen back to if getattr(self, "_pc_user_override", False): return # the user owns this block's pc_type + # The rotated free-slip path builds its OWN fieldsplit KSP and leaves + # this one un-set-up, so asking it for sub-KSPs raises -- and PETSc + # prints a full error banner before the exception can be caught, which + # makes a healthy solve look broken. Skip it by the path rather than by + # catching. (Suppressing with pushErrorHandler was tried: it is global + # state and broke 23 unrelated tests.) + if getattr(self, "_rotated_freeslip_bcs", None): + return + pc = self.snes.getKSP().getPC() + if pc.getType() != "fieldsplit": + return try: - velocity = self.snes.getKSP().getPC().getFieldSplitSubKSP()[0] - installed = velocity.getPC().getType() + installed = pc.getFieldSplitSubKSP()[0].getPC().getType() except Exception: - return # no fieldsplit to inspect + return # not set up: nothing to inspect if installed == "mg": return