diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index e5ba8ba2..6f75ea62 100644 --- a/.github/workflows/tests.yml +++ b/.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 diff --git a/changelog.d/1014.fixed.md b/changelog.d/1014.fixed.md new file mode 100644 index 00000000..a8d25bd1 --- /dev/null +++ b/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. diff --git a/pyproject.toml b/pyproject.toml index 0fb94782..028bfe3c 100644 --- a/pyproject.toml +++ b/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 diff --git a/tests/test_windows_real_wscript_v0_42_3_1002.py b/tests/test_windows_real_wscript_v0_42_3_1002.py index 803a3523..d07a59cc 100644 --- a/tests/test_windows_real_wscript_v0_42_3_1002.py +++ b/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