[DO NOT MERGE] Probe hang stack dump against a live Kit process - #7153
[DO NOT MERGE] Probe hang stack dump against a live Kit process#7153mataylor-nvidia wants to merge 4 commits into
Conversation
A test that crashes reported a traceback, because PYTHONFAULTHANDLER=1 installs faulthandler for SIGSEGV and friends. A test that hung reported nothing: the runner detects the hang and kills the process group with SIGKILL, which cannot be caught, so no handler ever ran. The report carried system tables and the last -v test name, and nothing that points at the hung code. The runner now asks the process where it is stuck before killing it. tools/hang_dump.py registers SIGUSR1 with faulthandler.register, and capture_test_output_with_timeout signals the process and drains the dump into pre_kill_diag, which already flows into the startup_hang, timeout, and shutdown_hang reports. The dump is taken twice: identical stacks seconds apart are what tell a wedged process from a slow one. SIGTERM and SIGABRT cannot be used for this. AppLauncher binds both to a handler that calls SimulationApp.close(), which is itself what a shutdown hang is stuck inside, so either would re-enter the hang. A Python-level signal handler would not run regardless, since those execute between bytecodes and a thread wedged in a native Kit, CUDA, or renderer call never returns to the interpreter loop. faulthandler.register installs a C-level handler that walks every thread from inside the signal handler, so it reports a process whose GIL will never be released.
The dump never reached CI. pytest captures at the file-descriptor level, so it has already pointed fd 2 at a temporary file of its own by the time the plugin loads; faulthandler.register(file=sys.__stderr__) stored fd 2 and wrote there. That buffer is discarded when the process is SIGKILLed, which is the only case the dump is ever written in, so a hung test still reported nothing but system tables. The dump now goes to a file named by ISAACLAB_HANG_DUMP, which the runner sets per test file and clears per attempt, mirroring the crash journal's ISAACLAB_TEST_JOURNAL. pytest does not redirect it, and the runner reads it after the process is gone. This is the same reason tools/ovrtx_log.py keeps the renderer log in a file. The regression tests missed this because they hung a bare `python script.py` child, which has no capture, so the dump reached stderr and they passed. They now hang a real `python -m pytest` child, reproducing the CI failure: against the previous implementation all three fail on `assert 'HANG STACK DUMP' in ''`. Found by the CI probe in the follow-up branch, which wedged a rendering correctness test and produced a timeout report with no stack.
Blocks test_rendering_cartpole.py forever after its first case has really rendered, so CI exercises the hang stack dump against a live Isaac Sim process rather than the toy subprocess the unit tests use. Kit is fully up and all of its threads are running when SIGUSR1 arrives, which is the part the unit tests cannot cover. Expect the file to be killed for "timeout" and its report to carry a HANG STACK DUMP section naming _probe_wedge. Not for merge.
13f9fad to
774826b
Compare
Run 1 result: the probe worked, and it found a real bugThe wedge landed exactly where intended, and the hang was detected on schedule — but no stack dump was produced:
Root causepytest captures at the file-descriptor level. It The decisive evidence is this probe's own The regression tests in #7152 missed this because they hung a bare Fix#7152 now writes the dump to a file named by Also added the Re-running to confirm the dump appears. Worth notingTwo things did work on run 1: the timeout fired at exactly 1700 s (1000 |
# Description A test that **crashes** reports a traceback, because `PYTHONFAULTHANDLER=1` installs `faulthandler` for `SIGSEGV` and friends. A test that **hangs** reports nothing. Hang *detection* already works — `tools/conftest.py` catches three kinds: | Kind | Trigger | Constant | |---|---|---| | `startup_hang` | no `AppLauncher initialization complete` / `collected ` marker | `STARTUP_DEADLINE = 120` s | | `timeout` | wall clock exceeds the per-file budget | `DEFAULT_TIMEOUT = 1000` s | | `shutdown_hang` | JUnit report written, process still alive | `SHUTDOWN_GRACE_PERIOD = 30` s | The problem is what happens next: all three escalate straight to `os.killpg(pgid, SIGKILL)`. `SIGKILL` cannot be caught, so nothing gets a chance to dump. The report carries `nvidia-smi`, `ps auxf`, `dmesg` and the last `-v` test name — nothing pointing at the hung code. The repo already records the symptom in a skip reason: *"Native hang: the per-file CI runner kills the suite after 1000s with no pytest outcome"* (`source/isaaclab_tasks/test/rendering_test_utils.py`). This complements the crash journal (#7005): that recovers **which tests** had passed when a process died; this reports **where the process is stuck**. ## Change The runner asks the process where it is stuck before killing it. - **`tools/hang_dump.py`** (new) — pytest plugin registering `SIGUSR1` via `faulthandler.register()`, writing to a file named by `ISAACLAB_HANG_DUMP`, which the runner sets per test file and clears per attempt, mirroring the crash journal's `ISAACLAB_TEST_JOURNAL`. No-ops where the signal does not exist. The dump has to go to a **file**, not stderr. pytest captures at the file-descriptor level, so it has already redirected fd 2 by the time the plugin loads; a dump written there is discarded when the process is `SIGKILL`ed — the only case it is ever written in. The first revision of this PR wrote to `sys.__stderr__` and produced no dump in CI at all, which #7153 caught. `tools/ovrtx_log.py` keeps the renderer log in a file for the same reason. - **`conftest.py`** — loads it via `pytest_plugins`, covering every suite. - **`tools/conftest.py`** — `_dump_hung_process_stacks()` signals the process and drains its output before the existing `SIGKILL`, prepending the result to `pre_kill_diag`. The fd-drain block was extracted into `_drain_ready_output()` so the watchdog loop and the dump path share one implementation. `pre_kill_diag` is now also threaded into `_make_missing_report_result`, so a fresh-process retry that hangs reports its stack too. The dump is taken twice — identical stacks seconds apart are what distinguish a wedged process from a slow one. Report plumbing is otherwise unchanged: `pre_kill_diag` already flows into the `startup_hang` and `timeout` reports and the retry warnings, and the drain echoes to stdout/stderr, so the stack also streams live to the job log. Prepending rather than appending matters — `_get_diagnostics` truncates with `diag[:10000]`, so the stack survives and the system tables get trimmed instead. ## Artifact The dump reached CI only through `pre_kill_diag`, which `_get_diagnostics` truncates to 10 000 characters — and a Kit process has enough threads to exceed that, so the part worth reading was the part being cut. The dumps are now written to `tests/hang-dumps/` and collected as a `hang-dumps-<container>` artifact, alongside the existing `comparison-images` and `ovrtx-logs` ones. The reports and the job log still carry the (truncated) dump; the artifact is the whole thing. It is absent unless something hung, which `if-no-files-found: ignore` already covers. ## Why `SIGUSR1` `SIGTERM` and `SIGABRT` are unusable here. `AppLauncher` binds both to `_on_abort_signal`, which calls `SimulationApp.close()` — itself what a shutdown hang is stuck inside — so either would re-enter the hang. Binding `SIGABRT` also displaces `faulthandler`'s own handler. A Python-level `signal` handler would not run regardless: those execute between bytecodes, and a thread wedged in a native Kit, CUDA, or renderer call never returns to the interpreter loop. `isaaclab.cli.multigpu` documents the same constraint when reaping stragglers. `faulthandler.register()` installs a C-level handler that walks every thread from inside the signal handler, so it reports a process whose GIL will never be released. `SIGUSR1` is unused anywhere in `source/`, `tools/`, `scripts/`, `.github/`. ## Sample output Against a process blocked in `threading.Event().wait()`: ``` === HANG STACK DUMP (all threads) === ----- dump 1 of 2 ----- Current thread 0x000073f05cc49080 (most recent call first): File "/usr/lib/python3.12/threading.py", line 355 in wait File "<string>", line 8 in wedged_call ``` ## Type of change - Bug fix (non-breaking change which fixes an issue) ## Release backport - [x] <!-- backport-active-release --> Backport this pull request to the active release branch after it merges into `develop` ## Screenshots Not applicable. ## Checklist - [x] I have run the [`pre-commit` checks](https://pre-commit.com/) with `./isaaclab.sh --format` - [x] I have made corresponding changes to the documentation - [x] My changes generate no new warnings - [x] I have added tests that prove my fix is effective or that my feature works - [x] I have updated the changelog and the corresponding version in the extension's `config/extension.toml` file - [x] I have added my name to the `CONTRIBUTORS.md` or my name already exists there ## Testing One regression test added to `test_test_orchestrator_result_handling.py`, exercising the **real** `capture_test_output_with_timeout` against a genuinely hung child. It asserts every property of the dump — the stack names the hung call, more than one dump is taken, and the stack precedes the system tables — because each is a facet of the same `pre_kill_diag` and each costs a real timeout to reproduce separately. Confirmed it fails without the change on the meaningful assertion (`assert 'HANG STACK DUMP' in ''`), not on a missing constant. It skips on Windows, where the orchestrator's process handling (`select` on pipes, `os.killpg`, `start_new_session`) is unavailable. ### CI cost The three hang tests each waited out a 15 s timeout, costing the Isaac Sim suite about a minute for coverage that needs no GPU. `test_test_orchestrator_result_handling.py` is now listed in `TESTS_TO_SKIP`, so the whole file is out of CI; the skip entry records the command to run it on demand when changing the orchestrator. Note this also takes the file's pre-existing tests (crash-journal blaming, retry semantics, renderer-log bounds, result summary) out of CI. The hang tests are also folded into one, so a local run is not a minute either. The remaining test still has to sit through a real timeout, so that timeout is sized to what the child actually needs: measured ~1.4 s idle and ~2.6 s with eight spawned at once, against a budget of 8 s. Whole file measured at 15 passed, 1 skipped in 2.9 s on Windows. #7153 is a throwaway probe branched off this one, wedging a rendering correctness test so CI exercises the dump against a live Kit process with all its threads running. ## Scope Deliberately excluded: - **No native C++ frames** (no `py-spy`/`gdb`). Python stacks stop at the C boundary, so a Kit shutdown hang reads as `_close_app` → `SimulationApp.close()` without naming the RTX/PhysX call. Still localizes the hang to a test and a call site. - **No change to pass/fail classification** — `passed (shutdown hanged)` stays a pass, so nothing goes red as a side effect. - **Still uncovered:** `docker wait` in `run_tests.sh` has no deadline, so a container hanging *above* pytest is caught only by the 180-minute job timeout.
Description
Do not merge. Throwaway CI probe for #7152, branched off it. Revert by deleting the marked block and the
_probe_wedge()call.What this proves
#7152 adds three regression tests that spawn a genuinely hung child and assert the stack dump appears. Those cover the mechanism, but the child is a toy
pythonprocess with one thread.What they cannot cover is the part that actually matters here: does a real Isaac Sim process answer
SIGUSR1? Kit runs dozens of native threads, installs its own signal handling, and parks the main thread inside C++ calls that never return to the interpreter loop. If Kit blocked or claimedSIGUSR1, the feature would pass CI and still be useless on the hangs it was built for.This probe wedges
test_rendering_cartpole.pyafter its first case has really rendered — so Kit is fully initialized, has produced actual frames, and all its threads are live at the moment the signal arrives.Note the injection is a hang, not a kill. Killing Kit produces a crash, and crashes already printed stacks before #7152 —
PYTHONFAULTHANDLER=1coversSIGSEGV/SIGABRT. The gap being closed is specifically hangs.Expected result
The
rendering-correctnessjob should showtest_rendering_cartpole.pykilled fortimeout, with both the job log and the JUnit report carrying:Two things to check:
_probe_wedgeis named, and the frames below it are the real pytest/Kit call chain — the diagnostic that did not exist before.Thread 0x...blocks. That is the evidencefaulthandler.registerwalks a live Kit process, not just the main thread.The two dumps should be identical, which is the intended "wedged, not slow" signal.
Cost and blast radius
test_rendering_cartpole.pycarries noPER_TEST_TIMEOUTSentry, so it runs onDEFAULT_TIMEOUT(1000 s) plus the 700 s cold-cache buffer it earns as the firstenable_cameras=Truefile — roughly 28 minutes before the dump fires, against the job's 120-minute budget. Left at the defaults deliberately so the probe exercises the real configuration.The orchestrator runs each file in its own process, so only
test_rendering_cartpole.pyis affected; the other six rendering files in the job run normally afterward.test-rendering-correctnessiscontinue-on-erroron pull requests, so a red result here does not block.Before
The same hang on
developproduces:No stack, anywhere. That is the gap #7152 closes.
Type of change
Checklist
pre-commitchecks with./isaaclab.sh --formatconfig/extension.tomlfileCONTRIBUTORS.mdor my name already exists there