Skip to content

Commit c1b239d

Browse files
fengzhi09s39-dev
andauthored
fix(test): a millisecond boundary was deciding whether run-mirror passed (#132)
Two races, not a slow machine. The suite counted chat lines including the turn's "§§ processed_duration" row, but that row is only written when durationMs > 0 and the fake transport resolves inside a single tick — whether the tail crosses a millisecond boundary is a coin flip nobody controls. stable() already strips that row for content comparisons; the length assertion walked straight past it. Then the failure amplified. beginRun/endRun is a process-level registry and the file waits on a global activeRunCount() === 0, so when the first test left turn2 on the fake transport the route never reached its finally { endRun(cid) }, runsByCid kept the entry, and every later test burned its full 2s budget without reaching an assertion. One real failure became eight red and 14.4 seconds — which is exactly the shape the macOS log shows, and exactly why it read as "macOS is slow, raise the budget". Raising it would have produced the same cascade in 30 seconds instead. durable() strips that metadata row while keeping ##tc:, whose position is itself a contract. An afterEach drains the new-session gate and awaits the turns it tracked — awaiting matters, because a missed finalize persists after the next test has already cleared the store. 10/10 clean, and 10/10 clean again under nice plus 14 CPU burners. Co-authored-by: s39-dev <s39-dev@local>
1 parent 0e99b45 commit c1b239d

1 file changed

Lines changed: 105 additions & 21 deletions

File tree

‎packages/webui/test/routes/chat-run-mirror.check.mjs‎

Lines changed: 105 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -39,7 +39,7 @@
3939
// record (captured owning webui id) is promoted and receives the
4040
// turn — never the record the user switched to.
4141

42-
import { test, describe, before, beforeEach, after } from "node:test";
42+
import { test, describe, before, beforeEach, afterEach, after } from "node:test";
4343
import assert from "node:assert/strict";
4444
import { Readable } from "node:stream";
4545
import {rmSync} from "node:fs";
@@ -230,6 +230,59 @@ async function waitFor(fn, what, timeoutMs = 2000) {
230230
}
231231
}
232232

233+
// ------------------------------------------------------------------
234+
// Turn bookkeeping — a test must never abandon a live turn.
235+
//
236+
// `beginRun` / `endRun` keep a PROCESS-WIDE registry (the cid claim plus
237+
// the engine-session claim), and `activeRunCount()` reads it globally. A
238+
// test that aborts mid-turn — any assertion failure between `handleSend`
239+
// and the finalize — leaves that turn parked on the fake transport: the
240+
// route never reaches its `finally { endRun(cid) }`, the claim for the
241+
// cid and for `mvs_fake_N` stays registered, and the run buffer for the
242+
// cid stays seeded. The next test's `waitFor(activeRunCount() === 0)`
243+
// can then never be satisfied, so a single real failure used to cascade
244+
// into EVERY following test, each burning its full 2s budget: one flake
245+
// became eight red tests and a 14s run, which is what made this file look
246+
// like a "slow machine" problem in the CI logs.
247+
//
248+
// `trackTurn` therefore registers every turn this file starts, and
249+
// `afterEach` unblocks and drains whatever is still parked before the next
250+
// test's `beforeEach` throws the state away. The cleanup is a safety net,
251+
// not the assertion: a leak still fails the test that caused it.
252+
// ------------------------------------------------------------------
253+
const liveTurns = new Set();
254+
255+
/** Register the promise `handleSend` returns so `afterEach` can drain it. */
256+
function trackTurn(turn) {
257+
liveTurns.add(turn);
258+
// `.then` with both arms (not `.finally`) so a rejecting turn settles
259+
// the derived promise too — an unobserved rejection would crash the run.
260+
turn.then(
261+
() => liveTurns.delete(turn),
262+
() => liveTurns.delete(turn),
263+
);
264+
return turn;
265+
}
266+
267+
// The draft case parks a turn inside `session/new`, before any prompt
268+
// exists; releasing `pending` is not enough to let that turn finish.
269+
let newSessionReleaser = null;
270+
271+
/** Park every subsequent `session/new` until the cleanup or the test says so. */
272+
function gateNewSession() {
273+
FakeMcodeAcpClient.newSessionGate = () =>
274+
new Promise((r) => {
275+
newSessionReleaser = r;
276+
});
277+
}
278+
279+
/** Unblock a parked `session/new` (idempotent). */
280+
function releaseNewSessionGate() {
281+
const releaser = newSessionReleaser;
282+
newSessionReleaser = null;
283+
if (releaser) releaser();
284+
}
285+
233286
const WS = _tmpDataDir; // mkdtempSync already created the leaf — assertWorkspacePath's realpathSync requires an existing path.
234287

