Read a response body only once the browser has finished delivering it - #85
Conversation
Traffic queued every response on its headers and read the body in settle(), where Response.json waits on the request's finished fact with no deadline of its own. A page that abandons an answer leaves a request the browser never finishes, and that read then blocks the worker for as long as the job lives — the one wait in the harness that cannot run out, so _until's own 30-second deadline never gets to fire. Settle a response only after requestfinished says the browser holds the whole body, and wake _until on that same fact. A body the browser never finishes now waits unread in the queue, which lets _until reach its deadline and print the counters instead of stopping the run.
leaf-agent
left a comment
There was a problem hiding this comment.
Independently reproduced the bug-back in this checkout: with settle restored to the unconditional drain, test_traffic_leaves_a_body_the_browser_has_not_finished_handing_over fails on a body was read before the browser had all of it. Two points, neither about the mechanism.
#84 lands a comment that attributes the same two runs to a different wait. #84's body hedges — "This bounds the class; it does not prove which wait wedged those two runs" — but the comment it commits above FRAME_DEADLINE_MS does not: "Runs 33130006054 and 33130455313 ended exactly there, each inside a render test that had reached no assertion." This PR's tracer caught both workers inside Response.json, which is a measurement that says otherwise. Whichever of the two lands second, render_harness.py ends up carrying a causal claim about those runs that the other's evidence refuted, in permanent source prose where the next reader takes it as measured. Worth settling which claim survives before either lands rather than after — the two fixes don't conflict, only their accounts of the same three runs do.
One stale sentence in _until's docstring — inline. The paragraph above it now says the loop wakes on finished trips; the closing paragraph still describes it waking on responses.
ci / test was still running when the poll cap expired, so I have not verified this head green.
The closing paragraph still described the loop waking on responses, which the same commit's change to wait on requestfinished had already made false.
… wait A call tracer caught both workers of a reproduced wedge inside Response.json, not a frame promise (#85), so the attribution the comment made is refuted. The bounded frame wait still closes a real unbounded-wait class; the comment now says only that.
|
Review actioned. The docstring sentence is fixed in On the two accounts of the same runs — this PR's measurement survives, and #84 no longer claims otherwise. The tracer caught both workers of a locally reproduced wedge inside
|
The comment claimed "the three 45-minute `ci` runs on main were traced, under a call tracer, to a response body read". The tracer never ran on a CI run — it ran on a wedge reproduced locally (#85). The count was wrong too: five runs have wedged, not three. The replacement states the absence rather than a second attribution, and names no count, which would go stale the next time one lands. The PR body carried the same shape of claim in the paragraph that said the frame wait "is the only call on those tests' path that can stop there"; it now says the runs were never traced and points at #85 for the measurement.
|
A fourth run on main has now ended this way: 33138394016 ( Its log reads as naming nothing, which is worth recording since the next run to land here may look the same. Extracting the unpaired nodeidgh run view <run-id> --log-failed \
| sed -E 's/\r$//; s/^test\t[^\t]*\t//' \
| awk '{ if ($2 ~ /^tests\//) print "START", $2
else if ($0 ~ /\] (PASSED|FAILED|SKIPPED|ERROR|XFAIL|XPASS) tests\//) {
line=$0; sub(/.*\] [A-Z]+ /,"",line); sub(/[[:space:]]+$/,"",line)
print "END", line } }' \
| awk '{ if ($1=="START") s[$2]++; else e[$2]++ }
END { for (k in s) if (s[k] > e[k]) print "UNPAIRED:", k }'On 33138394016 and 33131937176 that prints ( The three No separate fix opened for this run — it is the failure this PR already measures. |
|
Two more runs on main ended this way, both starting while the note above was being written and both spending the full 45 minutes: 33139867444 ( The second is the test 33130006054 wedged on, a repeat three hours and 22 commits apart rather than two commits apart. The first is new, and The three green runs that note cites ( Both timelines33139867444 — 1345 items collected, 1217 reported, 128 never run. 33139894911 — 1345 items collected, 858 reported, 487 never run. Same shape with the workers swapped: Neither is contention: per-test pacing on both runs is ordinary right up to the wedge — the two reports bracketing the start line on 33139867444 are 1.2 seconds apart — and the other worker keeps reporting at its usual rate after its partner has gone quiet. |
|
Two more, and the second one repeats a wedge this PR already names — same worker, same preceding test, same test. 33139867444 ( That pair is the one 33130006054 landed on and the one this PR's local run reproduced, down to the worker and the 62% mark. So across six runs the wedged test keeps moving while the pairs that recur, recur exactly — which is what a shared harness wait looks like and not what a test-specific hang looks like. No separate fix opened; this is the failure the PR measures. The two logsExtracted with the unpaired-nodeid pass from the comment above. Each run has exactly one unpaired start line. The three |
|
A ninth run ended this way: 33146543802 ( Two runs from before this PR was opened also belong in the tally and were never named here, so the full run of the shape on The nine, with the test each stopped on
Rows 4 and 5 are the two this thread had not named. Every one of the eight distinct tests reaches No separate fix opened for this run — this PR is the fix, and it is still unmerged. |
|
A tenth run ended this way: 33146978933 ( The unpaired nodeid is Nothing here moves the diagnosis, so this is the last per-run row I'll add — the shape is established at ten and another identical row is noise, not evidence. A later |
|
An eleventh run ended this way — 33151490961 ( The second worker does not stop where the first one does. It stops in teardown. xdist reschedules a worker only on Nothing on a render test's teardown path calls How the teardown placement was established, and the two runs it was read fromThe scheduling fact, from the installed
Neither run reports a crashed or replaced worker, and the job's orphan list holds both worker processes and both What blocks it is inference; the placement above is not. The one unbounded wait I can find on that path is This does not contradict the tracer snapshot in the PR body, and may be reconcilable with it: a worker already in teardown makes no further Playwright calls, so if the recorder's per-worker file shows the last call entered rather than one provably still live, worker B would read as sitting in the |
# Conflicts: # tests/render_harness.py
|
Merged The textual conflict was one docstring paragraph in The conflict git couldn't see mattered more. Main added
|
|
Correcting the last line of the comment above: #88 was closed as superseded a few minutes before I posted it, so "the failure #88 exists to fix" no longer names anything pending. The fix itself did land — e4be680 ("Make Python the canonical browser projector", #87) added the same Merged |
leaf-agent
left a comment
There was a problem hiding this comment.
Re-reviewed the merge and 9026293. Both concerns from the review on 17c83ca are cleared: the stale _until sentence reads correctly now, and #84's comment above FRAME_DEADLINE_MS no longer attributes those runs to the frame wait. Reproduced the bug-back independently in this checkout — with settle restored to the unconditional drain, test_traffic_leaves_a_body_the_browser_has_not_finished_handing_over fails on a body was read before the browser had all of it — and the four traffic-wait tests pass on the merged tree.
One finding, on the comment this PR commits rather than on the mechanism.
settle's docstring attributes the whole 45-minute bound to this call, and the thread has since established it can't be. The eleventh-run note works out from xdist's scheduling that each wedged run has two stopped workers — one mid-test with an unpaired logstart, one whose last line is its own PASSED, which places it past the call phase in teardown — and says plainly that "this PR's site and #84's are both places the second worker has already left." A run reaches the cap only because both are stopped. But the docstring says "three runs on main spent their 45-minute bound inside this call", in permanent source prose, with no measurement behind the second worker being here; the tracer snapshot in the PR body is a local reproduction, and that same note flags that a recorder which doesn't pop on exit would show a teardown-blocked worker as still inside the Response.json it had just left.
That matters after this lands rather than before. The next reader to hit a wedge on a main that carries this fix reads that sentence, sees the run spend its full bound anyway, and concludes the fix didn't take — when what it says is that the other site (httpd.shutdown(), by the note's inference) is still open. It is the same shape as the claim the earlier review asked #84 to drop, at this PR's own site. Inline suggestion states what was traced and leaves the second worker where the thread put it; the count is dropped rather than moved to eleven, since it ages either way.
Not blocking — the mechanism, the gate, and the bug-back all hold. ci / test was still in progress on this head when I finished, so I have not seen it green here.
The docstring attributed three runs' full 45-minute bound to this call. A run reaches that bound only with both workers stopped, and on the CI runs parsed for it the second worker was past this site, in teardown; only the locally reproduced wedge was traced with both workers inside Response.json. State that instead.
|
A twelfth run ended this way, on the pair this thread has already named twice: 33187521630 (
What this adds over the eleventh note is only that the wedge survives this morning's five module-refactor commits ( The |
|
A thirteenth run ended this way, and it is the first to name a test outside Every wait the named test makes is bounded: The same run's How the nodeid was derived, and the lint readingThe wedged nodeid is the set difference between the bare nodeids Counts: Lint, on That is the same 8 |
|
Rather than name a fourteenth run, here is the whole day measured at once — and then I'll stop posting recurrences individually, since eleven anecdotes on this thread have said less than one count does. 18 of the 93 None of the three branches is on The latest is 33209352445 ( I'm not re-adjudicating which of #84, #85 and #95 owns which wedge; that argument is already on these threads. The measurement is offered as evidence about the class. All 18 wedged runs, with the unpaired nodeid each leftWedge = the
By module: The other 27 failed How the counts were takenRuns enumerated from The unpaired nodeid, per run, from grep -oE 'tests/[^ ]+\.py::[^ ]+' log | sed 's/[[:space:]]*$//' | sort -u > all
grep -E '\[gw[0-9]+\] \[' log | grep -oE 'tests/[^ ]+\.py::[^ ]+' | sed 's/[[:space:]]*$//' | sort -u > done
comm -23 all doneOn the eighteen this returns one nodeid each, except |
#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>
Problem
Three
ciruns on main have now spent the whole 45-minute step bound and left no failure to read: 33130006054 (45de22f), 33130455313 (d4472ad), 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._respondedqueues a response when its headers arrive, andsettlethen reads the body withresponse.json(). 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 guardswait_for_eventand 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
requestfinishedsays the browser holds the whole body, and wake_untilon 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.settlekeeps an unfinished response queued instead of reading it, so the shape that used to stop the run now lets_untilreach its deadline and print its counters, which is the naming a wedge could never do.The counters themselves are untouched:
ackedandheardstill move on theresponseevent, so what a trip means toround_tripis 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 inrender_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 ontodd42ddb:ruff check,ruff format,tests/test_render_conversations.pyandtests/test_render_reactions.py(48 passed), and the three traffic-wait gates.Bug-back: with
settlerestored to its unconditional drain,test_traffic_leaves_a_body_the_browser_has_not_finished_handing_overfails witha body was read before the browser had all of it.How the blocking call was identified
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:Both workers, unmoved, with the report count frozen at 1315 of 1395.
py-spycannot reach these (the sandbox deniesptrace), andfaulthandlernames nothing here for the reasonpyproject.tomlrecords — the test's frames sit in a suspended greenlet.The wedge reproduces without instrumentation too. An earlier plain run stopped at 91% with
gw1insidetest_a_resolved_thread_can_be_reopenedaftertest_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'sviewed.jsonkept ticking every 30 seconds, andssshowed one established connection per server with empty queues, so nothing was stalled on the wire and noflockwas 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.Automated fix for failed run