row 172 brief: the cause is a Seen click dropped during a Board read, and the reload race in the row 165 test (P19 366, #1670)

This commit is contained in:
2026-10-19 15:03:56 -05:00
parent bab069b3c5
commit 164e1f97fe
@@ -15,36 +15,62 @@ Error: Condition timed out: !document.querySelector("#signed-out").hidden
at async TestContext.<anonymous> (board-held.test.mjs:220:5)
```
Line 220 is the module-read step: `window.__redirect.push('/api/queue'), location.hash = '#/queue'`, then `out()`. The
wait helper (:73) polls 100 times at 50 ms, so the page has about 5 s of its own time to show the sign-out line. The
logs are on P19 366 (comments 279 and 280) and in `/mnt/storage/scratch/sage-r170/out-run1/` and `out-run3/`.
Correction (Sage, after the trace): line 220 is not the module-read step. It is the `out()` after the Seen click at
:219, the board POST step: `window.__redirect.push('/api/seen')`, then a click on the inspector's Seen button. All four
failures seen so far stop there: row 170 runs 1 and 3 (`pkg-webui.log:259`), row 134 gate run 1 (`pkg-webui.log:260`)
and the traced reproduction below. The wait helper (:73) polls 100 times at 50 ms, so the page has about 5 s of its own
time to show the sign-out line. The logs are on P19 366 (comments 279 and 280) and in
`/mnt/storage/scratch/sage-r170/out-run1/` and `out-run3/`.
What reading the code rules out (bus.js and app.js at d58c9c5cd):
- The redirect itself is immediate. The test's fetch stub answers `/api/queue` with an opaque redirect without touching
the server, and `fetchApi` (bus.js:46) calls `signOut()` on it.
- The page never reads `/api/queue` for real before the push, so a slow `reads.queue()` subprocess isn't in the path.
- Before the queue read, `render(true)` (bus.js:1059) does one real read, `/api/bus/messages`, from the in-process
broker. That read and the hashchange dispatch are the only steps that can wait on something.
The bullets below were written for the module-read step and don't bear on the cause. They stay as first written.
## The cause
Not yet established. The row stays queued until it is. Mos's ruling: the fix goes after the cause of the wait under
load, such as ordering, a shared browser or the event it waits on, and a longer timeout alone won't do. This section
gets the cause, with the trace that shows it, and the brief is re-pinned before the row moves to briefed.
The page drops a Seen click that lands while a Board read is in flight. `app.js:404-405` at bab069b3c:
Step 1, Sage, on the slot. Run the webui suite under the gate's load, with the test's page timeline traced:
the hashchange time, each fetch's start and end with its path, the `mosaic-signed-out` event time, and the
`#signed-out` unhide time. Repeat until the failure reproduces. Record what the page was waiting on when the 5 s ran out.
```js
const seen = e.target.closest('[data-seen]');
if (!seen || busy) return;
```
`refresh()` (`app.js:360`) holds `busy` for the whole `/api/board` read and the conversation poll after it. The
sign-out test runs with fast timers, so the 10 s poll fires every 150 ms and a Board read is in flight for a large share
of the test's time. Under the gate's load each read takes longer, and the chance that the click lands inside one rises.
When it does, the click returns without a word, `/api/seen` is never fetched, the stub's redirect never answers, and the
sign-out line never shows. The 5 s wait then times out. Nothing was slow. The page waited on a request it never sent.
The trace. Sage ran the webui suite on a load loop with the page timeline recorded (every fetch's start and end with its
path, clicks, the `mosaic-signed-out` event). Run 3 reproduced the failure, recorded in
`/mnt/storage/scratch/sage-r172/traces/fail-seen-3572058-1792439609092.json`. The wait gave up at 5191 ms with the page
clock at 5792 ms, which puts the click at about 595 ms. A `/api/board` read ran from 580 to 615 ms. The trace has no
`/api/seen` fetch at all and no sign-out event.
This is a product defect, not a test artifact. On the live Board a person's Seen click during the 10 s poll's read does
nothing, and a slow machine scan widens that window.
## The change
Written with the cause. It fixes the ordering or the wait condition that the trace shows. It doesn't raise the
helper's 100 × 50 ms budget as the fix.
A Seen click during a Board read waits for that read and then posts on the row the read drew. `refresh()` exposes the
read in flight as a `reading` promise, cleared when it settles. The click handler sets a `writing` flag, disables the
button, waits while `reading` is set, looks the row up again and posts. A second click while one waits or posts is
dropped, so one click never becomes two toggles. The wait helper's 100 x 50 ms budget is unchanged.
The test (`board-held.test.mjs`, before the sign-out test). The fetch stub gains `window.__hold`: the next fetch of that
path waits until the test releases it. The test holds a Refresh's `/api/board` read, clicks Seen, checks no
`/api/seen` went out, releases the read, holds the POST, clicks again, releases, and checks the Seen count is 1 and
exactly one `/api/seen` followed the read. On bab069b3c it fails at the Seen count wait. On the candidate it passes.
A second flake, found by the acceptance loop. Run 2 of the first 10-run loop on the candidate failed in another test,
`instances-browser.test.mjs:17` (row 165), with `{"code":-32000,"message":"Inspected target navigated or closed"}`.
Its last step called `location.reload()` from an evaluate and then waited. The evaluate returns before the reload
commits, so under load the wait's evaluate starts on the old document and the reload kills it. A 300 ms delayed reload
gives the same error every time (`/mnt/storage/scratch/sage-r172/reload-probe-delayed.log`). It blocks this row's
acceptance and sits in the same package's tests, so the fix goes here: the step loads the page with `b.navigate` and a
different query, which waits for the new document. The loop restarts from run 1 after the fix.
## Acceptance
- The cause, its trace and the fix go in the candidate packet. The fix's test (or the changed test) fails on
d58c9c5cd under the traced condition and passes on the candidate.
bab069b3c under the traced condition and passes on the candidate.
- The webui suite passes 10 times in a row under the gate's load on the candidate, run by the gate owner.
- Full gate green on Sage's gate.