235288
function makeClient(cid, { sessionId = null, mcodeSessionId = null } = {}) {
@@ -273,6 +326,22 @@ const stable = (chat) =>
273326
return !s.startsWith("§§") && !s.startsWith("##tc:");
274327
});
275328

329+
// Same idea as `stable()`, but it keeps the `##tc:` marker — that marker's
330+
// POSITION is part of the contract, so counting lines must still see it —
331+
// and drops only `§§ processed_duration=Nms`.
332+
//
333+
// Why that one line cannot be counted: `mcode-acp.js#finalize` writes the
334+
// duration marker only when the turn took at least one whole millisecond
335+
// (`if (r.durationMs > 0)`), and `r.durationMs` is `Date.now() - t0`
336+
// measured across a fake transport that settles inside a single tick. So
337+
// the marker is present or absent depending on whether the event loop
338+
// crossed a millisecond boundary between the prompt starting and the turn
339+
// settling — a coin flip the test does not control, measured at 2 runs in
340+
// 5 on a warm local machine. `stable()` already hides the line from the
341+
// content comparisons; `durable()` hides it from the line COUNT.
342+
const durable = (chat) =>
343+
(chat || []).filter((line) => !String(line).startsWith("§§ processed_duration"));
344+
276345
before(async (t) => {
277346
await setupMocks(t);
278347
sb = await import(absPath("lib/state-bus.js"));
@@ -295,6 +364,23 @@ beforeEach(() => {
295364
FakeMcodeAcpClient.reset();
296365
});
297366

367+
// Runs after EVERY test, including one that failed or threw — which is
368+
// precisely the case that used to leak. The wait is bounded so a turn that
369+
// cannot be unblocked reports its own failure instead of hanging the file.
370+
afterEach(async () => {
371+
releaseNewSessionGate();
372+
while (FakeMcodeAcpClient.pending.length) FakeMcodeAcpClient.release();
373+
if (liveTurns.size === 0) return;
374+
const drained = Promise.allSettled([...liveTurns]);
375+
let timer;
376+
await Promise.race([
377+
drained,
378+
new Promise((r) => { timer = setTimeout(r, 5000); }),
379+
]);
380+
clearTimeout(timer);
381+
liveTurns.clear();
382+
});
383+
298384
after(() => {
299385
try {
300386
rmSync(_tmpDataDir, { recursive: true, force: true });
@@ -313,7 +399,7 @@ async function setupTwoSessions(cid) {
313399
// Turn 1 — completes immediately; promotes the A record to the
314400
// engine identity (id → mvs_fake_1) and persists ["› hello", "● ok"].
315401
const res1 = fakeRes();
316-
const turn1 = handleSend(fakeReq({ content: "hello" }), res1, { cs, cid });
402+
const turn1 = trackTurn(handleSend(fakeReq({ content: "hello" }), res1, { cs, cid }));
317403
await waitFor(() => cs.mcodeSessionId, "turn 1 to bind the engine sid");
318404
FakeMcodeAcpClient.release();
319405
await turn1;
@@ -344,7 +430,7 @@ describe("run-mirror — mid-run switch keeps views and records isolated", () =>
344430
const { cs, sidA } = await setupTwoSessions(cid);
345431

346432
const res2 = fakeRes();
347-
const turn2 = handleSend(fakeReq({ content: "run A2" }), res2, { cs, cid });
433+
const turn2 = trackTurn(handleSend(fakeReq({ content: "run A2" }), res2, { cs, cid }));
348434
await waitFor(
349435
() => FakeMcodeAcpClient.pending.length === 1,
350436
"turn 2 prompt to park",
@@ -396,14 +482,16 @@ describe("run-mirror — mid-run switch keeps views and records isolated", () =>
396482
true,
397483
"owning view keeps its running indicator after switch-back",
398484
);
399-
// base (3 persisted lines) + the 6 buffered stream lines so far
400-
// (▲ pondering, → Bash header, status line, output line, ● line)
401-
// — plus the slice-06 `##tc:<id>` marker that precedes the tool
402-
// header. The marker is consumed by the decoder and never
403-
// appears in the rendered chat body; it only inflates the raw
404-
// buffer length. Filtering it via `stable()` would drop it
405-
// here too — see `stable()`'s docstring.
406-
assert.equal(backSnap.chat.length, 10);
485+
// 3 persisted base lines (› hello, ● ok, › run A2) + the 6 buffered
486+
// stream lines so far: ▲ pondering, the slice-06 `##tc:<id>` marker,
487+
// the → Bash header, the status line, the output line and the ● line.
488+
// The marker is consumed by the decoder and never appears in the
489+
// rendered chat body; it only inflates the raw buffer length, so the
490+
// count must see it (`stable()` would drop it — see `stable()`), while
491+
// turn 1's duration marker must not (`durable()` drops it — see
492+
// `durable()`, and .tickets/webui-parity/90-chat-run-mirror-flaky.md
493+
// for the 10-vs-9 flake this assertion used to carry).
494+
assert.equal(durable(backSnap.chat).length, 9);
407495
assert.deepEqual(
408496
stable(backSnap.chat).slice(0, 3),
409497
["› hello", "● ok", "› run A2"],
@@ -447,7 +535,7 @@ describe("run-mirror — mid-run switch keeps views and records isolated", () =>
447535
const { cs, sidA } = await setupTwoSessions(cid);
448536

449537
const res2 = fakeRes();
450-
const turn2 = handleSend(fakeReq({ content: "run A2" }), res2, { cs, cid });
538+
const turn2 = trackTurn(handleSend(fakeReq({ content: "run A2" }), res2, { cs, cid }));
451539
await waitFor(() => FakeMcodeAcpClient.pending.length === 1, "prompt parked");
452540
emitThought();
453541
emitToolAndAnswer();
@@ -506,30 +594,26 @@ describe("run-mirror — mid-run switch keeps views and records isolated", () =>
506594

507595
test("first turn on a draft with a pre-bind switch: the DRAFT record is promoted and receives the turn, not the switched-to session", async () => {
508596
const cid = "cid-draft-switch";
509-
let releaseNewSession;
510-
FakeMcodeAcpClient.newSessionGate = () =>
511-
new Promise((r) => {
512-
releaseNewSession = r;
513-
});
597+
gateNewSession();
514598

515599
const cs = makeClient(cid); // brand-new: no sessionId, no sid
516600
storeRecord("sess-B", []);
517601

518602
const res1 = fakeRes();
519-
const turn1 = handleSend(fakeReq({ content: "first!" }), res1, { cs, cid });
603+
const turn1 = trackTurn(handleSend(fakeReq({ content: "first!" }), res1, { cs, cid }));
520604
// handleSend created the draft record; the turn is parked BEFORE the
521605
// engine session id exists (inside session/new).
522606
await waitFor(() => cs.sessionId, "draft record created");
523607
const draftId = cs.sessionId;
524608
assert.ok(draftId && draftId !== "sess-B");
525-
await waitFor(() => releaseNewSession, "turn parked inside session/new");
609+
await waitFor(() => newSessionReleaser, "turn parked inside session/new");
526610

527611
// User switches away BEFORE the bind ran.
528612
await handleSwitchSession(fakeReq({ id: "sess-B" }), fakeRes(), { cs, cid });
529613
assert.equal(cs.sessionId, "sess-B");
530614
assert.equal(cs.mcodeSessionId, null);
531615

532-
releaseNewSession();
616+
releaseNewSessionGate();
533617

534618
// The DRAFT record (found via its preserved `›` line) got the engine
535619
// binding and was promoted (id = mvs sid); the switched-to record was
@@ -600,7 +684,7 @@ describe("finalize writes the turn coordinate into the transcript", () => {
600684
async function runTurn(cid, { sessionId, answer, lastAssistantMessageId }) {
601685
const cs = makeClient(cid, { sessionId });
602686
storeRecord(sessionId, []);
603-
const turn = handleSend(fakeReq({ content: "改一下文件" }), fakeRes(), { cs, cid });
687+
const turn = trackTurn(handleSend(fakeReq({ content: "改一下文件" }), fakeRes(), { cs, cid }));
604688
await waitFor(() => cs.mcodeSessionId, "the engine sid to bind");
605689
await waitFor(() => FakeMcodeAcpClient.pending.length === 1, "prompt parked");
606690
FakeMcodeAcpClient.emit({ kind: "message", text: answer });

0 commit comments

Comments
 (0)