From 84a40d4492e8e0fcee17b9f026778a67d44b60ba Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gerg=C5=91=20T=C3=B6rcsv=C3=A1ri?= Date: Mon, 3 Aug 2026 11:05:10 +0200 Subject: [PATCH] diag(asyncify): write-time instrumentation + local warm-load repro findings MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The prod differential ladder finished: staged byte VOLUME on a warm load is the only trigger left (V1a siblings-without-lib-tables dies, V1b +120 files survives, V1c sibling KiCad files renamed byte-for-byte dies, V1d Leonardo + 123MB of inert markdown dies on loads 3-4; 14MB never dies). 3D models, collab/ydoc/presence, lib tables, sibling KiCad handling and file count are all exonerated — volume only loads the dice on the underlying race. That made the crash reproducible locally for the first time in six campaigns: a persistent browser profile + a 110MB project fails every warm load with the exact prod signature. Iteration is now ~12 minutes instead of a release cycle. Shim: every fiber switch now records the departing side's remaining asyncify buffer and its recorded rewind entry (rem=/rf=), which is what identified the unrewindable capture and disproved buffer overflow. The deferral family is closed for good — a microtask-deferred retry on a clean empty stack died identically to the nested rewind, because the suspension is broken at write time, not by nesting. Shell: log the origin stack when wx reports the top window destroyed. That notification fires from ~wxTopLevelWindowWasm for ANY top-level window, so a transient frame dying mid-load navigates the user out of the editor — a real bug in its own right, found while chasing the empty flight-recorder dumps. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_019SE4o46Lnq3hF574FFq8x4 --- docs/features/async/16-fiber-resume-guard.md | 101 +++++++++++++++++++ kicad | 2 +- scripts/common/shims/handlesleep.js | 43 +++++--- web/standalone/src/components/WasmTool.tsx | 5 + 4 files changed, 137 insertions(+), 14 deletions(-) diff --git a/docs/features/async/16-fiber-resume-guard.md b/docs/features/async/16-fiber-resume-guard.md index 476141d..c82ba1f 100644 --- a/docs/features/async/16-fiber-resume-guard.md +++ b/docs/features/async/16-fiber-resume-guard.md @@ -230,3 +230,104 @@ recording instead of a stack-shape puzzle. stay green (guard must not refuse valid suspensions). - Prod validation: watch for `jump-refused` beacons in the next crash-free Leonardo load — each one is a would-have-been crash. + +## Round 6 (2026-08-03): local repro at last, and the microtask deferral + +**The trigger was never a feature.** The prod differential ladder (V0–V4, +then V1a–V1d) exonerated every content theory one release at a time — 3D +models, sibling restage timing, collab/ydoc/presence (valid `?collab=0` +crashes), sibling lib-table/.kicad_pro surface (V1a: tables disabled, still +died), sibling KiCad-extension handling (V1c: extensions neutralized byte- +for-byte, still died), file count (V1b: +120 files, clean). What remained: +**staged byte volume × a warm load**, with dose-response — 140MB dies on +warm load 2, 123MB of *pure inert ballast* (V1d) dies on load 3–4, 14MB +never dies. Volume loads the dice; the defect was always the dual-protocol +race. + +**Local repro (first after 5+ failed campaigns):** seed the V1d ballast tree +into the local stack (`seed-from-dir.ts`, 110MB), then +`REPRO_PROFILE= repro-board-load.ts` — run 1 cold is clean, warm runs +2/3/4 crash with the exact prod signature (`fcsTotal=68 rootHotTotal=1`, +`currData=root+20`, state stuck Rewinding). 100% warm reproduction. + +**The frozen ring names the interleave.** On a crashed run the recorder +stops at the trap and retains the whole run. Healthy iterations: root parks +(`sleep s=0`), wakes ~8ms later, re-parks within ~3ms; ALL coroutine +round-trips run at `w=0` — fresh JS entries while root is parked. The kill: +one wake's forward slice runs 670ms (the volume-stretched settle work), and +*inside that live slice* a pending event dispatches a coroutine — +`fcs old=ROOT new=F w=1`, `fcs old=F new=ROOT w=1` — the only `w=1` pair in +the entire run. The return rewinds root+20 nested inside the wake's own +doRewind frame. rootHotTotal across many runs: 1 in crashed runs (the kill), +1–3 in green runs. **The "matches thousands per open" fear that retired the +deferral family was wrong on current code — the predicate is 1-per-crash +rare.** + +**Fix (third deferral variant — microtask, entry-side primary):** both +retired variants failed for macrotask reasons, not deferral reasons. +`setTimeout(0)` retries are background-tab throttled (the v0.1.24 hung +opens), and the macrotask gap lets a fresh timer entry launder root's +suspension slot before the retry (the Nano crash 22ms after `deferrals=1`). +A microtask retry runs after the current stack unwinds — past the hazardous +live doRewind frame — but before ANY timer/event can enter wasm: no +throttling, no laundering window, thousands would cost nothing. Predicate is +root-owned-wake-scoped (`__wakingRoot > 0`) on both sides: entry-side +(`old == root, new != root`) stops the fatal round-trip before the fiber +ever runs nested; return-side (`new == root`, v0.1.24's predicate) remains +as backup for laundered attributions. Chain cap (1000 microtask hops → +setTimeout) converts any pathological livelock into a macrotask hop instead +of starving the event loop. + +**Verification gate:** warm repro ×3 must survive with `deferrals≥1` and a +settled board; cold run clean; kicad e2e (collab + drift + park suites) and +web e2e green. + +### Round 6 corrections (same day, local iteration loop) + +**The microtask deferral trapped identically** — retried on a clean empty +stack at `w=0` and died in the same doRewind. The suspension is broken AT +WRITE TIME, not by nesting. Instrumentation (`rem=`/`rf=` on every fcs event) +then showed why: healthy fresh-entry root captures record their rewind entry +as the `dynCall_*` export they were taken under (~10KB of frames); the fatal +in-slice capture records **`rf=__main_argc_argv`** — `emscripten_fiber_swap` +stamps `Asyncify.exportCallStack[0]` (the re-invoked main export of the wake) +onto a 1.3KB capture of swap-site frames. Rewinding that pairing can never +work. Deferral family closed for good; prevention must run BEFORE +`_asyncify_start_unwind`. + +**Guard v1 (refuse `old==main && hot` in jump_fcontext) was aimed wrong**: the +only refusal it ever fired was a jump INTO main (`ctx=1`) — a fiber yield-back +flavor — and stranding that mid-yield cascaded into a genuine top-window +close (app quit, page reload; the "crash" became +`~wxTopLevelWindowWasm → wxAppTopWindowClosed → quit hook → teardown trap`). +fcsTotal read 66 = baseline 68 minus the never-completed fatal pair, so the +refused jump was part of the fatal chain itself. + +**Guard v2**: refuse only `old==main && new!=main && hot` (the doomed MAIN +suspension write); always allow jumps into main (they consume main's existing +suspension — fiber yield-backs, laundered-null attribution included); beacon +`jump-hot-into-main` observes the remaining hot flavors without refusing. + +### Round 6 verdict: refusal retracted, mechanism nailed + +Guard v2 (refuse `old==main && new!=main && hot`) fired exactly once per load, +on the right event, and the `unreachable executed` cascade vanished — the +doomed suspension was genuinely never written. The load still died: the +dropped dispatch strands the tool coroutine, the frame tears down, +`~wxTopLevelWindowWasm` fires the host quit notification (which the shell +reads as "user quit" and navigates away), and the teardown itself traps +`index out of bounds`. With the quit hook suppressed and navigation blocked, +the open reported `settled=true` but the page was the blue screen. Same dead +board, different obituary — so the refusal is retracted (kept as the +`hot-main-swap-out` beacon, which names the fatal interleave in any field log, +plus `jump-hot-into-main` for correlation). + +**Where this leaves the fix.** Vetoing the swap after the fact cannot work: +by then the only choices are "write an unrewindable suspension" or "drop a +dispatch the tool framework needs". The cure must stop main from swapping out +inside its own wake continuation at all — either by delivering wx events from +a fresh JS entry rather than inline in that continuation (a targeted requeue +at the dispatch site, unexplored), or by removing the dual-protocol nesting +entirely (design B, the fiber-first runtime). Everything needed to evaluate +either is now in place: a 100%-reproducible local warm-load repro and beacons +that name the exact event. diff --git a/kicad b/kicad index f0ce20e..4b18494 160000 --- a/kicad +++ b/kicad @@ -1 +1 @@ -Subproject commit f0ce20ef645059c7c8443626d6aa2b94a32e80cf +Subproject commit 4b1849424db8d3e0b0c5343b76034beafe106377 diff --git a/scripts/common/shims/handlesleep.js b/scripts/common/shims/handlesleep.js index 86d639c..2f39530 100644 --- a/scripts/common/shims/handlesleep.js +++ b/scripts/common/shims/handlesleep.js @@ -294,10 +294,26 @@ if (typeof Fibers !== "undefined" if (newFiber === Fibers.__rootFiber && (Asyncify.__inSleepWake || 0) > 0) { Fibers.__rootHotTotal = (Fibers.__rootHotTotal || 0) + 1; } + // rem = free bytes left in the old side's asyncify buffer after its unwind + // finished (asyncify_data layout: [data]=write ptr, [data+4]=buffer end). + // A deep capture that exhausts the 512K fiber buffer overflows SILENTLY in + // release — rem at/below 0 here is the smoking gun for an unrewindable + // suspension (the 2026-08-03 deferred-retry trap hypothesis). + var __remStr = ""; + if (Asyncify.currData) { + var __H = (typeof GROWABLE_HEAP_U32 === "function") ? GROWABLE_HEAP_U32() : HEAPU32; + __remStr = " rem=" + (__H[((Asyncify.currData + 4) >>> 2) >>> 0] - __H[(Asyncify.currData >>> 2) >>> 0]) + // The rewind entry recorded for this suspension (setDataRewindFunc + // wrote exportCallStack[0] at unwind start) vs the export stack NOW — + // a capture taken under a NESTED export whose recorded entry is the + // outer _main-style bottom is unrewindable (the 2026-08-03 trap). + + " rf=" + (Asyncify.getDataRewindFuncName ? Asyncify.getDataRewindFuncName(Asyncify.currData) : "?") + + " es=[" + (Asyncify.exportCallStack || []).join("|") + "]"; + } __fcsRec("fcs old=" + (Asyncify.currData ? Asyncify.currData - 20 : 0) + " new=" + newFiber + (newFiber === Fibers.__rootFiber ? " ROOT" : "") - + " w=" + (Asyncify.__inSleepWake || 0)); + + " w=" + (Asyncify.__inSleepWake || 0) + __remStr); // The swap that scheduled this switch just suspended its old fiber and // left currData = oldFiber+20 (fiber_swap's unwind path); record that // suspension as live — and a GENUINE swap-out also ends any internal @@ -331,18 +347,19 @@ if (typeof Fibers !== "undefined" var isRoot = newFiber === Fibers.__rootFiber; - // DEFERRAL RETIRED (2026-08-02, second retraction — see async/16 round 5). - // Both deferral variants are unsound: the main loop's every iteration runs - // INSIDE its yield-wake's synchronous extent, so "root re-entry during a - // root-owned wake" also matches every legit nested coroutine Call/return - // in a board open — v0.1.24 deferred thousands of them per load and the - // open crawled/hung (open:settled result=failed at the 60s escape, - // "hung forever" with a throttled background tab). The fatal interleave - // and the benign bulk share the same observable signature at this layer; - // the discriminator does not exist here. The rare nested-rewind crash is - // accepted until the fiber-first runtime (design B) removes the dual - // suspension protocols altogether; the recorder keeps every occurrence - // fully observable. + // DEFERRAL FAMILY CLOSED (2026-08-03, round 6 — the definitive finding). + // Deferral at this layer can never work: by the time finishContextSwitch + // runs, _asyncify_start_unwind has ALREADY written the suspension, and a + // root suspension captured inside main's own live wake window is broken + // AT WRITE TIME — emscripten_fiber_swap records the rewind entry as + // exportCallStack[0] (the re-invoked main export) while the capture only + // spans the swap-site frames (1.3KB vs a valid fresh-entry's ~10KB). A + // microtask-deferred retry on a clean empty stack trapped IDENTICALLY to + // the nested rewind. Prevention lives where it must: the libcontext C++ + // guard refuses the jump BEFORE the unwind starts (jump-refused-hot-main, + // keyed on __wakingRoot via EM_JS) — same ghost contract as the parked + // guard. The consume-once/quarantine checks below remain the backstop + // for laundered attributions the C++ layer cannot see. var HEAPU32v = (typeof GROWABLE_HEAP_U32 === "function") ? GROWABLE_HEAP_U32() : HEAPU32; var entryPoint = HEAPU32v[((newFiber + 12) >>> 2) >>> 0]; diff --git a/web/standalone/src/components/WasmTool.tsx b/web/standalone/src/components/WasmTool.tsx index 101bdd8..4a2ba96 100644 --- a/web/standalone/src/components/WasmTool.tsx +++ b/web/standalone/src/components/WasmTool.tsx @@ -454,6 +454,11 @@ function markDeliberateNavigation() { const quitDispatcher = () => { if (quitHandled) return; quitHandled = true; + // The wasm side only calls this when the app's top window is genuinely + // destroyed. When that happens unexpectedly (2026-08-03: a guarded-off + // settle-window dispatch cascaded into a silent frame close), the stack is + // the only artifact that says WHO closed it — keep it in every log. + console.warn("[quit] wxAppTopWindowClosed invoked — top window destroyed", new Error("quit-origin").stack); activeQuitHook?.(); };