diff --git a/core/test/follow-through.test.js b/core/test/follow-through.test.js index 1bffc4ca6..e2c4727bc 100644 --- a/core/test/follow-through.test.js +++ b/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', () => { diff --git a/patches/ds-bot/0001-core-fixes.patch b/patches/ds-bot/0001-core-fixes.patch index 97c416f05..d28d2de6e 100644 --- a/patches/ds-bot/0001-core-fixes.patch +++ b/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\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) => { -@@ -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', () => { diff --git a/plugins/social/test/social.test.js b/plugins/social/test/social.test.js index 8dac1d728..9ef93d814 100644 --- a/plugins/social/test/social.test.js +++ b/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) => {