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

.github/workflows/tests.yml

@@ -87,7 +87,46 @@ jobs:
           Add-MpPreference -ExclusionPath "${{ github.workspace }}"
           Add-MpPreference -ExclusionPath "$env:RUNNER_TEMP"
       - name: Run tests
-        run: pytest
+        # #1014 round 2: this PR's own CI already hit a Windows leg that
+        # ran past this timeout and still ended `cancelled` with no log at
+        # all (job 114418645594) -- the step-level kill is not trusted to
+        # fire on its own on every OS. pyproject.toml's faulthandler_timeout
+        # dumps the stuck test's traceback well inside this bound, and the
+        # step's own timeout-minutes is what actually ends the step and
+        # keeps the log (proven on Linux: run 38122057767, job
+        # 114445674357 -- the faulthandler traceback IS in the kept log,
+        # followed by the step-timeout error). `tee` is belt-and-braces on
+        # top of that: whatever reached the log file before the step ends
+        # is uploaded as an artifact below under `if: always()`, rather
+        # than depending only on the step's own captured output surviving.
+        timeout-minutes: 25
+        shell: bash
+        run: |
+          set -o pipefail
+          pytest 2>&1 | tee pytest-output.log
+      - name: Upload pytest output log
+        # `if: always()` so a failed or timed-out step still uploads
+        # whatever reached the file -- the one case this cannot cover is
+        # a job-level `cancelled` (#1014's original failure mode, observed
+        # on Windows: job 114418645594), where GitHub Actions stops
+        # running steps entirely rather than executing the ones still
+        # pending. That path is not proven fixed here -- see the issue
+        # filed for the unproven Windows cancellation case.
+        if: always()
+        uses: actions/upload-artifact@v4
+        with:
+          name: pytest-output-${{ matrix.os }}-${{ matrix.python-version }}
+          path: pytest-output.log
+          if-no-files-found: ignore
+          retention-days: 7
+      - name: List surviving wscript/bash/conhost/powershell processes (Windows)
+        if: always() && runner.os == 'Windows'
+        shell: pwsh
+        run: |
+          Get-CimInstance Win32_Process |
+            Where-Object { $_.Name -in @('wscript.exe', 'bash.exe', 'conhost.exe', 'powershell.exe') } |
+            Select-Object ProcessId, ParentProcessId, Name, CommandLine |
+            Format-List
 
   # #900: each hooks.json-registered hook script is inlined and
   # comment-stripped for the release tree (compile_hooks.py) so the
@@ -139,4 +178,26 @@ jobs:
         # above already uses on this same matrix.
         run: python .github/scripts/compile_hooks.py --repo . --apply
       - name: Run the full suite against the compiled hooks
-        run: pytest
+        # Same #1014-round-2 reasoning as the plain pytest job's own "Run
+        # tests" step above.
+        timeout-minutes: 25
+        shell: bash
+        run: |
+          set -o pipefail
+          pytest 2>&1 | tee pytest-output.log
+      - name: Upload pytest output log
+        if: always()
+        uses: actions/upload-artifact@v4
+        with:
+          name: pytest-output-hooks-${{ matrix.os }}
+          path: pytest-output.log
+          if-no-files-found: ignore
+          retention-days: 7
+      - name: List surviving wscript/bash/conhost/powershell processes (Windows)
+        if: always() && runner.os == 'Windows'
+        shell: pwsh
+        run: |
+          Get-CimInstance Win32_Process |
+            Where-Object { $_.Name -in @('wscript.exe', 'bash.exe', 'conhost.exe', 'powershell.exe') } |
+            Select-Object ProcessId, ParentProcessId, Name, CommandLine |
+            Format-List

changelog.d/1014.fixed.md

@@ -0,0 +1,13 @@
+- Fixed #1014: a hung pytest leg on CI used to be cancelled by its own
+  job-level `timeout-minutes` with no log at all, leaving no way to tell
+  which test hung. `pyproject.toml` now sets `faulthandler_timeout = 900`
+  so a stuck test dumps every thread's traceback well before CI's own
+  25-minute step timeout fires, the "Run tests" step now runs under its
+  own `timeout-minutes: 25` and tees output to a log file that is uploaded
+  as an artifact under `if: always()`, and a Windows leg additionally
+  lists any surviving `wscript.exe`/`bash.exe`/`conhost.exe`/
+  `powershell.exe` processes at teardown. Proven on Linux (run 38122057767,
+  job 114445674357): the faulthandler traceback naming the stuck test is
+  present in the kept log. The equivalent Windows failure mode (a job
+  ending `cancelled` with no log at all, run 38122057767, job
+  114418645594) is not shown fixed by this change; tracked separately.

