Skip to content

Run the CI suite verbosely so a wedged test names itself - #81

Merged
max-sixty merged 1 commit into
mainfrom
fix/ci-33069480665
Aug 27, 2026
Merged

Run the CI suite verbosely so a wedged test names itself#81
max-sixty merged 1 commit into
mainfrom
fix/ci-33069480665

Conversation

@leaf-agent

Copy link
Copy Markdown
Collaborator

Problem

Run 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.

Diagnosis: why no fix for the stall itself

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 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, 35m03s), and the two commits that followed it onto maincbff468 and 03a0f31 — 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, 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.

Separately: the bound's headroom is thinning fast

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) — 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.

Cost of `-v`

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.


Automated fix for failed run 33069480665

@max-sixty
max-sixty merged commit 280be10 into main Aug 27, 2026
4 checks passed
@leaf-agent

Copy link
Copy Markdown
Collaborator Author

This PR's own ci run demonstrates the mechanism in Actions rather than only on a workstation — run 33077529603, 1388 passed, 6 skipped in 2225.02s (0:37:05).

The slowest sweep writes its nodeid at 13:53:18Z and its result at 13:57:49Z, so for four and a half minutes and 169 log lines it stands alone as the last unmatched line:

13:53:18Z tests/test_render_controls.py::test_every_ring_the_layer_draws_is_shown_whole_somewhere_in_the_corpus
13:57:49Z [gw1] [ 68%] PASSED tests/test_render_controls.py::test_every_ring_the_layer_draws_is_shown_whole_somewhere_in_the_corpus

That is what a wedge would leave behind, and it confirms the output is flushed to the Actions pipe as it happens rather than held in a buffer that a kill would discard.

@max-sixty
max-sixty deleted the fix/ci-33069480665 branch August 27, 2026 14:13
max-sixty pushed a commit that referenced this pull request Aug 29, 2026
…#85)

## Problem

