From ea1f0fd96da163be6ffeaa429876442698cedb2f Mon Sep 17 00:00:00 2001 From: Danyang Chen Date: Sun, 25 Oct 2026 00:23:53 +0800 Subject: [PATCH] Fix the real-clock wait bound in follow-through.test.js (#1012) A wait on a real clock was 20000 setImmediate rounds - about 100 ms of wall clock on a runner - while the relay path still has real work to do before it hands the line over (a state write, the Session flush, resolving the Agent). The merge_group run burned all 20000 rounds in 149 ms and the test failed as "condition not reached" although nothing had been lost. Keep the mocked-clock path exactly as it was (#821: only a tick moves that clock) and bound the real clock in real time: 5 s, in 5 ms steps. Docs-not-needed: test-only change to a test helper's wait bound; the product's behaviour is unchanged. --- core/test/follow-through.test.js | 31 +++++++++-- patches/ds-bot/0001-core-fixes.patch | 81 ++++++++++++++++++++++------ 2 files changed, 93 insertions(+), 19 deletions(-) diff --git a/core/test/follow-through.test.js b/core/test/follow-through.test.js index 0e55c533b..e25893dd0 100644 --- a/core/test/follow-through.test.js +++ b/core/test/follow-through.test.js @@ -101,11 +101,24 @@ const mockTimers = (t) => { 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. +// How long a wait may take on the real clock, and how finely it steps. +const REAL_WAIT_MS = 5000 +const REAL_WAIT_STEP_MS = 5 +// A wait is bounded by rounds when the test mocks the clock, because only a tick moves that clock +// and a wall-clock deadline would decide a race the test controls (#821). const waitFor = async (check, rounds = 20000) => { + if (mockedTimers === undefined) { + // Bounded by the real clock, in real time: a round is one `setImmediate` (a few microseconds), so + // 20000 rounds are ~100 ms while the relay path does real work (state.json writes, the Session + // flush, resolving the Agent) and a loaded runner stretches that to more (#1012: the merge_group + // failure burned all 20000 rounds in 149 ms, so `openRoomTurn` never saw its call). A genuinely + // lost call still ends the run rather than stalling it. + const deadline = Date.now() + REAL_WAIT_MS + while (!check() && Date.now() < deadline) await new Promise(resolve => setTimeout(resolve, REAL_WAIT_STEP_MS)) + return check() + } for (let i = 0; i < rounds && !check(); i++) { - mockedTimers?.tick(1) + mockedTimers.tick(1) await new Promise(resolve => setImmediate(resolve)) } return check() @@ -482,6 +495,18 @@ test('in its own chat, a Bot that wrote a tool call as text is asked to make it' assert.match(text(retry), /^\[Your last reply wrote a tool call as text, so nothing ran\]/) }) +test('a real-clock wait outlives its round budget (#1012)', async () => { + // Today the wait on a real clock is 20000 setImmediate rounds: about 100 ms on a runner, and the + // relay chain that has to hand a line over can take longer than that while nothing is wrong. + let ready = false + setTimeout(() => { ready = true }, 300) + await settle(() => ready) + // The bound is the clock's, not the round count's: the same wait with a tiny budget still waits. + let later = false + setTimeout(() => { later = true }, 50) + assert.equal(await waitFor(() => later, 5), true) +}) + test('a written tool call is told apart from text about one', () => { assert.equal(writesToolCall(WRITTEN), true) assert.equal(writesToolCall('\na.md'), true) diff --git a/patches/ds-bot/0001-core-fixes.patch b/patches/ds-bot/0001-core-fixes.patch index 6d229fc34..1a32ea828 100644 --- a/patches/ds-bot/0001-core-fixes.patch +++ b/patches/ds-bot/0001-core-fixes.patch @@ -6049,19 +6049,33 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js started.set(home, [...(started.get(home) ?? []), host]) return host } -@@ -72,15 +72,33 @@ const freshHome = (t) => { - t.after(async () => { - await Promise.all((started.get(home) ?? []).map(host => host.stop())) - started.delete(home) -+ durable.delete(home) - rmSync(home, { recursive: true, force: true, maxRetries: 5, retryDelay: 20 }) - }) - return home - } +@@ -69,21 +85,52 @@ + const freshHome = (t) => { + const home = mkdtempSync(join(tmpdir(), 'ds-bot-follow-')) + writeFileSync(join(home, 'state.json'), JSON.stringify(seed())) +- t.after(async () => { +- await Promise.all((started.get(home) ?? []).map(host => host.stop())) +- started.delete(home) +- rmSync(home, { recursive: true, force: true, maxRetries: 5, retryDelay: 20 }) +- }) +- 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') +-} +-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: {} } } ++ t.after(async () => { ++ await Promise.all((started.get(home) ?? []).map(host => host.stop())) ++ started.delete(home) ++ durable.delete(home) ++ rmSync(home, { recursive: true, force: true, maxRetries: 5, retryDelay: 20 }) ++ }) ++ return home ++} +// 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 @@ -6070,23 +6084,39 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js + 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. ++// How long a wait may take on the real clock, and how finely it steps. ++const REAL_WAIT_MS = 5000 ++const REAL_WAIT_STEP_MS = 5 ++// A wait is bounded by rounds when the test mocks the clock, because only a tick moves that clock ++// and a wall-clock deadline would decide a race the test controls (#821). +const waitFor = async (check, rounds = 20000) => { ++ if (mockedTimers === undefined) { ++ // Bounded by the real clock, in real time: a round is one `setImmediate` (a few microseconds), so ++ // 20000 rounds are ~100 ms while the relay path does real work (state.json writes, the Session ++ // flush, resolving the Agent) and a loaded runner stretches that to more (#1012: the merge_group ++ // failure burned all 20000 rounds in 149 ms, so `openRoomTurn` never saw its call). A genuinely ++ // lost call still ends the run rather than stalling it. ++ const deadline = Date.now() + REAL_WAIT_MS ++ while (!check() && Date.now() < deadline) await new Promise(resolve => setTimeout(resolve, REAL_WAIT_STEP_MS)) ++ return check() ++ } + for (let i = 0; i < rounds && !check(); i++) { -+ mockedTimers?.tick(1) ++ 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). +const flushWrites = async (rounds = 20) => { for (let i = 0; i < rounds; i++) await new Promise(resolve => setImmediate(resolve)) } - 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: {} } } ++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: {} } } + } + const inflight = home => notes(home).turns ?? {} + // A message as DSH would replay it: the turn starts and takes it up. @@ -104,7 +104,7 @@ async function openRoomTurn(t, host) { } @@ -6305,6 +6335,25 @@ diff --git a/test/follow-through.test.js b/test/follow-through.test.js const WRITTEN = 'Checking now.\n\n\n\nGet-ChildItem E:\\\n\n\n' test('a tool call written as text gets one more turn on the same round slot', async (t) => { +@@ -284,5 +284,17 @@ + }) + ++test('a real-clock wait outlives its round budget (#1012)', async () => { ++ // Today the wait on a real clock is 20000 setImmediate rounds: about 100 ms on a runner, and the ++ // relay chain that has to hand a line over can take longer than that while nothing is wrong. ++ let ready = false ++ setTimeout(() => { ready = true }, 300) ++ await settle(() => ready) ++ // The bound is the clock's, not the round count's: the same wait with a tiny budget still waits. ++ let later = false ++ setTimeout(() => { later = true }, 50) ++ assert.equal(await waitFor(() => later, 5), true) ++}) ++ + test('a written tool call is told apart from text about one', () => { + assert.equal(writesToolCall(WRITTEN), true) + assert.equal(writesToolCall('\na.md'), true) + diff --git a/test/group-status.test.js b/test/group-status.test.js --- a/test/group-status.test.js +++ b/test/group-status.test.js