Skip to content

Fix #1014: faulthandler_timeout + step timeout so a hung pytest leg names its test - #1022

Merged
fdaviddpt merged 6 commits into
mainfrom
fix-1014-ci-hang-log
Oct 11, 2026
Merged

fdaviddpt merged 6 commits into
mainfrom
fix-1014-ci-hang-log

Conversation

@fdaviddpt

@fdaviddpt fdaviddpt commented Oct 11, 2026 •

Copy link
Copy Markdown
Contributor

Closes #1014.

A Windows pytest leg was cancelled twice by the job-level timeout-minutes: 30 (PR #1013 job 114288023016, PR #1020 job 114358206393). A job cancelled
by its own timeout writes no log at all, so we could not tell which
test hung, or whether it was the runner or our code -- and this suite runs
real wscript.exe tests (#1002) that have already hung 40+ minutes once.

What changed

  • pyproject.toml: faulthandler_timeout = 900 under
    [tool.pytest.ini_options] (built into pytest, no new dependency). Dumps
    every thread's traceback, naming the hung test, once any single test
    runs longer than 900s. Sized with ~30x margin over the slowest single
    test observed on a recent green windows-latest run (30.14s, run
    38091996750, job 114330142530), and below the new step timeout so the
    dump lands in a kept log.
  • .github/workflows/tests.yml: a step-level timeout-minutes: 25 on both
    "Run tests" and "Run the full suite against the compiled hooks" -- below
    the job's 30-minute one, so a hang fails the step and the job still
    completes with its log (including the faulthandler dump), instead of
    being cancelled with no log at all. Output is tee'd to a file uploaded
    as an artifact under if: always(), and a trailing Windows-only step
    lists any surviving wscript.exe/bash.exe/conhost.exe/
    powershell.exe processes with PID/PPID/command line.

What is proven, and what is not

Proven (Linux): this PR's own round-2 proof -- a deliberately hanging
test, with faulthandler_timeout temporarily lowered and the step timeout
left in place -- was run on CI (run 38122057767, job 114445674357). The
faulthandler traceback naming the stuck test is present in the kept
log
, followed by ##[error]The action 'Run tests' has timed out after 25 minutes.. That shows the step's own timeout-minutes is what keeps
the log -- pytest itself was not observed to exit before the step timeout
fired.

Not proven: faulthandler_exit_on_timeout (which would make pytest
_exit the process itself, well inside the 900s bound) was tried in an
earlier round-2 commit on this branch and then removed, because the proof
above gave no evidence it does anything before the step timeout already
ends the step -- it was never shown to fire first. And Windows was not
exercised by this proof at all
-- only a Linux leg ran the deliberate
hang. The original failure mode #1014 was filed for (a Windows job ending
cancelled with no log, run 38122057767, job 114418645594: ~33.6 min past
the step's own 25-minute timeout) is therefore not shown fixed by this
PR. Filed as #1032 to track closing that gap with a Windows-side proof.

Earlier, separately-captured evidence that faulthandler_timeout itself
(the dump mechanism, not the step-timeout-keeps-the-log mechanism) fires on
both OSes: run 38103924282, a throwaway 8s-sleep test with
faulthandler_timeout = 5, produced the traceback on both
pytest (windows-latest, 3.10) job 114365322297 and
pytest (ubuntu-latest, 3.10) job 114365322191. That proof only showed the
dump firing, not that the step then ends the job with the log kept on
Windows under a genuine hang -- which is exactly the part #1032 tracks.

Compatibility checked

  • --cov: faulthandler_timeout is independent of coverage collection;
    no interaction observed locally or in the proof runs (all ran with
    --cov active).
  • pytest-xdist: a repo-wide grep found no xdist usage anywhere in this
    repo. faulthandler_timeout is a per-worker/per-process setting, so it
    would still work if xdist is added later.

Changelog

A changelog.d/1014.fixed.md fragment was added, since this does change
CI behavior observable to anyone whose pytest leg hangs (a log now exists
where none did before). The PR still carries the no-changelog label from
an earlier pass that judged this CI-only and therefore invisible to
end-users of the software; the maintainer may want to remove that label to
match the fragment, or drop the fragment to match the label -- noted here
rather than decided unilaterally.

CI

19/19 checks green on the finalizing commit (one round; no rerun needed).

[AI-generated]

@fdaviddpt fdaviddpt added the no-changelog Change is invisible to users label Oct 11, 2026
fdaviddpt added a commit that referenced this pull request Oct 11, 2026
…ames its test

A Windows pytest leg was cancelled twice by the job-level timeout-minutes:
30 (PR #1013 job 114288023016, PR #1020 job 114358206393), and a job
cancelled by its own timeout writes NO log at all, so we could not tell
which test hung or whether it was the runner or our code (#1002's real
wscript.exe tests have already hung 40+ minutes once).

- pyproject.toml: faulthandler_timeout = 900 under [tool.pytest.ini_options]
  (built into pytest, no new dependency). Dumps every thread's traceback,
  naming the hung test, once any single test runs longer than 900s. Sized
  with ~30x margin over the slowest single test observed on a recent green
  windows-latest run (30.14s, run 38091996750 job 114330142530), and below
  the new step timeout so the dump lands in a kept log.
- .github/workflows/tests.yml: a step-level timeout-minutes: 25 on both
  "Run tests" and "Run the full suite against the compiled hooks" -- below
  the job's 30-minute one, so a hang fails the STEP and the job still
  completes with its log (including the faulthandler dump) rather than
  being cancelled with no log at all.
- A trailing, Windows-only, if: always() step on both jobs that lists any
  surviving wscript.exe/bash.exe/conhost.exe/powershell.exe processes with
  PID/PPID/command line, so a leaked child is visible. Not hypothetical:
  the same green run above still had to force-terminate a leaked bash and
  a leaked wscript process at job teardown.

PROVEN on PR #1022 (same branch, run 38103924282, before this commit): a
temporary faulthandler_timeout=5 plus a throwaway test sleeping 8s produced
a log on BOTH a Windows leg (pytest (windows-latest, 3.10), job
114365322297, lines 703-708: "Timeout (0:00:05)!" naming
tests/test_proof_1014_faulthandler.py::test_proof_sleep_past_faulthandler_timeout
with its full traceback) and a Linux leg (pytest (ubuntu-latest, 3.10), job
114365322191, lines 1072-1079: same dump, same test). The throwaway test
and the lowered value are removed/restored in this commit; the real values
above are what ships.

No user-visible behavior changes -- CI-only -- so no changelog fragment;
PR labeled no-changelog instead.

faulthandler_timeout is independent of --cov (coverage collection is
unaffected) and of pytest-xdist (confirmed via repo-wide grep: this repo
has no xdist configured, and the setting is per-worker/per-process either
way if that changes).

Co-Authored-By: Max <noreply>
@fdaviddpt fdaviddpt changed the title WIP #1014: CI hang evidence -- faulthandler_timeout proof run Fix #1014: faulthandler_timeout + step timeout so a hung pytest leg names its test Oct 11, 2026
@fdaviddpt
fdaviddpt marked this pull request as ready for review October 11, 2026 07:39
@fdaviddpt
fdaviddpt force-pushed the fix-1014-ci-hang-log branch from 41c4d47 to 7991bec Compare October 11, 2026 10:13
fdaviddpt added a commit that referenced this pull request Oct 11, 2026
…ames its test

A Windows pytest leg was cancelled twice by the job-level timeout-minutes:
30 (PR #1013 job 114288023016, PR #1020 job 114358206393), and a job
cancelled by its own timeout writes NO log at all, so we could not tell
which test hung or whether it was the runner or our code (#1002's real
wscript.exe tests have already hung 40+ minutes once).

- pyproject.toml: faulthandler_timeout = 900 under [tool.pytest.ini_options]
  (built into pytest, no new dependency). Dumps every thread's traceback,
  naming the hung test, once any single test runs longer than 900s. Sized
  with ~30x margin over the slowest single test observed on a recent green
  windows-latest run (30.14s, run 38091996750 job 114330142530), and below
  the new step timeout so the dump lands in a kept log.
- .github/workflows/tests.yml: a step-level timeout-minutes: 25 on both
  "Run tests" and "Run the full suite against the compiled hooks" -- below
  the job's 30-minute one, so a hang fails the STEP and the job still
  completes with its log (including the faulthandler dump) rather than
  being cancelled with no log at all.
- A trailing, Windows-only, if: always() step on both jobs that lists any
  surviving wscript.exe/bash.exe/conhost.exe/powershell.exe processes with
  PID/PPID/command line, so a leaked child is visible. Not hypothetical:
  the same green run above still had to force-terminate a leaked bash and
  a leaked wscript process at job teardown.

PROVEN on PR #1022 (same branch, run 38103924282, before this commit): a
temporary faulthandler_timeout=5 plus a throwaway test sleeping 8s produced
a log on BOTH a Windows leg (pytest (windows-latest, 3.10), job
114365322297, lines 703-708: "Timeout (0:00:05)!" naming
tests/test_proof_1014_faulthandler.py::test_proof_sleep_past_faulthandler_timeout
with its full traceback) and a Linux leg (pytest (ubuntu-latest, 3.10), job
114365322191, lines 1072-1079: same dump, same test). The throwaway test
and the lowered value are removed/restored in this commit; the real values
above are what ships.

No user-visible behavior changes -- CI-only -- so no changelog fragment;
PR labeled no-changelog instead.

faulthandler_timeout is independent of --cov (coverage collection is
unaffected) and of pytest-xdist (confirmed via repo-wide grep: this repo
has no xdist configured, and the setting is per-worker/per-process either
way if that changes).

Co-Authored-By: Max <noreply>
fdaviddpt and others added 6 commits October 11, 2026 22:57
…dump fires

Temporary commit to capture CI evidence that pytest's faulthandler_timeout
names a hung test and dumps its traceback. Will be removed before the
final PR: this lowers faulthandler_timeout to 5s and adds a throwaway
test that sleeps 8s so the dump fires on a real CI run (windows + linux).

Co-Authored-By: Max <noreply>
…ames its test

A Windows pytest leg was cancelled twice by the job-level timeout-minutes:
30 (PR #1013 job 114288023016, PR #1020 job 114358206393), and a job
cancelled by its own timeout writes NO log at all, so we could not tell
which test hung or whether it was the runner or our code (#1002's real
wscript.exe tests have already hung 40+ minutes once).

- pyproject.toml: faulthandler_timeout = 900 under [tool.pytest.ini_options]
  (built into pytest, no new dependency). Dumps every thread's traceback,
  naming the hung test, once any single test runs longer than 900s. Sized
  with ~30x margin over the slowest single test observed on a recent green
  windows-latest run (30.14s, run 38091996750 job 114330142530), and below
  the new step timeout so the dump lands in a kept log.
- .github/workflows/tests.yml: a step-level timeout-minutes: 25 on both
  "Run tests" and "Run the full suite against the compiled hooks" -- below
  the job's 30-minute one, so a hang fails the STEP and the job still
  completes with its log (including the faulthandler dump) rather than
  being cancelled with no log at all.
- A trailing, Windows-only, if: always() step on both jobs that lists any
  surviving wscript.exe/bash.exe/conhost.exe/powershell.exe processes with
  PID/PPID/command line, so a leaked child is visible. Not hypothetical:
  the same green run above still had to force-terminate a leaked bash and
  a leaked wscript process at job teardown.

PROVEN on PR #1022 (same branch, run 38103924282, before this commit): a
temporary faulthandler_timeout=5 plus a throwaway test sleeping 8s produced
a log on BOTH a Windows leg (pytest (windows-latest, 3.10), job
114365322297, lines 703-708: "Timeout (0:00:05)!" naming
tests/test_proof_1014_faulthandler.py::test_proof_sleep_past_faulthandler_timeout
with its full traceback) and a Linux leg (pytest (ubuntu-latest, 3.10), job
114365322191, lines 1072-1079: same dump, same test). The throwaway test
and the lowered value are removed/restored in this commit; the real values
above are what ships.

No user-visible behavior changes -- CI-only -- so no changelog fragment;
PR labeled no-changelog instead.

faulthandler_timeout is independent of --cov (coverage collection is
unaffected) and of pytest-xdist (confirmed via repo-wide grep: this repo
has no xdist configured, and the setting is per-worker/per-process either
way if that changes).

Co-Authored-By: Max <noreply>
…ls a genuine hang

This PR's own CI (run 38122057767, job 114418645594, pytest windows-latest/3.9)
ran the "Run tests" step ~33.6 min past its own 25min timeout and still ended
`cancelled` with no log at all -- the exact failure #1014 set out to fix, on
this PR's own branch. Neither the step's nor the job's timeout-minutes
visibly stopped it.

Temporarily lowers faulthandler_timeout to 20s and adds a test that sleeps
forever (never returns on its own) to prove faulthandler_exit_on_timeout
kills the pytest PROCESS itself well inside that bound, converting a hang
into a failed step with a traceback in a kept log -- rather than depending
on a runner-level kill already observed not to fire. Removed in the
finalizing commit on this branch; the real values ship there.

Co-Authored-By: Claude Sonnet 5 <[email protected]>
… orphans (#1014)

Belt-and-braces alongside faulthandler_exit_on_timeout: the "Run tests" and
"Run the full suite against the compiled hooks" steps now tee pytest's
output to a file and upload it with actions/upload-artifact under
`if: always()`, so a failed or timed-out step still leaves the log behind
even if the step's own captured output is somehow lost. Does not cover a
job-level `cancelled` -- GitHub Actions skips steps entirely in that case --
which is exactly why the process-level kill is the primary fix.

Also fixes the orphan processes a green leg of this PR's own CI already
surfaced (run 38122057767, job 114418645663): the OLD v0.42.3 shape
test_windows_real_wscript_v0_42_3_1002.py drives backgrounds wscript.exe
with a trailing `&` and disowns it by design (reproducing the shipped
trap-B silent skip), so nothing in that shape or this test module ever
waited on or killed what it launched -- the job's own teardown had to
force-terminate a leftover bash.exe/wscript.exe pair at the end of the
whole run. Adds an autouse fixture that force-terminates, after every test
in the module, any wscript.exe/bash.exe/conhost.exe whose command line
mentions that test's own tmp_path.

Co-Authored-By: Claude Sonnet 5 <[email protected]>
… the Linux-only claim

The round-2 proof (run 38122057767, job 114445674357) showed the faulthandler
traceback naming the stuck test IS kept in the log on Linux, followed by the
step's own 25-minute timeout error -- i.e. the step timeout is what keeps the
log, not faulthandler_exit_on_timeout: pytest was not observed to exit on its
own before the step timeout fired. Windows was not proven.

- Removes tests/test_proof_1014_round2_exit_on_timeout.py (the deliberately
  hanging proof test) and restores faulthandler_timeout to its real value
  (900s).
- Drops faulthandler_exit_on_timeout: unproven by the round-2 evidence, so
  this repo does not rely on it.
- Updates the workflow comments that had claimed faulthandler_exit_on_timeout
  does the killing, to instead say what is actually proven: the step timeout
  keeps the log, proven on Linux only.
- Adds the changelog.d/1014.fixed.md fragment this PR was missing.

Co-Authored-By: Claude Sonnet 5 <[email protected]>
Co-Authored-By: Claude Sonnet 5 <[email protected]>
@fdaviddpt
fdaviddpt force-pushed the fix-1014-ci-hang-log branch from 7991bec to 3b00b1f Compare October 11, 2026 21:01
@fdaviddpt fdaviddpt removed the no-changelog Change is invisible to users label Oct 11, 2026
@fdaviddpt
fdaviddpt merged commit 723d651 into main Oct 11, 2026
20 checks passed
@fdaviddpt
fdaviddpt deleted the fix-1014-ci-hang-log branch October 11, 2026 21:38
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.

CI: a hung Windows pytest leg leaves no log at all — make a hang name its test

1 participant