|
| 1 | +# Smoke-all E2E deflake |
| 2 | + |
| 3 | +## Overview |
| 4 | + |
| 5 | +Nightly `smoke-all` E2E (`hub-client/e2e/smoke-all.spec.ts`) shows failures |
| 6 | +concentrated on specific fixtures, not a uniform slow-render tail (binomial |
| 7 | +test: observed 12 hard-fails vs 1.9 expected under i.i.d., p ≈ 8e-7). |
| 8 | + |
| 9 | +Two clusters dominate: |
| 10 | + |
| 11 | +- **A — shortcode/extension `[html]`**: every top failure expands a `{{< … >}}` |
| 12 | + shortcode (runs the WASM Lua interpreter). The multi-file extension fixtures |
| 13 | + (`block-shortcode` = 3 files, worst with 3 hard-fails) add a VFS-sync race on |
| 14 | + top: nothing gates the first render / the assertion re-render on all project |
| 15 | + files having synced into the VFS. `smoke-all.spec.ts` only *sorts* the target |
| 16 | + QMD last when creating docs server-side — a best-effort hint, not a barrier. |
| 17 | +- **B — `q2-preview`**: renders through the Q2PreviewIframe + postMessage path, |
| 18 | + asserting on post-render layout decoration (`header#title-block-header`, |
| 19 | + `div.quarto-title-meta`). The completion signal (`body.innerHTML.length > 0`, |
| 20 | + `previewExtraction.ts:72`) fires as soon as the body paragraph renders, before |
| 21 | + decoration lands. |
| 22 | + |
| 23 | +Shared amplifier: a too-weak "render done" signal checked against a fixed 75s |
| 24 | +deadline, on a 2-core CI runner. Mitigations already spent: `workers:1` for |
| 25 | +smoke-all, `retries:3`. |
| 26 | + |
| 27 | +## Root causes (harness-side, deterministic to fix) |
| 28 | + |
| 29 | +1. No VFS barrier: assertions can re-render against an incomplete VFS. |
| 30 | +2. Weak completion signal: `body.innerHTML.length > 0` ≠ "render complete". |
| 31 | +3. `ensureHtmlElements` live-iframe waits inherit the default expect timeout |
| 32 | + (5s), too short for a post-late-sync re-render under contention. |
| 33 | + |
| 34 | +## Checklist |
| 35 | + |
| 36 | +- [x] Set up worktree from main, reuse build artifacts (WASM, hub bin, node_modules) |
| 37 | +- [x] Build WASM from main source (toolchain ok); build app with VITE_E2E=1; build ts-packages dist |
| 38 | +- [x] Establish a local baseline run of the flaky subset (couldn't repro flake — 12 cores vs CI 2) |
| 39 | +- [x] Fix 1: VFS barrier helper (`waitForVfsFiles`) — poll `vfsListFiles()` until project files present |
| 40 | +- [x] Fix 1a: tolerate "WASM not initialized" throw while polling (barrier runs before first render) |
| 41 | +- [x] Fix 1b: make barrier best-effort (warn, not throw) — over-broad discovery in q2-preview/ fixtures |
| 42 | +- [x] Fix 2: single assertion render (`renderForAssertions`) — was 2 redundant WASM renders/test |
| 43 | +- [x] Fix 3: generous (30s) element-wait timeout for `ensureHtmlElements` |
| 44 | +- [x] Verify flaky subset passes locally, repeated x4, retries off → 28/28 pass |
| 45 | +- [x] Verify full smoke-all passes locally (single pass) → 78/78 |
| 46 | +- [x] Commit (e09005d7) + push #1 + CI run 27813896174 |
| 47 | +- [x] CI run #1 ballooned (>1hr) — barrier waited 30s on over-broad q2-preview fixtures; cancelled |
| 48 | +- [x] Redesign barrier: quiesce escape + 10s cap + 3s grace (26ab9810); 78/78 local, 3.4m |
| 49 | +- [x] Push #2 + CI run 27818252697 — in progress, watching smoke-all step |
| 50 | +- [x] Implement root-cause fix in sync client (6fc040e8): bound repo.find() |
| 51 | + with AbortSignal.timeout(5s) + load file docs concurrently (Promise.all) |
| 52 | +- [x] quarto-sync-client unit suite: 102 pass (no regression) |
| 53 | +- [x] no-contention smoke-all: 78/78, ~30% faster (2.4m vs 3.4m) |
| 54 | +- [x] heavy 10-hog contention (extension subset): ~all-fail → 2/15 |
| 55 | +- [ ] Confirm CI smoke-all green + fast; compare flake counts vs baseline |
| 56 | + |
| 57 | +## Fix + measurements (commit 6fc040e8) |
| 58 | + |
| 59 | +Root cause (proven by boot-trace): sync client `connect()` → |
| 60 | +`loadFileDocuments()` loaded ~49 file docs **serially**, and `findDoc()`'s |
| 61 | +`repo.find()` had **no deadline** → a single slow doc hung ~60s on |
| 62 | +automerge-repo's internal unavailable timeout → blew the 75s render budget → |
| 63 | +Editor/preview never mounted. (The extension fixtures share one ~49-file |
| 64 | +project because `extensions/_quarto.yml` roots them all there — more docs = |
| 65 | +higher odds of hitting a slow one, which is why they dominate the flaky list.) |
| 66 | + |
| 67 | +Fix: `AbortSignal.timeout(5s)` per `repo.find` attempt (degrades to the |
| 68 | +existing `markFileUnavailable` path) + concurrent `Promise.all` loading |
| 69 | +(wait bounded by the slowest doc, not the sum). |
| 70 | + |
| 71 | +| scenario | before fix | after fix | |
| 72 | +| --- | --- | --- | |
| 73 | +| no contention (full 78) | 78/78 (3.4m) | 78/78 (2.4m) | |
| 74 | +| 10-hog subset (×3) | ~all fail | 2/15 fail | |
| 75 | +| 6-hog subset (×3) | n/a | 2/18 fail | |
| 76 | +| 6-hog full (78) | 1 fail | 6 fail* | |
| 77 | + |
| 78 | +\* full-suite 6-hog amplified by the shared hub accumulating load over 78 |
| 79 | +tests (a test-infra factor, not the fix). All residual failures are still |
| 80 | +75s render-timeouts (connect slow), NOT dropped-file assertion failures — |
| 81 | +so the 5s timeout is not dropping needed docs. With CI `retries:3` an ~11% |
| 82 | +per-attempt rate → near-zero hard-fails. |
| 83 | + |
| 84 | +Residual / follow-ups (not done): (a) eager retry-on-peer-arrival for |
| 85 | +unavailable docs ("plan D2"); (b) don't block the render on non-active file |
| 86 | +docs (load active file + deps first, siblings in background) — the real |
| 87 | +structural fix for over-scoped projects; (c) the shared single hub across 78 |
| 88 | +e2e tests accumulates load — consider per-test isolation. |
| 89 | + |
| 90 | +## ROOT CAUSE (the real one) — render stalls under CPU contention |
| 91 | + |
| 92 | +Reproduced the CI failures locally by saturating cores (`yes >/dev/null` ×N |
| 93 | +on a 12-core machine; CI's 2 physical cores + vite+hub+chromium+playwright is |
| 94 | +comparably starved). Findings: |
| 95 | + |
| 96 | +- **6-hog (≈CI) full suite, retries off:** 77/78, the 1 failure is |
| 97 | + `block-shortcode` — `waitForPreviewRender` times out at 75s. |
| 98 | +- **10-hog full suite:** 8/78 fail, all `waitForPreviewRender` 75s timeouts |
| 99 | + (6 of them) + 1 blob-image element miss. Failures concentrate on the heaviest |
| 100 | + renders: Lua shortcode fixtures (`block-shortcode`, `builtin-kbd`) and |
| 101 | + `q2-preview` React renders. |
| 102 | +- **The 401 in the console is a RED HERRING** — it's the deliberate `/auth/me` |
| 103 | + stub (`projectFactory.ts:155 mockAuthMe`, no-auth test mode). It's collected |
| 104 | + for every test but only *printed* when a test fails, so it looked correlated. |
| 105 | +- **Slow vs stuck — decisive test:** bumped the render timeout 75s→150s and ran |
| 106 | + the shortcode fixtures under 8-hog contention. They **still timed out at the |
| 107 | + full 150000ms** (4/6). A render that completes in <2s uncontended does not |
| 108 | + finish in 150s under contention → **the render STALLS (livelock), it is not |
| 109 | + merely slow.** Bumping the timeout does nothing. |
| 110 | + |
| 111 | +**Conclusion: this is a render-pipeline bug, not a test-harness flake.** Under |
| 112 | +CPU contention the WASM render (worst for the Lua shortcode path and the |
| 113 | +q2-preview React path) stalls indefinitely. `retries:3` + `workers:1` is why |
| 114 | +it historically reads as *flaky* (a less-contended retry completes). No |
| 115 | +test-harness change can make a stalled render finish. This very likely also |
| 116 | +affects real hub-client users on loaded/slow machines. |
| 117 | + |
| 118 | +### Localized via render-trace instrumentation (then reverted) |
| 119 | + |
| 120 | +Added temporary `[render-trace]` console logs through Preview.tsx / |
| 121 | +PreviewRouter.tsx and captured them under 10-hog contention. Comparing a |
| 122 | +passing vs a failing run of `block-shortcode`: |
| 123 | + |
| 124 | +- **Passing:** whole boot < 1s — `PreviewRouter MOUNT → initWasm DONE ms=1 → |
| 125 | + Preview MOUNTED (contentLen=203) → render done 799ms`. |
| 126 | +- **Failing:** only `Preview.tsx MODULE LOADED` fires. **`PreviewRouter` never |
| 127 | + mounts.** No initWasm, no checkFormat, no render. |
| 128 | + |
| 129 | +So the three things we suspected are all RULED OUT: |
| 130 | +- WASM init is **1ms** (not the stall). |
| 131 | +- The WASM **render is 800ms** (not the stall) — it never even runs. |
| 132 | +- The Preview render loop / Lua path is never reached. |
| 133 | + |
| 134 | +**The stall is UPSTREAM of `PreviewRouter`** — in the app-shell boot → |
| 135 | +project-load → Editor-mount path, after the test's `page.goto(file URL)` |
| 136 | +(which re-boots the app: re-load bundle, re-connect ws, re-hydrate the |
| 137 | +Automerge project, route to file, mount Editor). A boot that normally takes |
| 138 | +<1s not reaching `PreviewRouter` in **75s** is a **75×+ slowdown = a livelock, |
| 139 | +not slowness.** |
| 140 | + |
| 141 | +Likely contributing factor (test-harness): the spec does |
| 142 | +`bootstrapProjectSet` + `seedProjectInBrowser` (waits for connected) and THEN a |
| 143 | +full `page.goto(file URL)` that **throws away that work and cold-boots the app |
| 144 | +again**. The cold boot under contention is what stalls. `retries:3` re-boots |
| 145 | +fresh each attempt → why it reads as flaky, not hard-fail. |
| 146 | + |
| 147 | +### ROOT CAUSE FOUND (boot-trace through App.tsx → sync client) |
| 148 | + |
| 149 | +Traced the boot path under 10-hog contention. The chain: |
| 150 | +`handleRouteChange` (App.tsx) → `connectAndLoadContents` → `connect` |
| 151 | +(automergeSync.ts) → sync client `connect()` → **`loadFileDocuments()`** |
| 152 | +(quarto-sync-client/src/client.ts:553). |
| 153 | + |
| 154 | +`loadFileDocuments` loads every project file doc **sequentially**, each via |
| 155 | +`findDoc()` → **`repo.find(docId)`** (client.ts:432). |
| 156 | + |
| 157 | +- **Passing run:** all ~49 file docs resolve in <2ms each → connect = 335ms. |
| 158 | +- **Failing run:** ONE file doc's `repo.find()` **hangs ~60s** (automerge-repo |
| 159 | + 2.5.6's default unavailable-doc timeout) before rejecting, then the retry |
| 160 | + loop (attempts=3, fast) gives up and `markFileUnavailable`s it. That single |
| 161 | + 60s serial stall blows the 75s `waitForPreviewRender` budget → test fails. |
| 162 | + Trace: `findDoc TbSuvu11 attempt=0` at t=764195 → `attempt=1` at t=824451 |
| 163 | + (exactly +60.2s). |
| 164 | + |
| 165 | +So the stall is **NOT** render, WASM init, the Preview loop, or the harness — |
| 166 | +it's the sync client waiting ~60s for any single project file doc that's slow |
| 167 | +to serve under contention, while loading all docs serially. Real users hit |
| 168 | +this too: opening a project where one doc is slow to sync stalls the whole |
| 169 | +open for 60s. |
| 170 | + |
| 171 | +**Fix surface (clean):** `repo.find<T>(id, options?: RepoFindOptions & |
| 172 | +AbortOptions)` accepts an `AbortSignal` (automerge-repo 2.5.6). Bound |
| 173 | +`findDoc`'s `repo.find` with `AbortSignal.timeout(N)` (e.g. 8s) so an unsynced |
| 174 | +doc fails fast into the existing `isUnavailableError`/retry/`markFileUnavailable` |
| 175 | +path instead of hanging 60s. Likely also: load file docs in parallel, and/or |
| 176 | +don't block the initial render on non-active file docs (load siblings in the |
| 177 | +background; re-subscribe via the index `change` handler when they arrive). |
| 178 | + |
| 179 | +**Design questions for the owner (why this is a checkpoint, not a blind edit):** |
| 180 | +- Marking a slow-but-coming doc "unavailable" makes the render proceed without |
| 181 | + it. Does the client reliably **re-load + re-render** when the doc finally |
| 182 | + syncs? (index `change` handler re-subscribes *new* files; does it retry |
| 183 | + known-unavailable ones?) If not, the active target doc timing out would turn |
| 184 | + a 60s flake into a wrong render. |
| 185 | +- The 60s is automerge-repo's own find timeout; bounding it changes |
| 186 | + offline/slow-sync semantics that `client.*.test.ts` pins. Needs the |
| 187 | + sync-client test suite run + review. |
| 188 | +- This touches shared infra used by real users, not just the e2e suite. |
| 189 | + |
| 190 | +## Runtime regression (CI run #1) — root cause + fix |
| 191 | + |
| 192 | +The first barrier waited up to 30s for ALL discovered project files. The |
| 193 | +~20 q2-preview/ fixtures over-include unrelated sibling-project files |
| 194 | +(no _quarto.yml at that dir → roots at parent) that sync slowly/never, so |
| 195 | +each paid the full 30s → smoke-all step ballooned far past its fast |
| 196 | +baseline. Fixed by bounding the barrier (commit 26ab9810): |
| 197 | +- return on exact-match (fast path) OR VFS-count quiesce (escape hatch); |
| 198 | +- cap 30s → 10s; |
| 199 | +- quiesce gated behind 3s grace + ~600ms stable run so it can't preempt a |
| 200 | + still-arriving extension fixture (files push target-last). |
| 201 | +Net: over-broad fixtures cost ~3s instead of 30s. |
| 202 | + |
| 203 | +## Findings / decisions |
| 204 | + |
| 205 | +- Local cannot reproduce the contention flake (12 cores). Fixes target the |
| 206 | + deterministic root causes; CI is the real validator. |
| 207 | +- The prebuilt WASM from another branch can't be reused: its generated |
| 208 | + `pkg/*.js` hardcodes a `ts-packages/wasm-js-bridge/src/*` path that drifts |
| 209 | + between branches → must `build:wasm` from the worktree's own source. |
| 210 | +- `build-wasm.js` step 2 (wasm-bindgen) ignores `CARGO_TARGET_DIR`; ran |
| 211 | + wasm-bindgen by hand against the shared-target artifact to avoid a recompile. |
| 212 | +- Discovery quirk (pre-existing, not fixed here): `q2-preview/` has no |
| 213 | + `_quarto.yml`, so single-file fixtures there root at the parent and pull in |
| 214 | + unrelated sibling-project files. Best-effort barrier sidesteps it; worth a |
| 215 | + follow-up to add a `q2-preview/_quarto.yml` or tighten discovery. |
| 216 | +- Must clean up stray hub (port 3031) + `/tmp/hub-e2e-server.json` between runs |
| 217 | + or globalSetup fails with ENOENT. |
| 218 | + |
| 219 | +## Notes |
| 220 | + |
| 221 | +- Harness `.ts` files run in the Playwright node process, NOT the vite bundle — |
| 222 | + iterating on them does NOT require rebuilding WASM/dist. One good app build suffices. |
| 223 | +- Local = 12 cores; CI = 2. Contention-driven flake may not reproduce locally; |
| 224 | + fixes target the deterministic root causes (barrier, completion signal). |
| 225 | +- CI lever: `gh workflow run hub-client-e2e.yml -f run-smoke-all=true`. |
0 commit comments