pyproject.toml

@@ -7,3 +7,33 @@ testpaths = ["tests"]
 # human. Rendered as a bare `s`, a green run with silent skips is visually
 # identical to a green run that checked everything (#306).
 addopts = "-rs --durations=25 --cov=pipeline --cov-report=term-missing --cov-fail-under=80"
+
+# #1014: a job cancelled by its own job-level timeout-minutes writes NO log at
+# all, so a hung test used to be unidentifiable. faulthandler_timeout (builtin
+# to pytest, no new dependency) dumps every thread's traceback -- naming the
+# hung test -- once any single test runs longer than this. Sized from a green
+# windows-latest run's own --durations=25 output (run 38091996750, job
+# 114330142530): the slowest single test there was 30.14s, so 900s leaves
+# ~30x margin over normal variance, and fires well inside the step's own
+# 25min (1500s) timeout below.
+#
+# #1014 round 2 PROOF (run 38122057767, job 114445674357, pytest
+# linux/3.x -- a deliberately hanging test, with faulthandler_timeout
+# temporarily lowered and the step timeout left in place): 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." -- i.e. the STEP timeout is what kept the log, not
+# faulthandler_exit_on_timeout: pytest was not observed to exit on its
+# own before the step timeout fired. faulthandler_exit_on_timeout is
+# therefore not enabled here; it was not shown to do anything in this
+# proof, and this repo does not rely on it. Only Linux was proven this
+# way -- the earlier round-2 Windows failure (run 38122057767, job
+# 114418645594: cancelled, no log, after ~33.6 min past the step's own
+# 25min timeout) is NOT shown fixed by this setting; see issue filed
+# separately for that gap.
+#
+# Compatible with --cov (faulthandler is independent of coverage collection)
+# and with pytest-xdist if it is ever added (this repo currently has none,
+# confirmed by a repo-wide grep); both ini options are per-worker/per-process
+# settings either way.
+faulthandler_timeout = 900

tests/test_windows_real_wscript_v0_42_3_1002.py

@@ -53,6 +53,52 @@
 _WSH_KEY = r"HKCU\Software\Microsoft\Windows Script Host\Settings"
 
 
+def _kill_processes_matching(substr: str) -> list[str]:
+    """Windows only: force-terminate any wscript.exe/bash.exe/conhost.exe
+    whose command line mentions SUBSTR (this test's own tmp_path).
+
+    #1014 CI finding (run 38122057767, job 114418645663 -- a GREEN leg of
+    this same PR's own CI): the hidden-launch route this module drives
+    left an orphan bash.exe and wscript.exe alive all the way to the job's
+    own teardown step, which had to force-terminate them itself (log lines
+    2256-2258, "Cleaning up orphan processes"). The OLD v0.42.3 shape under
+    test here backgrounds wscript.exe with a trailing `&` and disowns it --
+    by design, since trap B (the silent skip this module exists to
+    observe) depends on the caller never waiting on it -- so nothing in
+    the shape itself, or in this test module before this fixture, ever
+    killed what it launched.
+
+    Returns what it killed, for diagnostics; killing nothing is not an
+    error -- traps A and B can both mean the hidden route never actually
+    reached a running wscript.exe at all.
+    """
+    if sys.platform != "win32":
+        return []
+    ps = (
+        "Get-CimInstance Win32_Process | "
+        "Where-Object { $_.Name -in @('wscript.exe','bash.exe','conhost.exe') -and "
+        f"$_.CommandLine -like '*{substr}*' }} | "
+        "Select-Object ProcessId, Name | ForEach-Object { "
+        "Write-Output \"$($_.ProcessId) $($_.Name)\"; "
+        "Stop-Process -Id $_.ProcessId -Force -ErrorAction SilentlyContinue }"
+    )
+    r = subprocess.run(["powershell", "-NoProfile", "-Command", ps],
+                        capture_output=True, text=True, timeout=15, check=False)
+    return [line for line in r.stdout.splitlines() if line.strip()]
+
+
+@pytest.fixture(autouse=True)
+def _cleanup_hidden_launch_orphans(tmp_path):
+    """Kill, after every test in this module, any wscript.exe/bash.exe this
+    test's own hidden-launch call spawned and never waited on (see
+    `_kill_processes_matching`'s docstring for the CI evidence). Matched on
+    this test's own tmp_path so cleanup never reaches a process some other,
+    unrelated test launched.
+    """
+    yield
+    _kill_processes_matching(str(tmp_path))
+
+
 def _run(script: str, env: dict | None = None, timeout: float = 20,
          cwd: Path | None = None) -> subprocess.CompletedProcess:
     """CI finding (#1002 round 3, job 114204833202 and siblings): without