Wait on events, not a fixed budget, in two flaky test waits (#2102)

core/test/follow-through.test.js

@@ -104,33 +104,21 @@ const mockTimers = (t) => {
   mockedTimers = t.mock.timers
   t.after(() => { if (mockedTimers === t.mock.timers) mockedTimers = undefined })
 }
-// How long a wait may take on the real clock, and how finely it steps.
-const REAL_WAIT_MS = 5000
+// How long a wait may take on the real clock, and how finely it steps. The budget is generous on
+// purpose: it only has to be longer than a genuinely lost call takes to prove nothing arrives.
+const REAL_WAIT_MS = 15000
 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()
-  }
-  // Every round still ticks the mocked clock, because only a tick moves it — but a tick cannot rush
-  // the real work the relay chain does (`inflight.json`/`state.json` writes, the Session flush,
-  // resolving the Agent), and 20000 `setImmediate` turns are ~70 ms of real time. So the round count
-  // is a floor under the budget, not a deadline: keep waiting until the real clock's deadline too
-  // (#1192 — a loaded runner burned all 20000 rounds before the relay call landed and kicked #1190
-  // out of the merge queue). `Date.now()` is not frozen by `mock.timers.enable({ apis: ['setTimeout']
-  // })`, and this puts no `setTimeout` in front of the mocked clock (#821).
+// A wait yields the CPU between checks. Round counts do not: 20000 `setImmediate` turns are ~70 ms of
+// pure spin, and on a loaded 2-core runner that spins against the very real work the relay chain does
+// (`inflight.json`/`state.json` writes, the Session flush, resolving the Agent), so a wait nothing is
+// wrong with still ran out (#1012, #1192, #2102 — the 1840b05e push failure). A round is now one real
+// timer step, and the bound is the real clock's alone; a mocked clock still gets its tick, because
+// only a tick moves it (#821).
+const waitFor = async (check) => {
   const deadline = Date.now() + REAL_WAIT_MS
-  for (let i = 0; !check() && (i < rounds || Date.now() < deadline); i++) {
-    mockedTimers.tick(1)
-    await new Promise(resolve => setImmediate(resolve))
+  while (!check() && Date.now() < deadline) {
+    mockedTimers?.tick(1)
+    await new Promise(resolve => realSetTimeout(resolve, REAL_WAIT_STEP_MS))
   }
   return check()
 }
@@ -506,27 +494,25 @@ 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.
+test('a real-clock wait outlives a slow arrival (#1012)', async () => {
+  // The relay chain that has to hand a line over does real work, and a loaded runner stretches it.
   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.
+  // The bound is the clock's, not a round count's: a wait keeps stepping until the deadline.
   let later = false
   setTimeout(() => { later = true }, 50)
-  assert.equal(await waitFor(() => later, 5), true)
+  assert.equal(await waitFor(() => later), true)
 })
 
-test('a mocked-clock wait keeps a real-clock floor under its round budget (#1192)', async (t) => {
+test('a mocked-clock wait steps in real time until its deadline (#1192)', async (t) => {
   mockTimers(t)
-  // One round is a tick plus one `setImmediate` — microseconds — so a mocked wait given a small
-  // budget used to give up long before real work landed; a loaded runner then burned all 20000
-  // rounds while the relay chain was still writing `state.json`. 100 ms of real work is the
-  // smallest honest stand-in, and the mocked clock cannot advance it: the timer is the real one.
+  // A mocked wait ticks the mocked clock, but its steps are real time: real work landing after
+  // `state.json` writes must still be seen. 100 ms of real work is the smallest honest stand-in, and
+  // the mocked clock cannot advance it: the timer is the real one.
   let landed = false
   realSetTimeout(() => { landed = true }, 100)
-  assert.equal(await waitFor(() => landed, 1), true)
+  assert.equal(await waitFor(() => landed), true)
 })
 
 test('a written tool call is told apart from text about one', () => {

patches/ds-bot/0001-core-fixes.patch

@@ -9521,7 +9521,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,15 +72,57 @@ const freshHome = (t) => {
+@@ -72,15 +72,45 @@ const freshHome = (t) => {
    t.after(async () => {
      await Promise.all((started.get(home) ?? []).map(host => host.stop()))
      started.delete(home)
@@ -9545,33 +9545,21 @@ 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 })
 +}
-+// How long a wait may take on the real clock, and how finely it steps.
-+const REAL_WAIT_MS = 5000
++// How long a wait may take on the real clock, and how finely it steps. The budget is generous on
++// purpose: it only has to be longer than a genuinely lost call takes to prove nothing arrives.
++const REAL_WAIT_MS = 15000
 +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()
-+  }
-+  // Every round still ticks the mocked clock, because only a tick moves it — but a tick cannot rush
-+  // the real work the relay chain does (`inflight.json`/`state.json` writes, the Session flush,
-+  // resolving the Agent), and 20000 `setImmediate` turns are ~70 ms of real time. So the round count
-+  // is a floor under the budget, not a deadline: keep waiting until the real clock's deadline too
-+  // (#1192 — a loaded runner burned all 20000 rounds before the relay call landed and kicked #1190
-+  // out of the merge queue). `Date.now()` is not frozen by `mock.timers.enable({ apis: ['setTimeout']
-+  // })`, and this puts no `setTimeout` in front of the mocked clock (#821).
++// A wait yields the CPU between checks. Round counts do not: 20000 `setImmediate` turns are ~70 ms of
++// pure spin, and on a loaded 2-core runner that spins against the very real work the relay chain does
++// (`inflight.json`/`state.json` writes, the Session flush, resolving the Agent), so a wait nothing is
++// wrong with still ran out (#1012, #1192, #2102 — the 1840b05e push failure). A round is now one real
++// timer step, and the bound is the real clock's alone; a mocked clock still gets its tick, because
++// only a tick moves it (#821).
++const waitFor = async (check) => {
 +  const deadline = Date.now() + REAL_WAIT_MS
-+  for (let i = 0; !check() && (i < rounds || Date.now() < deadline); i++) {
-+    mockedTimers.tick(1)
-+    await new Promise(resolve => setImmediate(resolve))
++  while (!check() && Date.now() < deadline) {
++    mockedTimers?.tick(1)
++    await new Promise(resolve => realSetTimeout(resolve, REAL_WAIT_STEP_MS))
 +  }
 +  return check()
  }
@@ -9801,31 +9789,29 @@ 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) => {
-@@ -283,6 +283,29 @@ test('in its own chat, a Bot that wrote a tool call as text is asked to make it'
+@@ -283,6 +283,27 @@ 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.
++test('a real-clock wait outlives a slow arrival (#1012)', async () => {
++  // The relay chain that has to hand a line over does real work, and a loaded runner stretches it.
 +  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.
++  // The bound is the clock's, not a round count's: a wait keeps stepping until the deadline.
 +  let later = false
 +  setTimeout(() => { later = true }, 50)
-+  assert.equal(await waitFor(() => later, 5), true)
++  assert.equal(await waitFor(() => later), true)
 +})
 +
-+test('a mocked-clock wait keeps a real-clock floor under its round budget (#1192)', async (t) => {
++test('a mocked-clock wait steps in real time until its deadline (#1192)', async (t) => {
 +  mockTimers(t)
-+  // One round is a tick plus one `setImmediate` — microseconds — so a mocked wait given a small
-+  // budget used to give up long before real work landed; a loaded runner then burned all 20000
-+  // rounds while the relay chain was still writing `state.json`. 100 ms of real work is the
-+  // smallest honest stand-in, and the mocked clock cannot advance it: the timer is the real one.
++  // A mocked wait ticks the mocked clock, but its steps are real time: real work landing after
++  // `state.json` writes must still be seen. 100 ms of real work is the smallest honest stand-in, and
++  // the mocked clock cannot advance it: the timer is the real one.
 +  let landed = false
 +  realSetTimeout(() => { landed = true }, 100)
-+  assert.equal(await waitFor(() => landed, 1), true)
++  assert.equal(await waitFor(() => landed), true)
 +})
 +
  test('a written tool call is told apart from text about one', () => {

plugins/social/test/social.test.js

@@ -5392,6 +5392,25 @@ test('#90: hide-remote leaves independent rooms in parallel and does not wait fo
   const { ctx, call, home, stop } = await team()
   t.after(stop)
   const server = mockServer()
+  // Hold the leave itself: the call must return while every room leave it started is still blocked,
+  // and the seats must still be seated. A wall-clock race here measured the runner's scheduling, not
+  // the contract — on a slow machine a correct implementation lost a 60 ms race (#2102). The plugin
+  // builds its own scoped API, so the latch goes on `scope()` before it is created.
+  let release
+  const held = new Promise(resolve => { release = resolve })
+  t.after(() => release?.())
+  let leaves = 0
+  const realScope = ctx.flybot.scope.bind(ctx.flybot)
+  ctx.flybot.scope = (name) => {
+    const scoped = realScope(name)
+    const removeParticipant = scoped.rooms.removeParticipant.bind(scoped.rooms)
+    scoped.rooms.removeParticipant = async (...args) => {
+      leaves += 1
+      await held
+      return removeParticipant(...args)
+    }
+    return scoped
+  }
   const social = createSocial(ctx.flybot, { autoAccept: false, inboxPollMs: 0, settingsPath: join(home, 'flybot-social-settings.json') }, {
     client: createMcpClient({ server: 'https://s', token: 'owner-token', fetch: server.fetch }),
     home: { id: 'h1', handle: '@danyang.home' },
@@ -5418,17 +5437,25 @@ test('#90: hide-remote leaves independent rooms in parallel and does not wait fo
   })
   assert.equal(first.ok, true, first.error?.message)
   assert.equal(second.ok, true, second.error?.message)
-  const started = Date.now()
-  const hidden = await Promise.race([
-    call('flybot/social/hide-remote', { handle: '@coder.bob.home' }),
-    new Promise((_, reject) => setTimeout(() => reject(new Error('hide-remote waited for room leave')), 60)),
-  ])
+  let returned = false
+  const pending = call('flybot/social/hide-remote', { handle: '@coder.bob.home' })
+    .then((result) => { returned = true; return result })
+  // The latch settles the question, so this only bounds a hang: an implementation that waits for the
+  // leave would never return, and that has to fail rather than stall the run.
+  await waitUntil(() => returned, { timeout: 10000 })
+  const hidden = await pending
   assert.equal(hidden.ok, true, hidden.error?.message)
-  assert.ok(Date.now() - started < 60)
   assert.equal(hidden.value.homes[0].bots.some(b => b.handle === '@coder.bob.home'), false)
   assert.ok(hidden.value.leftRooms.some(room => room.id === first.value.id))
   assert.ok(hidden.value.leftRooms.some(room => room.id === second.value.id))
-  await waitUntil(() => ctx.flybot.rooms.list().every(room => !(room.participants ?? []).some(p => p.handle === '@coder.bob.home' && p.leftSeq === undefined)))
+  assert.equal(leaves > 0, true, 'the hide starts leaving in the background')
+  assert.equal(
+    ctx.flybot.rooms.list().every(room => !(room.participants ?? []).some(p => p.handle === '@coder.bob.home' && p.leftSeq === undefined)),
+    false,
+    'the seats are still held by the latch',
+  )
+  release()
+  await waitUntil(() => ctx.flybot.rooms.list().every(room => !(room.participants ?? []).some(p => p.handle === '@coder.bob.home' && p.leftSeq === undefined)), { timeout: 5000 })
 })
 
 test('a hidden Bot survives a failed fetch and a legacy list_friends refresh', async (t) => {