8ed39a72a0Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01Td4ujboGuAw26jvbDQzehj
351 lines
14 KiB
TypeScript
351 lines
14 KiB
TypeScript
import type { Page } from "@playwright/test";
|
||
import { test, expect } from "./fixtures";
|
||
import { expectGuardsSilent } from "./utils/guard-beacons";
|
||
|
||
/**
|
||
* Timer-park concurrent-Asyncify repro (gal-refresh-timer investigation).
|
||
*
|
||
* The prod trap ("index out of bounds" + "unreachable executed" in doRewind,
|
||
* v0.1.17–19, still un-reproduced naturally): a wx timer callback is a FRESH
|
||
* JS→wasm entry (emscripten_async_call → TimerCallbackFunc::Run → Notify()),
|
||
* and the main loop spends most wall-clock time Asyncify-parked inside
|
||
* wxWasmYieldToBrowser. A timer handler that itself parks therefore creates
|
||
* TWO live Asyncify contexts over the single-slot `Asyncify.currData` — the
|
||
* emscripten #9153 family that the scheduler shim
|
||
* (scripts/common/shims/asyncify-scheduler.js) silently repairs. The collab entries add the third ingredient: they run on
|
||
* TOOL_MANAGER coroutines (emscripten_fiber_swap), which bypass the shim's
|
||
* allocateData accounting entirely — and `finishContextSwitch` is exactly
|
||
* where the prod trap's second stack dies.
|
||
*
|
||
* The natural trigger needs a timer handler that parks mid-paint
|
||
* (scheduler-dependent; never hit locally). `kicadTestArmTimerPark` makes the
|
||
* window deterministic: a one-shot wx timer whose Notify() emscripten_sleep()s
|
||
* for a fixed time. Three escalating cycles:
|
||
*
|
||
* 1. timer park alone (timer chain × main-loop yield park)
|
||
* 2. + collab entry hammering (adds fiber swaps through the window)
|
||
* 3. same again (interleaving lottery, second draw)
|
||
*
|
||
* The spec asserts the runtime SURVIVES every cycle — on a build where the
|
||
* hypothesis holds this is deterministically RED, and after the real fix it
|
||
* is the regression gate.
|
||
*
|
||
* RE-PINNED AT THE FLIP (docs/features/async/22 §10, 2026-08-08): the staged
|
||
* overlap needed the main loop's per-frame in-place park, which D5 removed.
|
||
* The final assert now pins ZERO observable concurrent-park windows — the
|
||
* post-migration invariant — instead of demanding the overlap engage.
|
||
*/
|
||
|
||
const SEG_TARGET = "fa220000-0000-0000-0000-00000000cafe";
|
||
const PROBE_HOME = "10000000,10000000"; // on-disk position (IU)
|
||
|
||
/** Compact deterministic board — enough items for a real snapshot walk. */
|
||
function board(): string {
|
||
const lines: string[] = [];
|
||
lines.push("(kicad_pcb");
|
||
lines.push("\t(version 20241229)");
|
||
lines.push('\t(generator "pcbnew")');
|
||
lines.push('\t(generator_version "9.0")');
|
||
lines.push("\t(general (thickness 1.6))");
|
||
lines.push('\t(paper "A4")');
|
||
lines.push("\t(layers");
|
||
lines.push('\t\t(0 "F.Cu" signal)');
|
||
lines.push('\t\t(2 "B.Cu" signal)');
|
||
lines.push('\t\t(25 "Edge.Cuts" user)');
|
||
lines.push("\t)");
|
||
lines.push("\t(setup)");
|
||
lines.push('\t(net 0 "")');
|
||
const uuid = (n: number) =>
|
||
`fa2${(n + 1).toString(16).padStart(5, "0")}-0000-0000-0000-000000000000`;
|
||
let n = 0;
|
||
for (let i = 0; i < 2000; i++) {
|
||
const x = 20 + (i % 100) * 1.5;
|
||
const y = 20 + Math.floor(i / 100) * 1;
|
||
lines.push(
|
||
`\t(segment (start ${x} ${y}) (end ${x + 1.2} ${y}) (width 0.2) (layer "F.Cu") (net 0) (uuid "${uuid(n++)}"))`,
|
||
);
|
||
}
|
||
lines.push(
|
||
`\t(segment (start 10 10) (end 15 10) (width 0.2) (layer "F.Cu") (net 0) (uuid "${SEG_TARGET}"))`,
|
||
);
|
||
lines.push(")");
|
||
return lines.join("\n");
|
||
}
|
||
|
||
type Mod = {
|
||
kicadOpenFile(p: string): unknown;
|
||
kicadOpenFileBusy(): boolean;
|
||
kicadTestArmTimerPark(delayMs: number, parkMs: number): boolean;
|
||
kicadTestTimerParkState(): string;
|
||
kicadCollabSnapshotItems(): string;
|
||
kicadCollabApply(j: string): unknown;
|
||
kicadCollabGetPos(id: string): string;
|
||
};
|
||
|
||
interface CycleStats {
|
||
armed: boolean;
|
||
fired: boolean;
|
||
done: boolean;
|
||
sawParked: boolean;
|
||
hammerIters: number;
|
||
/** Bytes the wasm heap grew mid-park (growHeap cycles; 0 = no growth). */
|
||
grewBytes: number;
|
||
errors: string[];
|
||
elapsedMs: number;
|
||
}
|
||
|
||
const TRAP_SIGNATURE =
|
||
/Aborted\(|index out of bounds|unreachable executed|indirect call signature|null function or function signature|memory access out of bounds/;
|
||
|
||
async function bootHarness(page: Page): Promise<void> {
|
||
await page.goto("/kicad/pcbnew-collab.html");
|
||
await expect(page.locator("#canvas")).toBeVisible({ timeout: 90000 });
|
||
await page.waitForFunction(() => !!window.wxElementRegistry, null, { timeout: 90000 });
|
||
await page.waitForFunction(
|
||
() => {
|
||
const m = (window as unknown as { Module?: Partial<Mod> }).Module;
|
||
return (
|
||
typeof m?.kicadOpenFile === "function" &&
|
||
typeof m?.kicadCollabSnapshotItems === "function" &&
|
||
typeof m?.kicadTestArmTimerPark === "function"
|
||
);
|
||
},
|
||
null,
|
||
{ timeout: 90000 },
|
||
);
|
||
await page.waitForFunction(
|
||
() =>
|
||
!!window.wxElementRegistry &&
|
||
window.wxElementRegistry
|
||
.findAll({ visible: true })
|
||
.some((e) => /Frame$/.test(e.typeName) || (e.name || "").endsWith("Frame")),
|
||
null,
|
||
{ timeout: 90000 },
|
||
);
|
||
}
|
||
|
||
/** Open the board and poll until the open chain truly settles. */
|
||
async function openAndSettle(page: Page, content: string): Promise<void> {
|
||
await page.evaluate((c) => {
|
||
const w = window as unknown as {
|
||
FS: { mkdirTree(p: string): void; writeFile(p: string, d: string): void };
|
||
Module: Mod;
|
||
};
|
||
const dir = "/home/kicad/documents";
|
||
try {
|
||
w.FS.mkdirTree(dir);
|
||
} catch {
|
||
/* exists */
|
||
}
|
||
w.FS.writeFile(`${dir}/timerpark.kicad_pcb`, c);
|
||
w.Module.kicadOpenFile(`${dir}/timerpark.kicad_pcb`);
|
||
}, content);
|
||
await expect
|
||
.poll(
|
||
() => page.evaluate(() => (window.Module as unknown as Mod).kicadOpenFileBusy()),
|
||
{ timeout: 120000, intervals: [250] },
|
||
)
|
||
.toBe(false);
|
||
}
|
||
|
||
/**
|
||
* One repro cycle in-page: arm the parking timer, then poll its state until
|
||
* the park completes — optionally hammering the fiber-based collab entries
|
||
* through the window (the prod settle fan-out shape). Every embind entry here
|
||
* runs while the timer chain is Asyncify-parked and the main loop's yield
|
||
* park keeps cycling: the exact concurrent-context interleaving under test.
|
||
*/
|
||
async function armAndRide(
|
||
page: Page,
|
||
opts: { parkMs: number; hammer: boolean; growHeap?: boolean },
|
||
): Promise<CycleStats> {
|
||
return page.evaluate(async ({ parkMs, hammer, growHeap }) => {
|
||
const m = (window as unknown as { Module: Mod }).Module;
|
||
const before = JSON.parse(m.kicadTestTimerParkState()) as { fired: number; done: number };
|
||
const stats = {
|
||
armed: false,
|
||
fired: false,
|
||
done: false,
|
||
sawParked: false,
|
||
hammerIters: 0,
|
||
grewBytes: 0,
|
||
errors: [] as string[],
|
||
elapsedMs: 0,
|
||
};
|
||
if (!m.kicadTestArmTimerPark(30, parkMs)) return stats;
|
||
stats.armed = true;
|
||
|
||
const t0 = performance.now();
|
||
// Bound = park length + generous rewind budget; exits on completion.
|
||
while (performance.now() - t0 < parkMs + 20000) {
|
||
try {
|
||
const st = JSON.parse(m.kicadTestTimerParkState()) as {
|
||
fired: number;
|
||
done: number;
|
||
parked: boolean;
|
||
};
|
||
if (st.fired > before.fired) stats.fired = true;
|
||
if (st.parked) stats.sawParked = true;
|
||
if (st.done > before.done) {
|
||
stats.done = true;
|
||
break;
|
||
}
|
||
} catch (e) {
|
||
stats.errors.push(`state poll: ${String(e)}`);
|
||
break;
|
||
}
|
||
// Heap growth mid-park (prod trace: `stage:done … GREW +187MB`): growth
|
||
// detaches every JS heap view; a stale view held across it is one of
|
||
// the few mechanisms that yields a bad function-table index LATER.
|
||
// 256 MB per shot, deliberately leaked — the asyncify buffers of the
|
||
// parked chains live in linear memory on both sides of the boundary.
|
||
if (stats.fired && growHeap && !stats.grewBytes) {
|
||
const alloc = (
|
||
m as unknown as { ___libc_malloc?: (n: number) => number }
|
||
).___libc_malloc;
|
||
if (typeof alloc === "function") {
|
||
const before = (window as unknown as { Module: { HEAPU8: Uint8Array } }).Module
|
||
.HEAPU8.byteLength;
|
||
alloc(256 * 1024 * 1024);
|
||
const after = (window as unknown as { Module: { HEAPU8: Uint8Array } }).Module
|
||
.HEAPU8.byteLength;
|
||
stats.grewBytes = after - before;
|
||
} else {
|
||
stats.errors.push("growHeap: ___libc_malloc not exported");
|
||
}
|
||
}
|
||
if (stats.fired && hammer) {
|
||
for (const [name, fn] of [
|
||
["snapshotItems", () => m.kicadCollabSnapshotItems()],
|
||
["getPos", () => m.kicadCollabGetPos("fa220000-0000-0000-0000-00000000cafe")],
|
||
] as const) {
|
||
try {
|
||
fn();
|
||
stats.hammerIters++;
|
||
} catch (e) {
|
||
stats.errors.push(`${name} during park: ${String(e)}`);
|
||
}
|
||
}
|
||
}
|
||
await new Promise((r) => setTimeout(r, 10));
|
||
}
|
||
stats.elapsedMs = Math.round(performance.now() - t0);
|
||
return stats;
|
||
}, opts);
|
||
}
|
||
|
||
test.describe("timer Notify() Asyncify-park during main-loop yield (concurrent currData)", () => {
|
||
test("runtime survives a parking timer handler, alone and under fiber hammering", async ({
|
||
page,
|
||
testLogger,
|
||
}) => {
|
||
test.setTimeout(300000);
|
||
await bootHarness(page);
|
||
await openAndSettle(page, board());
|
||
|
||
const cycles: Array<{ label: string; hammer: boolean; growHeap?: boolean }> = [
|
||
{ label: "park only", hammer: false },
|
||
{ label: "park + fiber hammer", hammer: true },
|
||
{ label: "park + fiber hammer (2nd draw)", hammer: true },
|
||
// Prod trace showed `GREW +187MB` on the crashing load: growth detaches
|
||
// every JS heap view while TWO chains are parked (timer + main-loop
|
||
// yield) and fibers swap through — the stale-view stale-buffer scenario.
|
||
{ label: "park + heap growth + fiber hammer", hammer: true, growHeap: true },
|
||
];
|
||
for (const { label, hammer, growHeap } of cycles) {
|
||
const stats = await armAndRide(page, { parkMs: 1500, hammer, growHeap });
|
||
console.log(
|
||
`[TEST] ${label}: fired=${stats.fired} done=${stats.done} parked=${stats.sawParked} ` +
|
||
`hammerIters=${stats.hammerIters} grew=${stats.grewBytes} ` +
|
||
`elapsed=${stats.elapsedMs}ms errors=${stats.errors.length}`,
|
||
);
|
||
expect(stats.armed, `${label}: timer armed`).toBe(true);
|
||
expect(stats.fired, `${label}: Notify() entered`).toBe(true);
|
||
expect(stats.sawParked, `${label}: the park window engaged`).toBe(true);
|
||
expect(stats.done, `${label}: Notify() survived its park and rewound`).toBe(true);
|
||
expect(stats.errors, `${label}: no embind entry trapped`).toEqual([]);
|
||
if (growHeap) {
|
||
expect(stats.grewBytes, `${label}: the heap actually grew mid-park`).toBeGreaterThan(0);
|
||
}
|
||
}
|
||
|
||
// The runtime is still fully functional: snapshots walk the board and a
|
||
// real apply lands (a poisoned Asyncify state fails one of these first).
|
||
const itemCount = await page.evaluate(
|
||
() =>
|
||
JSON.parse((window.Module as unknown as Mod).kicadCollabSnapshotItems()).added.length,
|
||
);
|
||
expect(itemCount, "post-cycle snapshot sees the board").toBeGreaterThan(2000);
|
||
await page.evaluate(
|
||
(id) =>
|
||
(window.Module as unknown as Mod).kicadCollabApply(
|
||
JSON.stringify({
|
||
added: [],
|
||
changed: [
|
||
{
|
||
id,
|
||
type: "PCB_TRACK",
|
||
sx: 12_000_000,
|
||
sy: 34_000_000,
|
||
ex: 17_000_000,
|
||
ey: 34_000_000,
|
||
width: 200000,
|
||
},
|
||
],
|
||
removed: [],
|
||
}),
|
||
),
|
||
SEG_TARGET,
|
||
);
|
||
await expect
|
||
.poll(
|
||
() =>
|
||
page.evaluate(
|
||
(id) => (window.Module as unknown as Mod).kicadCollabGetPos(id),
|
||
SEG_TARGET,
|
||
),
|
||
{ timeout: 10000, intervals: [200] },
|
||
)
|
||
.toBe("12000000,34000000");
|
||
|
||
// Console-level trap sweep: the prod signatures must not have appeared
|
||
// anywhere (the page survives some of them as "Uncaught" noise).
|
||
const trapLines = [...testLogger.consoleLogs, ...testLogger.errors].filter((l) =>
|
||
TRAP_SIGNATURE.test(l),
|
||
);
|
||
expect(trapLines, "no wasm trap signature anywhere in the run").toEqual([]);
|
||
|
||
// Doc 17 S1 tripwire (arms itself when the wasm ships the C mailbox lane,
|
||
// detected via the wxWasmMailboxTick export): timers are then delivered
|
||
// from the mailbox only when the interlock is free, so the legacy 17 ms
|
||
// parked-retry path must be SILENT. On legacy wasm this is skipped — the
|
||
// retry storm there is expected and covered by the assertions above.
|
||
// Both halves must be present: the wasm export (C lane compiled in) AND
|
||
// the shim (variant injected) — a C-lane wasm on legacy glue keeps legacy
|
||
// timer semantics, and its retry storms are expected.
|
||
const cLane = await page.evaluate(
|
||
() =>
|
||
typeof (window.Module as unknown as { _wxWasmMailboxTick?: unknown })
|
||
._wxWasmMailboxTick === "function" &&
|
||
!!(globalThis as unknown as { __wxScheduler?: unknown }).__wxScheduler,
|
||
);
|
||
if (cLane) expectGuardsSilent(testLogger.consoleLogs, ["timerRetry"]);
|
||
|
||
// RE-PINNED AT THE FLIP (docs/features/async/22 §10, 2026-08-08). This
|
||
// lever staged "timer park × MAIN-LOOP YIELD PARK", and D5 removed the
|
||
// main loop's per-frame in-place park — the overlap is structurally
|
||
// impossible now, so "the shim observed the window" (>0) can never pass
|
||
// again. The pin flips to the invariant the migration exists to
|
||
// establish: the lever runs, the park survives (asserted above), and NO
|
||
// concurrent-park window is observable at all.
|
||
const overlapLines = testLogger.consoleLogs.filter((l) =>
|
||
/\[wx-asyncify\] (concurrent-park|aliased-wake-live|overlapped-wake)/.test(l),
|
||
);
|
||
console.log(`[TEST] overlap beacons: ${overlapLines.length} line(s)`);
|
||
for (const l of overlapLines.slice(0, 10)) console.log(`[TEST] ${l}`);
|
||
expect(
|
||
overlapLines.length,
|
||
"no concurrent-park window is observable post-flip",
|
||
).toBe(0);
|
||
});
|
||
});
|