From 0f0006f40e80aebcd5154079db08a35604b40665 Mon Sep 17 00:00:00 2001 From: Day Dreamer <87640074+HugoXK@users.noreply.github.com> Date: Fri, 23 Oct 2026 16:57:45 +0800 Subject: [PATCH] fix(test): drive follow-through waits from the mocked clock (#821) `settle` spun on setImmediate against a wall-clock 3 s deadline while the case mocked `setTimeout`, so a wait that needed a tick could never progress on a loaded runner and reported "condition not reached" for a green PR (Test run 39917377405 attempt 1, head f027324e) that passed on rerun. One `mockTimers(t)` helper now enables the mocked clock and registers it, and `settle` advances that clock in bounded rounds, so no wait in the file races wall time. The cleared-note wait in the failing case no longer asserts inside the helper: the following assertion judges the write, so removing it fails on "the exchange a turn took up is still noted on disk". Regenerated patches/ds-bot/0001-core-fixes.patch. --- core/test/follow-through.test.js | 49 +++++++++------ patches/ds-bot/0001-core-fixes.patch | 90 +++++++++++++++++++++++----- 2 files changed, 107 insertions(+), 32 deletions(-) diff --git a/core/test/follow-through.test.js b/core/test/follow-through.test.js index 32285e083..0e55c533b 100644 --- a/core/test/follow-through.test.js +++ b/core/test/follow-through.test.js @@ -93,11 +93,24 @@ const freshHome = (t) => { }) return home } -const settle = async (check) => { - const until = Date.now() + 3000 - while (!check() && Date.now() < until) await new Promise(resolve => setImmediate(resolve)) - assert.ok(check(), 'condition not reached') +// The timers a case mocked, if any. A wait must advance that clock: `setImmediate` rounds alone can +// never fire a mocked `setTimeout`, so a wall-clock deadline would decide a race the test controls (#821). +let mockedTimers +const mockTimers = (t) => { + t.mock.timers.enable({ apis: ['setTimeout'] }) + mockedTimers = t.mock.timers + t.after(() => { if (mockedTimers === t.mock.timers) mockedTimers = undefined }) +} +// Bounded by rounds, never by wall-clock: a passing run does not depend on how slow the runner is, +// and a genuine failure names the condition rather than a timeout. +const waitFor = async (check, rounds = 20000) => { + for (let i = 0; i < rounds && !check(); i++) { + mockedTimers?.tick(1) + await new Promise(resolve => setImmediate(resolve)) + } + return check() } +const settle = async (check) => { assert.ok(await waitFor(check), 'condition not reached') } // Writes to `inflight.json` land on a later tick; after a mock-timer tick and after `stop()` the file // can still hold the previous write. Wait for them rather than reading early (the note of a failed // pickup is only proved kept once the clearing write has landed and been replaced). @@ -125,7 +138,7 @@ async function openRoomTurn(t, host) { } test('a group turn cut off by a restart is picked up once, and the group is told', async (t) => { - t.mock.timers.enable({ apis: ['setTimeout'] }) + mockTimers(t) const home = freshHome(t) const first = await start(home) await openRoomTurn(t, first) @@ -164,7 +177,7 @@ test('a group turn cut off by a restart is picked up once, and the group is told }) test('a request cut off by a restart goes on under the same exchange; own-chat work resumes in the chat', async (t) => { - t.mock.timers.enable({ apis: ['setTimeout'] }) + mockTimers(t) const home = freshHome(t) const first = await start(home) run(first, 'b', 1, { content: [{ type: 'text', text: '[Message from Chief]\nDraft the plan' }], source: { kind: 'bot', form: 'relay', role: 'request', exchangeId: 'x1', senderName: 'Chief', senderSessionId: 'a', hop: 0 } }) @@ -186,7 +199,7 @@ test('a request cut off by a restart goes on under the same exchange; own-chat w }) test('when only DS Bot restarts, a turn still running or finished meanwhile is not picked up', async (t) => { - t.mock.timers.enable({ apis: ['setTimeout'] }) + mockTimers(t) const home = freshHome(t) const first = await start(home) run(first, 'b', 1, { content: [{ type: 'text', text: '[Message from Chief]\nDraft the plan' }], source: { kind: 'bot', form: 'relay', role: 'request', exchangeId: 'x1', senderName: 'Chief', senderSessionId: 'a', hop: 0 } }) @@ -217,7 +230,7 @@ test('when only DS Bot restarts, a turn still running or finished meanwhile is n }) test('a turn that finished while the plugin was not listening is not picked up', async (t) => { - t.mock.timers.enable({ apis: ['setTimeout'] }) + mockTimers(t) const home = freshHome(t) const first = await start(home) run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) @@ -233,7 +246,7 @@ test('a turn that finished while the plugin was not listening is not picked up', }) test('a turn the restart truly cut (interrupted in the durable log) is still picked up', async (t) => { - t.mock.timers.enable({ apis: ['setTimeout'] }) + mockTimers(t) const home = freshHome(t) const first = await start(home) run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) @@ -247,7 +260,7 @@ test('a turn the restart truly cut (interrupted in the durable log) is still pic }) test('a pickup that fails keeps its note for the next start', async (t) => { - t.mock.timers.enable({ apis: ['setTimeout'] }) + mockTimers(t) const home = freshHome(t) const first = await start(home) run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) @@ -284,7 +297,7 @@ test('a pickup that fails keeps its note for the next start', async (t) => { }) test('a resumed turn that writes its own note keeps it', async (t) => { - t.mock.timers.enable({ apis: ['setTimeout'] }) + mockTimers(t) const home = freshHome(t) const first = await start(home) run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) @@ -321,7 +334,7 @@ test('stop waits for the note it just wrote', async (t) => { }) test('a finished turn leaves nothing to pick up', async (t) => { - t.mock.timers.enable({ apis: ['setTimeout'] }) + mockTimers(t) const home = freshHome(t) const first = await start(home) run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) @@ -359,7 +372,7 @@ test('a message a shutdown cancelled is sent again once; one still waiting, take await settle(() => (notes(home).queued.b ?? []).length === 2) await first.stop() - t.mock.timers.enable({ apis: ['setTimeout'] }) + mockTimers(t) const second = await start(home) // A hard stop keeps the inbox: that message runs when the Session wakes. second.agentOf('b').inbox.nextTurn.push(numbers) @@ -381,7 +394,7 @@ test('a message sent again is forgotten everywhere once a turn takes it up', asy await first.stop() // The second start sends the noted message again, under the same exchange. - t.mock.timers.enable({ apis: ['setTimeout'] }) + mockTimers(t) const second = await start(home) t.mock.timers.tick(3000) await settle(() => second.agentOf('b').calls.length === 1) @@ -391,7 +404,9 @@ test('a message sent again is forgotten everywhere once a turn takes it up', asy // every later start send the message once more. second.emit('b', 'user/message', { content: again.content, source: again.source }) const notedExchange = () => Object.values(notes(home).queued ?? {}).flat().filter(item => item?.args?.exchangeId === exchangeId) - await settle(() => notedExchange().length === 0) + // The clearing write is what this case proves: drive the clock the case controls and let the + // assertion below judge it. A wait here would blame `settle` for a write that never happened. + await waitFor(() => notedExchange().length === 0) await second.stop() assert.equal(notedExchange().length, 0, 'the exchange a turn took up is still noted on disk') @@ -403,7 +418,7 @@ test('a message sent again is forgotten everywhere once a turn takes it up', asy }) test('a live interrupted end does not drop the note of a turn still owed a pickup', async (t) => { - t.mock.timers.enable({ apis: ['setTimeout'] }) + mockTimers(t) const home = freshHome(t) const first = await start(home) run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) @@ -417,7 +432,7 @@ test('a live interrupted end does not drop the note of a turn still owed a picku }) test('a turn/start this process sees proves the noted turn ended, even when the log cannot', async (t) => { - t.mock.timers.enable({ apis: ['setTimeout'] }) + mockTimers(t) const home = freshHome(t) const first = await start(home) run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) diff --git a/patches/ds-bot/0001-core-fixes.patch b/patches/ds-bot/0001-core-fixes.patch index 9c1f6c24e..85b728ba2 100644 --- a/patches/ds-bot/0001-core-fixes.patch +++ b/patches/ds-bot/0001-core-fixes.patch @@ -5698,7 +5698,7 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js started.set(home, [...(started.get(home) ?? []), host]) return host } -@@ -72,6 +72,7 @@ const freshHome = (t) => { +@@ -72,15 +72,33 @@ const freshHome = (t) => { t.after(async () => { await Promise.all((started.get(home) ?? []).map(host => host.stop())) started.delete(home) @@ -5706,10 +5706,29 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js rmSync(home, { recursive: true, force: true, maxRetries: 5, retryDelay: 20 }) }) return home -@@ -81,6 +81,10 @@ const settle = async (check) => { - while (!check() && Date.now() < until) await new Promise(resolve => setImmediate(resolve)) - assert.ok(check(), 'condition not reached') } +-const settle = async (check) => { +- const until = Date.now() + 3000 +- while (!check() && Date.now() < until) await new Promise(resolve => setImmediate(resolve)) +- assert.ok(check(), 'condition not reached') ++// The timers a case mocked, if any. A wait must advance that clock: `setImmediate` rounds alone can ++// never fire a mocked `setTimeout`, so a wall-clock deadline would decide a race the test controls (#821). ++let mockedTimers ++const mockTimers = (t) => { ++ t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockedTimers = t.mock.timers ++ t.after(() => { if (mockedTimers === t.mock.timers) mockedTimers = undefined }) ++} ++// Bounded by rounds, never by wall-clock: a passing run does not depend on how slow the runner is, ++// and a genuine failure names the condition rather than a timeout. ++const waitFor = async (check, rounds = 20000) => { ++ for (let i = 0; i < rounds && !check(); i++) { ++ mockedTimers?.tick(1) ++ await new Promise(resolve => setImmediate(resolve)) ++ } ++ return check() + } ++const settle = async (check) => { assert.ok(await waitFor(check), 'condition not reached') } +// Writes to `inflight.json` land on a later tick; after a mock-timer tick and after `stop()` the file +// can still hold the previous write. Wait for them rather than reading early (the note of a failed +// pickup is only proved kept once the clearing write has landed and been replaced). @@ -5717,12 +5736,39 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js const text = message => message.content.map(block => block.text ?? '').join('\n') const notes = (home) => { try { return JSON.parse(readFileSync(join(home, 'inflight.json'), 'utf8')) } catch { return { turns: {}, queued: {} } } -@@ -195,6 +195,110 @@ test('when only DS Bot restarts, a turn still running or finished meanwhile is n +@@ -104,7 +104,7 @@ async function openRoomTurn(t, host) { + } + + test('a group turn cut off by a restart is picked up once, and the group is told', async (t) => { +- t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockTimers(t) + const home = freshHome(t) + const first = await start(home) + await openRoomTurn(t, first) +@@ -143,7 +143,7 @@ test('a group turn cut off by a restart is picked up once, and the group is told + }) + + test('a request cut off by a restart goes on under the same exchange; own-chat work resumes in the chat', async (t) => { +- t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockTimers(t) + const home = freshHome(t) + const first = await start(home) + run(first, 'b', 1, { content: [{ type: 'text', text: '[Message from Chief]\nDraft the plan' }], source: { kind: 'bot', form: 'relay', role: 'request', exchangeId: 'x1', senderName: 'Chief', senderSessionId: 'a', hop: 0 } }) +@@ -165,7 +165,7 @@ test('a request cut off by a restart goes on under the same exchange; own-chat w + }) + + test('when only DS Bot restarts, a turn still running or finished meanwhile is not picked up', async (t) => { +- t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockTimers(t) + const home = freshHome(t) + const first = await start(home) + run(first, 'b', 1, { content: [{ type: 'text', text: '[Message from Chief]\nDraft the plan' }], source: { kind: 'bot', form: 'relay', role: 'request', exchangeId: 'x1', senderName: 'Chief', senderSessionId: 'a', hop: 0 } }) +@@ -195,8 +195,112 @@ test('when only DS Bot restarts, a turn still running or finished meanwhile is n assert.deepEqual([third.agentOf('b').calls[0].source.exchangeId, third.agentOf('a').calls.length], ['x1', 0]) }) +test('a turn that finished while the plugin was not listening is not picked up', async (t) => { -+ t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockTimers(t) + const home = freshHome(t) + const first = await start(home) + run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) @@ -5738,7 +5784,7 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js +}) + +test('a turn the restart truly cut (interrupted in the durable log) is still picked up', async (t) => { -+ t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockTimers(t) + const home = freshHome(t) + const first = await start(home) + run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) @@ -5752,7 +5798,7 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js +}) + +test('a pickup that fails keeps its note for the next start', async (t) => { -+ t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockTimers(t) + const home = freshHome(t) + const first = await start(home) + run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) @@ -5789,7 +5835,7 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js +}) + +test('a resumed turn that writes its own note keeps it', async (t) => { -+ t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockTimers(t) + const home = freshHome(t) + const first = await start(home) + run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) @@ -5826,9 +5872,21 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js +}) + test('a finished turn leaves nothing to pick up', async (t) => { - t.mock.timers.enable({ apis: ['setTimeout'] }) +- t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockTimers(t) const home = freshHome(t) -@@ -246,6 +246,65 @@ test('a message a shutdown cancelled is sent again once; one still waiting, take + const first = await start(home) + run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) +@@ -234,7 +234,7 @@ test('a message a shutdown cancelled is sent again once; one still waiting, take + await settle(() => (notes(home).queued.b ?? []).length === 2) + await first.stop() + +- t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockTimers(t) + const second = await start(home) + // A hard stop keeps the inbox: that message runs when the Session wakes. + second.agentOf('b').inbox.nextTurn.push(numbers) +@@ -246,6 +246,67 @@ test('a message a shutdown cancelled is sent again once; one still waiting, take assert.equal((await second.call('exchange', { a: 'a', b: 'b' })).value.length, 4) }) @@ -5842,7 +5900,7 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js + await first.stop() + + // The second start sends the noted message again, under the same exchange. -+ t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockTimers(t) + const second = await start(home) + t.mock.timers.tick(3000) + await settle(() => second.agentOf('b').calls.length === 1) @@ -5852,7 +5910,9 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js + // every later start send the message once more. + second.emit('b', 'user/message', { content: again.content, source: again.source }) + const notedExchange = () => Object.values(notes(home).queued ?? {}).flat().filter(item => item?.args?.exchangeId === exchangeId) -+ await settle(() => notedExchange().length === 0) ++ // The clearing write is what this case proves: drive the clock the case controls and let the ++ // assertion below judge it. A wait here would blame `settle` for a write that never happened. ++ await waitFor(() => notedExchange().length === 0) + await second.stop() + assert.equal(notedExchange().length, 0, 'the exchange a turn took up is still noted on disk') + @@ -5864,7 +5924,7 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js +}) + +test('a live interrupted end does not drop the note of a turn still owed a pickup', async (t) => { -+ t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockTimers(t) + const home = freshHome(t) + const first = await start(home) + run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } }) @@ -5878,7 +5938,7 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js +}) + +test('a turn/start this process sees proves the noted turn ended, even when the log cannot', async (t) => { -+ t.mock.timers.enable({ apis: ['setTimeout'] }) ++ mockTimers(t) + const home = freshHome(t) + const first = await start(home) + run(first, 'a', 1, { content: [{ type: 'text', text: 'hello' }], source: { kind: 'user' } })