Remove the hang guard that killed a live worker and named no test - #46
Conversation
|
can we instead try removing the faulthandler configs? might that help? I'm loath to add more configs |
The faulthandler timeout cannot name a stalled browser test. Under the sync Playwright API the test's own frames sit in a suspended greenlet, so the dump sees only OS threads: its one trip on main printed the page server's thread, execnet's reader, and Playwright's event loop, and named nothing. It then exited the worker, which under `--dist loadgroup` leaves the controller on a session that never finishes, so a run already at 99% spent the job's whole 45-minute cap. What it fired on was not a hang either. The suite's slowest browser sweeps run 60-105 seconds on four cores at `-n 2`, so a three-minute clock sits 1.7x above work every run does, and one noisy runner spends that margin. The two things it was meant to buy are already held elsewhere. Playwright's own 30-second timeouts fail a stalled browser wait with the test's nodeid — the shape of the three other recent failures on main. The workflow's 45-minute step bound is what turns a true wedge into the `failure` `tend-ci-fix` answers.
4841984 to
3337041
Compare
|
Yes — it helps more than the tuning did, and I've replaced the PR with it. Pushed as Checking the premise turned up a better reason than the config count. The guard cannot name a stalled browser test. Under the sync Playwright API the test's own frames sit in a suspended greenlet, and faulthandler dumps OS threads — so the trip on main printed the page server's thread, execnet's reader, and Playwright's Both things it was meant to buy are already held, by machinery that wasn't added for it. Playwright's own 30-second timeouts fail a stalled browser wait with the nodeid — the three other recent One thing it gives up, in the PR body rather than here: the untimed cold-cache launcher runs in Also noting rather than changing: |
|
The red It's a GitHub-side runner-allocation problem, not one of ours, and it's hitting the repo more widely: main's Evidence
|
## Problem [Run 33069480665](https://github.com/max-sixty/leaf/actions/runs/33069480665) on `main` did not fail a test — it stopped. The suite ran clean to `[ 72%]` at 12:17:45Z and then wrote nothing for twenty-three minutes, until the step's 45-minute bound killed it. The bound kills pytest rather than failing it, so nothing is written on the way out, and the default terminal reaches the log only once every 72 tests: the run named no test at all, which is the one fact `tend-ci-fix` needed and the only one it could not get. ## Solution Add `-v` to the CI invocation. Under `-v` xdist writes a nodeid when a worker picks a test up and writes it again when the test reports, so the trailing unmatched line is exactly the test that stopped. It watches nothing and ends nothing, so it does not reopen the decision in `pyproject.toml`: the hang guard removed in #46 killed a worker in order to print a suspended greenlet's frames and name no test, and `-v` names the test while intervening in nothing. It also adds no configuration: `pyproject.toml` is untouched and the local default is unchanged, because the problem is CI-specific — on a workstation a wedge is visible in the terminal, while here a killed process leaves the log as the sole witness. No test is weakened and no bound moves. **This does not fix the stall.** The stall is not reproducible and I could not identify it. What it fixes is that the next one will be answerable instead of anonymous. <details><summary>Diagnosis: why no fix for the stall itself</summary> **The stall was not slowness.** The failed run was ahead of a healthy one at the same point — it reached 72% at 22m08s, where the green run on [bf87d64](https://github.com/max-sixty/leaf/actions/runs/33069396385) reached it at 25m16s. Then it produced nothing further. Normal blocks in that region run 2–7 minutes, so twenty-three is 3–4× the worst of them, and it was still silent when killed. **Both workers stopped, not one.** Under `--dist loadgroup` a wedged worker holds only its own batch; the other keeps draining `pending` and the counter keeps moving. It did not move at all. The runner's orphan sweep found both worker processes and both `chrome-headless-shell` processes still alive at the kill, so nothing had crashed either. **The code is not implicated.** The same tree passed on its own PR branch ([run 33066712190](https://github.com/max-sixty/leaf/actions/runs/33066712190), 35m03s), and the two commits that followed it onto `main` — [cbff468](https://github.com/max-sixty/leaf/actions/runs/33072090225) and [03a0f31](https://github.com/max-sixty/leaf/actions/runs/33073047974) — are both green with #79's code in them. `main` is not currently red. **It does not reproduce.** I ran the complete nightly suite on `main` on an `ubuntu-24.04` runner of the same class: `1381 passed, 6 skipped in 2296.13s (0:38:16)`, no failures and no stall, including the whole `test_render_gate.py` / `test_render_navigation.py` region that 72% falls in (`test_render_gate.py` spans items 944–1016 of 1387). That run was under `-v`, which is also where the claim above was checked rather than assumed: 1387 nodeid lines against 1381 `PASSED` lines, and each poll of the growing log ended on the bare nodeid of whatever was in flight — the 283s ring sweep stood alone for 171 lines. Output to a pipe, as in Actions, not a terminal. **The region is not the untimed-launcher class either.** #46 left one shape unbounded — the cold-cache runs in `test_interact_layer.py` that let `uv` resolve through the index with no `timeout=` — and it is not this: those are items 336–463, long finished by 72%, and everything in the stall's region goes through `render_version` and the browser, where Playwright's own 30-second bounds apply. **No upstream incident covers it.** githubstatus lists nothing against Actions in the 12:17–12:41Z window; the only incident open that morning was Copilot AI Model Providers, resolved 12:12:58Z. So this is not the dispatch-layer shape of #47, and it is not the stale-`page.route` cascade of #34 either. **It is the first wedge of its kind.** Across all 54 `ci` failures on `main` with a recorded test step, exactly two spent the full 45 minutes. The other, [32954830645](https://github.com/max-sixty/leaf/actions/runs/32954830645), is the one #46 answered: it reached 99%, the old faulthandler guard fired at three minutes, printed the server thread, execnet's reader and Playwright's event loop, killed `gw1` (`node down: Not properly terminated`) and left the controller on a session that never ended. That was the guard's own wedge and the guard is gone. Every other failure concluded in under 40 minutes on a real assertion. That leaves this one unclassified rather than transient, and `running-tend` says to treat unclassified as durable. A durable cause I cannot name has no safe fix, so the change above is scoped to making the next occurrence nameable rather than guessing at the wedge. </details> <details><summary>Separately: the bound's headroom is thinning fast</summary> Not addressed here — whether the suite should grow or the bound should is not a call to make on one occurrence — but worth seeing. Test-step wall time on `main`, oldest to newest: | Run started (UTC) | Items | Test step | | --- | --- | --- | | 08-26 09:48 | 1230 | 17.6 min to 99% | | 08-26 18:58 | — | 18.2 min | | 08-26 20:47 | — | 19.9 min | | 08-26 21:04 | — | 24.3 min | | 08-27 00:24 | — | 24.9 min | | 08-27 03:51 | — | 26.4 min | | 08-27 06:31 | — | 36.7 min | | 08-27 11:53 | 1381 | 36.0 min | | 08-27 12:41 | — | 35.4 min | The bound is 45. Note that the item count rose 13% while the time rose 110%, so this is per-test cost rather than test count. Four tests carry 13 of the roughly 76 worker-minutes, all corpus sweeps and three of them on `gallery`: ``` 283.65s test_render_controls.py::test_every_ring_the_layer_draws_is_shown_whole_somewhere_in_the_corpus 245.85s test_render_controls.py::test_a_press_leaves_its_neighbours_where_they_were[gallery] 140.72s test_render_controls.py::test_an_aimed_press_does_only_what_the_outline_promised[gallery] 109.79s test_render_anchors.py::test_every_passage_in_a_real_page_can_be_quoted[gallery] ``` `-n 2` is also the whole machine's allowance on a 4-vCPU runner, where the cap's stated reason — "keep overlapping browser test suites from saturating the machine" ([1ee98fe](1ee98fe)) — is a workstation's reason, and in CI no second suite exists. I have not touched it: more workers is more browser load on exactly the shape of race `running-tend` says dominates red runs here, and that trade is not mine to make. </details> <details><summary>Cost of `-v`</summary> About 2,800 lines and ~250 KB of log per run, in place of ~20 progress lines. The visible cost is to `gh run view --log-failed` on an ordinary red run, which now carries the roster ahead of the traceback. </details> --- Automated fix for [failed run 33069480665](https://github.com/max-sixty/leaf/actions/runs/33069480665) Co-authored-by: leaf-agent <318509791+leaf-agent@users.noreply.github.com>
Problem
Run 32954830645 reached 99% of the suite, tripped the 180s faulthandler guard, killed
gw1, and then sat silent for twenty-five minutes until the step's 45-minute bound ended the job. The guard bought a stack dump that named no test, and gave the rest of the budget back.It cannot name one. Under the sync Playwright API a test blocked on the browser has its own frames in a suspended greenlet, and faulthandler dumps OS threads — so the trip printed the page server's thread, execnet's reader, and Playwright's event loop, and nothing else. Exiting the worker is then worse than doing nothing: xdist clones a replacement, and under
--dist loadgroupthe clone never picks the run back up.What it fired on was probably not a hang. The suite's slowest browser sweeps run 60–105s on four cores at
-n 2— the shape of machine CI runs on, at the same wall time — so a three-minute clock sits 1.7× above work every run does, and one noisy runner spends that margin.Solution
Remove
faulthandler_timeoutandfaulthandler_exit_on_timeout. Both things the guard was meant to buy are already held elsewhere, by machinery that was not added for it:cifailures on main — each oneFAILED tests/test_render_projection.py::test_a_message_reference_travels_or_says_it_cant - TimeoutError, named, at ordinary cost.failuretend-ci-fixanswers, and that is the fault Bound the suite so a wedged run fails instead of vanishing #30 was actually about.Net two lines fewer than main, and nothing added.
What the dump actually printed
Three threads, no test frame among them: the page's dev server, execnet's reader, and the driver greenlet the main thread was sitting in.
What this gives up
One class the guard could have named, had it ever fired there: a wait with no timeout of its own outside the browser. The cold-cache launcher runs in
test_interact_layer.pyshell out tobin/leafand letuvresolve through the network with notimeout=. Those have never hung, and the direct fix if they ever do is atimeout=on the call — which names the test and raises in place, rather than exiting a worker the run cannot continue without. Not doing that here; no evidence asks for it yet.The
pytest>=9.1floor was raised in aef67af solely forfaulthandler_exit_on_timeoutsupport. Left alone —uv.lockpins 9.x either way, and lowering it would be a guess at a version the suite has not been run on.Testing
uv run pytest tests—574 passed, 6 skipped in 141.73s.pre-commitpasses on the changed file. This PR's owncirun exercises the config over the full--run-nightlysuite.