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:
@@ -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.
|
||||
|
||||
Reference in New Issue
Block a user