Three `ci` runs on main have now spent the whole 45-minute step bound
and left no failure to read:
[33130006054](https://github.com/max-sixty/leaf/actions/runs/33130006054)
(`45de22f`),
[33130455313](https://github.com/max-sixty/leaf/actions/runs/33130455313)
(`d4472ad`),
[33131937176](https://github.com/max-sixty/leaf/actions/runs/33131937176)
(`caa8460`). Under the `-v` #81 added, each names a different test that
a worker picked up and never reported —
`test_a_resolved_thread_can_be_reopened`,
`test_a_sent_comment_is_revealed_in_the_panel`,
`test_an_answer_carrying_an_older_pick_cannot_undo_a_newer_one` — so the
wedge is not a test's, and the other worker stops minutes later in a
module of its own.

It is `Traffic`.
[`_responded`](https://github.com/max-sixty/leaf/blob/3feb009d654af450fed766621909b1933f96e418/tests/render_harness.py#L629)
queues a response when its **headers** arrive, and
[`settle`](https://github.com/max-sixty/leaf/blob/3feb009d654af450fed766621909b1933f96e418/tests/render_harness.py#L648)
then reads the body with
[`response.json()`](https://github.com/max-sixty/leaf/blob/3feb009d654af450fed766621909b1933f96e418/tests/render_harness.py#L663).
That call waits on the request's finished fact and takes no timeout in
any binding. A page that abandons an answer it no longer wants leaves a
request Chromium never reports finished, and the read then blocks for as
long as the job lives. It is the one wait in this harness that cannot
run out: `_until`'s own 30-second deadline guards `wait_for_event` and
never gets a turn, so the worker stops inside a helper every render test
calls, with no nodeid, no traceback and no Playwright timeout.

This is measured, not inferred — the full suite was run locally under a
call tracer and both workers were caught inside `Response.json`, unmoved
across two snapshots a minute apart (below).

## Solution

Settle a response only once `requestfinished` says the browser holds the
whole body, and wake `_until` on that same fact rather than on arriving
headers — a body is what the counters are read from, and that event is
the browser saying it has one. `settle` keeps an unfinished response
queued instead of reading it, so the shape that used to stop the run now
lets `_until` reach its deadline and print its counters, which is the
naming a wedge could never do.

The counters themselves are untouched: `acked` and `heard` still move on
the `response` event, so what a trip means to `round_trip` is what it
meant before.

This is at a different site from #84, which bounds `page.evaluate`'s
frame promises on the same three runs' evidence and says of itself that
it does not prove which wait wedged them. The two do not overlap in
`render_harness.py`, and #84 still closes a real unbounded-wait class —
it is just not the one that stopped these runs.

## Testing

`uv run pytest tests --run-nightly` — **1357 passed, 6 skipped in
19:36**, on the machine that had just wedged twice in a row at 65% and
91% without the change. Rebased onto `dd42ddb`: `ruff check`, `ruff
format`, `tests/test_render_conversations.py` and
`tests/test_render_reactions.py` (48 passed), and the three traffic-wait
gates.

Bug-back: with `settle` restored to its unconditional drain,
`test_traffic_leaves_a_body_the_browser_has_not_finished_handing_over`
fails with `a body was read before the browser had all of it`.

<details><summary>How the blocking call was identified</summary>

The suite was run as CI runs it (`uv run pytest tests --run-nightly -v`)
with a plugin wrapping the Playwright sync surface — `Page.close`,
`Page.evaluate`, `Page.wait_for_function`, `Response.body/json/text`,
`Locator.*`, `Mouse.*`, `Keyboard.*` — each writing the call it is
inside to a per-worker file. A watchdog snapshotted those files after
the log had been silent for 150 seconds, and again a minute later:

```
--- snapshot A
30159 1787884275.442 ENTER Response.json stack=['Response.json']
27463 1787884129.338 ENTER Response.json stack=['Response.json']
--- snapshot B
30159 1787884275.442 ENTER Response.json stack=['Response.json']
27463 1787884129.338 ENTER Response.json stack=['Response.json']
```

Both workers, unmoved, with the report count frozen at 1315 of 1395.
`py-spy` cannot reach these (the sandbox denies `ptrace`), and
`faulthandler` names nothing here for the reason `pyproject.toml`
records — the test's frames sit in a suspended greenlet.

The wedge reproduces without instrumentation too. An earlier plain run
stopped at 91% with `gw1` inside
`test_a_resolved_thread_can_be_reopened` after
`test_a_thread_the_agent_closed_names_who_closed_it` — the same pair, in
the same order, as run 33130006054. Both wedges left their page server
answering: the served page's `viewed.json` kept ticking every 30
seconds, and `ss` showed one established connection per server with
empty queues, so nothing was stalled on the wire and no `flock` was
held. Per-test pacing in the failed CI runs matches a green run's decile
for decile, which rules out the machine slowing down before it stopped.

</details>

---
Automated fix for [failed
run](https://github.com/max-sixty/leaf/actions/runs/33130006054)

---------

Co-authored-by: leaf-agent <318509791+leaf-agent@users.noreply.github.com>
max-sixty pushed a commit that referenced this pull request Aug 29, 2026
#100)

## Problem

[Run
33220366482](https://github.com/max-sixty/leaf/actions/runs/33220366482)
(`db3f5d0`) spent the step's whole 45 minutes and left no failure to
read. Under the `-v` #81 added, both workers name what stopped them, and
they stopped in two different places. `gw0` printed
`tests/test_render_widgets.py::test_accept_all_decides_every_pending_suggestion`
at 23:48:35 — that is the `Response.json` shape #85 diagnosed, and #85
has since landed on `main` as
[e626f53](e626f53). `gw1`
printed
`tests/test_smoke.py::test_a_shipped_page_passes_the_real_browser_gate`
at 23:49:53, at 99%, and never reported it. That second one is left
over: it is one line — `render_gate_model.render_version(...)` — so the
wait is on the gate's own path, in shipped code rather than in `tests/`,
and it has now stopped three runs.

`page.evaluate` takes no timeout in any binding.
[`render_checks.py`](https://github.com/max-sixty/leaf/blob/b25a9e06f74cc1f994de6dc48a1e0a2ada873a05/plugins/leaf/skills/leaf/scripts/leaf/render_checks.py#L23)
already races the probe module's *load* against `call.timeoutMs`; the
probe it then invokes was awaited with nothing bounding it. Two probes
await a promise the page supplies rather than a fact it states, and both
are reached that way:

-
[`nextFrame`](https://github.com/max-sixty/leaf/blob/b25a9e06f74cc1f994de6dc48a1e0a2ada873a05/plugins/leaf/skills/leaf/scripts/leaf/render-checks/runtime.js#L47)
is `new Promise(requestAnimationFrame)`, awaited at
[`readings.py:188`](https://github.com/max-sixty/leaf/blob/b25a9e06f74cc1f994de6dc48a1e0a2ada873a05/plugins/leaf/skills/leaf/scripts/leaf/render_gate/readings.py#L188)
as the last thing each scheme reads. `requestAnimationFrame` stops in a
page the compositor has stopped drawing.
-
[`retiredSlots`](https://github.com/max-sixty/leaf/blob/b25a9e06f74cc1f994de6dc48a1e0a2ada873a05/plugins/leaf/skills/leaf/scripts/leaf/render-checks/widgets.js#L166)
awaits `Promise.allSettled` over each holder's animations —
`a.finished`, the same promise `bb8b7e0` had to bound on the test side.

They are the only two: no other export under `render-checks/` contains
an `await` or a `.then`. #84 named `nextFrame` and scoped it out as
product rather than suite behaviour, which is right — it belongs here
rather than in `tests/render_harness.py`, and this PR does not touch
anything #84 does.

## Solution

Race each probe's answer against the deadline `_INVOKE_PROBE` already
carries for the load, in the one place every probe goes through. Nothing
new is declared: `call.timeoutMs` is the gate's `served_timeout_ms`,
defaulting to `SERVED_TIMEOUT_MS`, which is Playwright's own 30 seconds
— so a probe now runs out where every other browser wait in the gate and
the suite runs out. The rejection comes back through `evaluate`, and
[`render_version`](https://github.com/max-sixty/leaf/blob/b25a9e06f74cc1f994de6dc48a1e0a2ada873a05/plugins/leaf/skills/leaf/scripts/leaf/render_gate/version.py#L94)
already turns a `PlaywrightError` from its probe module into a gate
finding, so `version check --render` reports which probe stopped and the
bound it passed instead of hanging.

Bounding at `_INVOKE_PROBE` rather than at the two probes is what keeps
the layer open: a probe added later that awaits the page is bounded by
existing, and the suite's own `evaluate_probe` callers are covered by
the same edit. `tests/CLAUDE.md`'s bounded-await rule is corrected to
say so, since it currently names only the loader and would send an
author to write a second race around a call that already has one.

This does not claim to bound every unbounded await in the payload — only
the ones reached through `evaluate_probe`. An `await` written directly
into a `page.evaluate` argument elsewhere is still a wait nothing
bounds.

## Testing

`test_a_probe_that_never_answers_is_a_gate_finding`, beside the loader's
own deadline test. It serves the real probe facade with `nextFrame`
replaced by a promise that never settles, runs the whole gate, and
asserts the finding names the probe and the bound. The replacement holds
its own resolver, as `requestAnimationFrame` holds the callback it was
handed — the first version let it be collected, and the driver ended the
wait itself with `Resulting promise was garbage collected`, which is a
different arrangement and not the one that stopped these runs.

Bug-back on this runner, same test both ways:

```
this branch      1 passed in 9.51s   (failure: "probe nextFrame did not answer within 3000ms")
main's _INVOKE_PROBE   exit=143      (still waiting when a 120s cap cut it off)
```

On the rebased tree (`b25a9e0`), every suite file that reaches
`evaluate_probe`, plus the one the wedge landed on:
`test_render_gate.py` and `test_smoke.py` (66 passed),
`test_render_pages.py`, `test_render_startup.py` and
`test_render_options.py` (135 passed), `test_render_widgets.py` (61
passed), and `test_render_export.py` with `test_render_projection.py`
(97 passed, run against `6045970` before the rebase, along with
`test_render_commands.py`). The everyday suite `uv run pytest tests` is
690 passed, 6 skipped, and `pre-commit run` over the three changed files
is clean. The full `--run-nightly` suite has not been run here; CI runs
it on this branch.

<details><summary>The three runs this wait stopped</summary>

Each row is the nodeid a worker printed and never reported, found by
pairing `-v`'s start lines against its `[gwN] … PASSED/FAILED` lines
over the whole job log:

| Run | Commit | Unpaired nodeid |
| --- | --- | --- |
|
[33169923393](https://github.com/max-sixty/leaf/actions/runs/33169923393),
attempt 1 | `16a94ad` (#95's branch) |
`test_smoke.py::test_a_shipped_page_passes_the_real_browser_gate`, and
`test_render_options.py::test_a_question_owns_one_thread_in_the_page_and_panel`
|
|
[33209352445](https://github.com/max-sixty/leaf/actions/runs/33209352445)
| `1c5edad` |
`test_smoke.py::test_a_shipped_page_passes_the_real_browser_gate`, and
`test_render_conversations.py::test_a_resolved_thread_can_be_reopened` |
|
[33220366482](https://github.com/max-sixty/leaf/actions/runs/33220366482)
| `db3f5d0` |
`test_smoke.py::test_a_shipped_page_passes_the_real_browser_gate`, and
`test_render_widgets.py::test_accept_all_decides_every_pending_suggestion`
|

The second nodeid on each row is #85's shape rather than this one — all
three reach `Traffic` through `round_trip`. This PR does not claim them;
e626f53 does.

That first row is attempt 1 because its failed jobs were re-run
afterwards, and the re-run's log is what `gh run view --job` returns
now; attempt 1's own log is still readable through
`actions/jobs/98844279758/logs`, and that is the one parsed here.

The diagnosis on #95 named both of this PR's awaits after the first of
these three runs, but #95 was a test-side fix and could not carry them.
That comment is now on a closed PR, so this restates it rather than
linking to it as if it were pending.

</details>

---

Automated fix for [failed
run](https://github.com/max-sixty/leaf/actions/runs/33220366482)

Co-authored-by: leaf-agent <318509791+leaf-agent@users.noreply.github.com>
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.

2 participants