Skip to content

test: stop the faulthandler segfault class in CI (3.11 and 3.12) - #327

Merged
ViperJuice merged 4 commits into
mainfrom
ci/fix-py311-segv
Oct 1, 2026
Merged

ViperJuice merged 4 commits into
mainfrom
ci/fix-py311-segv

Conversation

@ViperJuice

@ViperJuice ViperJuice commented Oct 1, 2026 •

Copy link
Copy Markdown
Collaborator

What failed

Four test (3.x) jobs ended with exit 139 (SIGSEGV), on 3.11 and 3.12:

  • 3.11: 110206935522, 110199067410 and 110194147466
  • 3.12: 110224907585

gh run view --log truncates the step log. The full REST job logs show the same thing in every job. The test was test_version_pin.py::test_the_invalid_pin_text_is_true_with_sources_before_and_after_it. Timeout (0:02:00)! appears, a thread dump starts in yaml/scanner.py and is cut off mid-line, and the job exits with 139. Main's own runs hit the same 120 s dump on 3.10, 3.11 and 3.12 and survived it, with jobs taking up to 24:36 of the 25-minute cap.

Root cause (the class)

faulthandler_timeout = 120 sat below the pytest-timeout kill (700 s). faulthandler's C watchdog dumps every thread without holding the GIL while the main thread keeps running. Any test that was slow but still running and crossed 120 s got its moving frame chain walked from another thread, and that can segfault. The tests from #323 were simply the first to cross 120 s.

They got there for two reasons:

  • The test itself: each test re-parses the 78 KB shipped manifest in pure-Python YAML, 432 times in total.
  • A pre-existing handler leak: pmcp.cli.setup_logging adds two root-logger handlers on every call, and nothing removed them. After tests/test_cli.py there were 90, and every later WARNING fanned out to all of them.

Fix

  1. Put the GIL-free dump above the kill, and make it fail closed (pyproject.toml).
    • timeout = 700 (signal method) is now the first thread dump and the kill. Its handler runs under the GIL, and the failed item cancels the faulthandler timer.
    • faulthandler_timeout = 720 with faulthandler_exit_on_timeout = true is the last resort. It only fires for a thread the kill could not reach, such as one stuck in C or holding the GIL, and then it dumps and exits. So even that hang ends red with a stack, not in the silent 25-minute cancel that tests/runtime: TestRemoteEmitterReachesDispatch (SSE) intermittently hangs in CI until the 25-minute job timeout #200 removed.
    • The 60 s async watchdog is unchanged. It runs in Python under the GIL.
    • The new ladder is 60 s, then 700 s, then 720 s, then 25 min. It is documented in pyproject.toml and tests/runtime/_hang_watchdog.py.
  2. Tests for the ladder (tests/runtime/test_hang_diagnostics.py). These replace the old "zero-risk, run continues" test.
    • A subprocess where a slow test is still running Python: pytest-timeout fails it, faulthandler never fires, and the session continues.
    • A subprocess where SIGALRM is blocked, so the kill cannot land: faulthandler dumps, the process exits non-zero, and the sentinel test never runs.
    • The ini invariant is now 0 < timeout < faulthandler_timeout < 25 min, plus exit-on-timeout and the signal method.
    • Mutation checks: with the old ordering, faulthandler fires on the slow test. With exit-on-timeout turned off, the run "passes" past the wedge. The new tests catch both.
  3. Stop the root-logger leak (tests/conftest.py). A new autouse fixture removes and closes any root-logger handlers a test added, and restores the level. pytest's own capture handlers are left alone.
    • Running test_cli.py, then test_scoped_advisor_audit.py, then the two precedence tests: 90 handlers before and 2 after, and 68.4 s before and 18.5 s after.
    • No test depended on the leaked handlers. The full suite passes, and --- Logging error --- appears 0 times.
  4. Memoise the shipped-manifest parse in the two exhaustive tests (kept from round 1). Each distinct YAML text is parsed for real once. Each caller gets a fresh copy through a pickle round trip, and parse errors are not cached. A merge-order bug in the loader still fails both tests.

This changes no src/ code and no behaviour, so there is no CHANGELOG entry.

