Give a real-clock wait in follow-through.test.js a real bound (#1012)

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('<function=read>\n<parameter=path>a.md</parameter></function>'), true)

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<tool_call>\n<function=pwsh>\n<parameter=command>\nGet-ChildItem E:\\\n</parameter>\n</function>\n</tool_call>'
 
  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('<function=read>\n<parameter=path>a.md</parameter></function>'), 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