Evidence

  • Gates: ruff check src/ tests/ passes, ruff format --check src/ tests/ reports 171 files already formatted, and mypy src/pmcp reports no issues in 52 files.
  • Local run: the full CI command on 3.11.16 under coverage gave 4887 passed and 89.44% coverage, with 0 Timeout (0: lines. It took 11:25, down from 13:33 for round 1.
  • CI on 9401f06: all checks green. From the full REST logs:
job pytest time job time Timeout (0: dumps the two precedence tests
3.10 9:51 10:06 0 0.9 s + 2.5 s
3.11 14:56 15:17 0 1.5 s + 3.9 s
3.12 12:29 12:50 0 1.4 s + 3.1 s

For comparison, main's d5a3cda re-run took 23:49 of pytest time on 3.11, with a 120 s dump on 3.10 and 3.11.

🤖 Generated with Claude Code

https://claude.ai/code/session_01RiabTgWZRfuqiUQ9siEegF

ViperJuice and others added 3 commits October 1, 2026 00:07
…e tests

The two 144/288-case precedence tests added in d5a3cda call load_manifest()
432 times; >99% of each call is pure-Python yaml.safe_load re-parsing the same
78 KB shipped manifest. Under coverage on CPython 3.11 the second test ran past
faulthandler_timeout (120 s) in CI, and the faulthandler dump of the still-
running main thread segfaulted the job (exit 139). Main's own run tripped the
same dump on 3.11 and 3.12 and survived it by luck, finishing 3.11 in 23:29 of
the 25-minute cap.

A test-local fixture memoizes yaml.safe_load by text (deep copy per call, parse
errors never cached), so every overlay is still parsed for real. Locally under
coverage on 3.11.16 the pair drops from 115 s to 4.9 s, and a merge-order
mutant in the loader still fails both tests.

Also corrects the pyproject comment that called faulthandler_timeout
zero-risk.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01RiabTgWZRfuqiUQ9siEegF
On the CI 3.11 runner the deepcopy version still spent 18 s + 50 s in the two
precedence tests: copy.deepcopy is pure Python and, under coverage's tracer,
costs a large share of the parse it replaced. pickle.loads is C. Isolated
under coverage on 3.11.16 the pair goes from 4.1 s to 2.7 s.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01RiabTgWZRfuqiUQ9siEegF
…logger leak

The 120 s faulthandler dump sat BELOW pytest-timeout's 700 s kill, so any
slow-but-running test crossing it got faulthandler's GIL-free walk of a moving
frame chain. That segfaulted four CI jobs (exit 139) on 3.11 and 3.12, and
main's own runs survived the same dump by luck. Re-order the ladder:

- timeout = 700 (signal) is now the first thread dump and the kill. Its
  handler runs under the GIL, and its failure cancels the faulthandler timer.
- faulthandler_timeout = 720 with faulthandler_exit_on_timeout = true is the
  last resort, for a thread the kill could not reach. It dumps and exits, so
  even that hang ends red instead of in the silent 25-minute cancel that
  #200 replaced. Fail closed.

test_hang_diagnostics now proves both directions in subprocesses: a slow
running test is failed by pytest-timeout and faulthandler never fires, and a
wedge with SIGALRM blocked is dumped and ends the run. The ini invariant is
kill < faulthandler < job cap, plus exit-on-timeout. Both proofs fail against
the old ordering and against exit-off.

Also add an autouse conftest fixture that removes and closes the root-logger
handlers a test adds. pmcp.cli.setup_logging adds two on every call, and
test_cli.py left 90 behind, which slowed every later WARNING-heavy test. After
test_cli.py + test_scoped_advisor_audit.py + the two precedence tests: 90 -> 2
handlers, 68.4 s -> 18.5 s. The full 3.11 suite under coverage locally went
from 13:33 to 11:25.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01RiabTgWZRfuqiUQ9siEegF
@ViperJuice ViperJuice changed the title test: stop the 3.11 CI segfault in the exhaustive pin-precedence tests test: stop the faulthandler segfault class in CI (3.11 and 3.12) Oct 1, 2026
… invariant

The 700/720 s timers are per test; the job's timeout-minutes caps the whole
job, so a hang that starts within 720 s of the cap is cancelled before any
dump. 3.11 ran ~15 min; 30 (the workflow guard's maximum) keeps that margin.
The invariant test now reads the test job's real cap from test.yml instead of
restating 25, and the comments stop placing per-test timers and the job cap on
one scale. Review finding N1 on see #327.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01RiabTgWZRfuqiUQ9siEegF
@ViperJuice
ViperJuice merged commit 3f19243 into main Oct 1, 2026
13 checks passed
@ViperJuice
ViperJuice deleted the ci/fix-py311-segv branch October 1, 2026 06:47
ViperJuice added a commit that referenced this pull request Oct 1, 2026
…dler errors described; broken stdio frames never shown (see #297)

Answers the round-9 board on #314 @ a449dd9:
- codex P1 (blocking): at DEBUG the MCP SDK logs each JSON-RPC message
  its transports receive and send, after the envelope is accepted and
  before pmcp validates the payload. install_log_scrubber now makes every
  rendering of an SDK message object (the four JSONRPC classes,
  SessionMessage and its metadata) structural, and the scrubber describes
  dict-shaped messages in log arguments. This takes over the SDK-traffic
  part of #315.
- Found by the new valid-envelope sweep (pre-existing): a request
  handler's escaping validation error reached the caller as pydantic's
  text, and a nameless catalog entry was logged by its content. Both are
  now structural.
- claude N1-r9: the stdio reader stays in "describe" mode after a
  rejected frame (or a frame head behind a banner) until a line parses.
- claude N2-r9: banner shapes now described are listed.

Repro: 12 of 12 scenarios leak on rev 9, 0 of 12 on rev 10. Main moved to
89559db (#325, #327) during the revision;
merged, and the 40 patches are embedded against 89559db and proven
cmp-identical to wip/297-code@6078419. Full suite: 5356 passed. Mutants:
64/64 killed; NO_STATIC 62/64 (M22, M35 by design).

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01RiabTgWZRfuqiUQ9siEegF
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant