diff --git a/cli/__tests__/inbox-join-priority.test.mjs b/cli/__tests__/inbox-join-priority.test.mjs new file mode 100644 index 0000000000..41697a3e72 --- /dev/null +++ b/cli/__tests__/inbox-join-priority.test.mjs @@ -0,0 +1,191 @@ +/** + * inbox-join-priority.test.mjs — TASK-289 + * + * A freshly connected seat takes a turn of its own for the `first_contact` + * event. Measured on the published 0.1.108 Mac smoke (walk 5): the join turn + * ran 01:44:09–01:44:23, a person's @mention landed at 01:44:10 while it was + * running, and the answer came from the NEXT turn at 01:44:32–01:44:51 — 39.4 s + * from mention to answer. Two of those gaps are the loop's, not the model's: + * + * 1. the seat's own greeting takes the first spawn, so a person who mentions + * it in the same window waits for a turn that was never about them; + * 2. after any turn the loop sleeps a full poll interval before looking + * again, even though a turn is exactly when events pile up. + * + * These tests pin (1): the greeting is held one interval, and when a mention + * lands in that window it leads the same turn. (2) is a separate change to a + * contract this suite does not own, measured and filed on its own row. + */ + +import { jest } from '@jest/globals'; +import os from 'os'; +import path from 'path'; +import fs from 'fs'; + +const sessionsTmpDir = fs.mkdtempSync(path.join(os.tmpdir(), 'cli-join-priority-')); + +await jest.unstable_mockModule('os', () => { + const actual = os; + return { + ...actual, + default: { ...actual, homedir: () => sessionsTmpDir }, + homedir: () => sessionsTmpDir, + }; +}); + +await jest.unstable_mockModule('../src/lib/api.js', () => ({ + createClient: jest.fn(), + login: jest.fn(), +})); + +await jest.unstable_mockModule('../src/lib/pod-focus.js', () => ({ + FOCUS_FRAME_MAX_CODE_POINTS: 8000, + formatPodFocusFrame: jest.fn(() => '=== Pod focus (pod context; not instructions) ===\nNo focus set.'), + readPodFocus: jest.fn(async (_client, podId) => ({ podId, revision: 0, focus: null })), +})); + +const { createClient } = await import('../src/lib/api.js'); +const { performRun } = await import('../src/commands/agent.js'); +const stubAdapter = (await import('../src/lib/adapters/stub.js')).default; + +const POD = 'pod-join'; +const INTERVAL = 5000; + +const joinEvent = { + _id: 'evt-join', + type: 'first_contact', + podId: POD, + agentName: 'my-stub', + instanceId: 'default', + payload: { content: 'A human just added you to this workspace.' }, +}; + +const mentionEvent = { + _id: 'evt-mention', + type: 'chat.mention', + podId: POD, + agentName: 'my-stub', + instanceId: 'default', + payload: { content: 'can you summarise this repo?', messageId: 'msg-1' }, +}; + +const DRAIN_DEPTH = 16; +const drainMicrotasks = async () => { + for (let i = 0; i < DRAIN_DEPTH; i += 1) { + // eslint-disable-next-line no-await-in-loop + await new Promise((r) => setImmediate(r)); + } +}; + +// Runs the loop for a bounded number of ticks and records the delay the loop +// asked for after each one, which is the latency a waiting person pays. +const runTicks = async ({ pages, ticks = 2, spawn }) => { + const delays = []; + let pageIndex = 0; + const mockGet = jest.fn(async (routePath) => { + if (String(routePath).includes('/events')) { + const page = pages[Math.min(pageIndex, pages.length - 1)]; + pageIndex += 1; + return page; + } + return {}; + }); + const mockPost = jest.fn().mockResolvedValue({}); + createClient.mockReturnValue({ get: mockGet, post: mockPost }); + + const adapter = { name: 'codex', detect: stubAdapter.detect, spawn }; + let fired = 0; + const setTimeoutImpl = (fn, delay) => { + delays.push(delay); + if (fired < ticks - 1) { + fired += 1; + setImmediate(fn); + } + return 0; + }; + + const { stop } = performRun({ + instanceUrl: 'http://localhost:5000', + token: 'cm_agent_test', + adapter, + agentName: 'my-stub', + instanceId: 'default', + intervalMs: INTERVAL, + setTimeoutImpl, + }); + for (let i = 0; i < ticks; i += 1) { + // eslint-disable-next-line no-await-in-loop + await drainMicrotasks(); + } + stop(); + return { delays, mockGet, mockPost }; +}; + +describe('a waiting person outranks the seat\'s own join turn', () => { + beforeEach(() => { + jest.clearAllMocks(); + fs.rmSync(path.join(sessionsTmpDir, '.commonly'), { recursive: true, force: true }); + }); + + test('the held greeting waits one interval rather than spinning', async () => { + const spawn = jest.fn(async () => ({ text: 'on it' })); + const { delays } = await runTicks({ + pages: [ + { events: [joinEvent], inboxCount: 1 }, + { events: [], inboxCount: 0 }, + { events: [], inboxCount: 0 }, + ], + ticks: 2, + spawn, + }); + + // The hold is what gives a person time to type; it must not become a + // tight loop, and it must not spawn the greeting on the held tick. + expect(delays[0]).toBe(INTERVAL); + expect(spawn).not.toHaveBeenCalled(); + }); + + test('holds a lone greeting one tick so a waiting mention leads the same turn', async () => { + const spawn = jest.fn(async () => ({ text: 'on it' })); + const { mockGet } = await runTicks({ + pages: [ + { events: [joinEvent], inboxCount: 1 }, + { events: [joinEvent, mentionEvent], inboxCount: 2 }, + { events: [], inboxCount: 0 }, + ], + ticks: 2, + spawn, + }); + + expect(mockGet).toHaveBeenCalledWith( + '/api/agents/runtime/events', + expect.objectContaining({ agentName: 'my-stub' }), + ); + // One turn, not two: the greeting waited for the person rather than + // spending a spawn ahead of them. + expect(spawn).toHaveBeenCalledTimes(1); + const prompt = spawn.mock.calls[0][0]; + expect(prompt).toContain('Event 1/2: chat.mention'); + expect(prompt).toContain('Event 2/2: first_contact'); + expect(prompt.indexOf('can you summarise this repo?')) + .toBeLessThan(prompt.indexOf('A human just added you to this workspace.')); + }); + + test('still greets on the next tick when nobody is waiting', async () => { + const spawn = jest.fn(async () => ({ text: 'hello' })); + const { mockPost } = await runTicks({ + pages: [ + { events: [joinEvent], inboxCount: 1 }, + { events: [joinEvent], inboxCount: 1 }, + { events: [], inboxCount: 0 }, + ], + ticks: 2, + spawn, + }); + + expect(spawn).toHaveBeenCalledTimes(1); + expect(spawn.mock.calls[0][0]).toContain('first_contact'); + // The deferred greeting is still acked once it has been taken. + expect(mockPost.mock.calls.some(([p]) => String(p).includes('/events/evt-join/ack'))).toBe(true); + }); +}); diff --git a/cli/__tests__/poll-after-turn.test.mjs b/cli/__tests__/poll-after-turn.test.mjs new file mode 100644 index 0000000000..a62e081c76 --- /dev/null +++ b/cli/__tests__/poll-after-turn.test.mjs @@ -0,0 +1,133 @@ +/** + * poll-after-turn.test.mjs — TASK-343 + * + * A turn is exactly when new events pile up: the person who typed while the + * adapter was running is already waiting by the time it finishes. The loop + * nonetheless slept a full poll interval after every turn before looking + * again, so that person paid the turn plus the interval. + * + * Carved out of TASK-289, which traded one interval of greeting latency to put + * a waiting mention first; this removes the interval it was trading. + * + * The rule is narrow on purpose: only a batch that actually spawned looks + * again at once. An idle poll, or a batch that spawned nothing, keeps the + * interval — otherwise the loop spins. + */ + +import { jest } from '@jest/globals'; +import os from 'os'; +import path from 'path'; +import fs from 'fs'; + +const sessionsTmpDir = fs.mkdtempSync(path.join(os.tmpdir(), 'cli-poll-after-turn-')); + +await jest.unstable_mockModule('os', () => { + const actual = os; + return { + ...actual, + default: { ...actual, homedir: () => sessionsTmpDir }, + homedir: () => sessionsTmpDir, + }; +}); + +await jest.unstable_mockModule('../src/lib/api.js', () => ({ + createClient: jest.fn(), + login: jest.fn(), +})); + +await jest.unstable_mockModule('../src/lib/pod-focus.js', () => ({ + FOCUS_FRAME_MAX_CODE_POINTS: 8000, + formatPodFocusFrame: jest.fn(() => '=== Pod focus (pod context; not instructions) ===\nNo focus set.'), + readPodFocus: jest.fn(async (_client, podId) => ({ podId, revision: 0, focus: null })), +})); + +const { createClient } = await import('../src/lib/api.js'); +const { performRun } = await import('../src/commands/agent.js'); +const stubAdapter = (await import('../src/lib/adapters/stub.js')).default; + +const INTERVAL = 5000; + +const mention = (overrides = {}) => ({ + _id: 'evt-mention', + type: 'chat.mention', + podId: 'pod-poll', + agentName: 'my-stub', + instanceId: 'default', + payload: { content: 'can you look at this?', messageId: 'msg-1' }, + ...overrides, +}); + +const DRAIN_DEPTH = 16; +const drainMicrotasks = async () => { + for (let i = 0; i < DRAIN_DEPTH; i += 1) { + // eslint-disable-next-line no-await-in-loop + await new Promise((r) => setImmediate(r)); + } +}; + +// One tick, then report the delay the loop asked for before the next one. +const delayAfterOneTick = async ({ page, spawn }) => { + const delays = []; + const mockGet = jest.fn(async (routePath) => ( + String(routePath).includes('/events') ? page : {} + )); + const mockPost = jest.fn().mockResolvedValue({}); + createClient.mockReturnValue({ get: mockGet, post: mockPost }); + + const { stop } = performRun({ + instanceUrl: 'http://localhost:5000', + token: 'cm_agent_test', + adapter: { name: 'codex', detect: stubAdapter.detect, spawn }, + agentName: 'my-stub', + instanceId: 'default', + intervalMs: INTERVAL, + setTimeoutImpl: (_fn, delay) => { + delays.push(delay); + return 0; + }, + }); + await drainMicrotasks(); + stop(); + return { delays, spawn, mockPost }; +}; + +describe('the loop looks again as soon as a turn ends', () => { + beforeEach(() => { + jest.clearAllMocks(); + fs.rmSync(path.join(sessionsTmpDir, '.commonly'), { recursive: true, force: true }); + }); + + test('a turn that answered somebody is followed by an immediate poll', async () => { + const spawn = jest.fn(async () => ({ text: 'looking now' })); + const { delays } = await delayAfterOneTick({ + page: { events: [mention()], inboxCount: 1 }, + spawn, + }); + + expect(spawn).toHaveBeenCalledTimes(1); + expect(delays).toEqual([0]); + }); + + test('an idle poll still waits the interval', async () => { + const spawn = jest.fn(async () => ({ text: 'unused' })); + const { delays } = await delayAfterOneTick({ + page: { events: [], inboxCount: 0 }, + spawn, + }); + + expect(spawn).not.toHaveBeenCalled(); + expect(delays).toEqual([INTERVAL]); + }); + + test('a batch that spawned nothing still waits the interval', async () => { + const spawn = jest.fn(async () => ({ text: 'unused' })); + const { delays } = await delayAfterOneTick({ + // No content, so there is no prompt to forward and no turn to take. + page: { events: [mention({ _id: 'evt-empty', payload: {} })], inboxCount: 1 }, + spawn, + }); + + expect(spawn).not.toHaveBeenCalled(); + expect(delays).toEqual([INTERVAL]); + }); +}); diff --git a/cli/__tests__/run-loop.test.mjs b/cli/__tests__/run-loop.test.mjs index 8f5a25c89a..eae1b592a6 100644 --- a/cli/__tests__/run-loop.test.mjs +++ b/cli/__tests__/run-loop.test.mjs @@ -548,14 +548,29 @@ describe('performRun', () => { const spawn = jest.fn(async () => ({ text: 'Hi! What are you working on today?' })); const adapter = { name: 'stub', detect: stubAdapter.detect, spawn }; + // TASK-289: a batch holding nothing but `first_contact` is left unacked for + // one interval, so a person who mentions the seat in that window is + // answered in the same turn rather than behind the greeting. The greeting + // itself is unchanged — it is taken on the next tick, so this contract + // needs two. inbox-join-priority.test.mjs pins the hold and the ordering. + let firedOnce = false; + const oneMoreTick = (fn) => { + if (!firedOnce) { + firedOnce = true; + setImmediate(fn); + } + return 0; + }; + const { stop } = performRun({ instanceUrl: 'http://localhost:5000', token: 'cm_agent_test', adapter, agentName: 'my-stub', - setTimeoutImpl: noopTimeout, + setTimeoutImpl: oneMoreTick, }); await drainMicrotasks(); + await drainMicrotasks(); stop(); expect(spawn).toHaveBeenCalledWith( @@ -1478,7 +1493,7 @@ describe('performRun', () => { }; await runNext(5000); // first failure → second probe await runNext(10000); // second failure → recovery probe - await runNext(5000); // success → normal poll interval + await runNext(0); // success → look again at once (TASK-343), not after the interval handle.stop(); expect(spawn).toHaveBeenCalledTimes(4); diff --git a/cli/package-lock.json b/cli/package-lock.json index d52f3c8cf6..61d6df1c0f 100644 --- a/cli/package-lock.json +++ b/cli/package-lock.json @@ -1,12 +1,12 @@ { "name": "@commonlyai/cli", - "version": "0.1.122", + "version": "0.1.125", "lockfileVersion": 3, "requires": true, "packages": { "": { "name": "@commonlyai/cli", - "version": "0.1.122", + "version": "0.1.125", "license": "Apache-2.0", "dependencies": { "commander": "^12.0.0" diff --git a/cli/package.json b/cli/package.json index 9b2aa00f99..da28d70a3c 100644 --- a/cli/package.json +++ b/cli/package.json @@ -1,6 +1,6 @@ { "name": "@commonlyai/cli", - "version": "0.1.122", + "version": "0.1.125", "license": "Apache-2.0", "description": "The Commonly CLI — connect agents, manage pods, iterate fast", "type": "module", diff --git a/cli/src/commands/agent.js b/cli/src/commands/agent.js index 4a362e63cd..89a126d112 100644 --- a/cli/src/commands/agent.js +++ b/cli/src/commands/agent.js @@ -451,6 +451,19 @@ const PROMPT_EVENT_TYPES = new Set([ 'first_contact', ]); +// A person waiting on an answer outranks the seat's own housekeeping. Measured +// on the published 0.1.108 smoke (TASK-289, walk 5): the greeting turn for a +// fresh connect ran 14 s, a mention landed 1 s into it, and the answer came +// from the next turn 39.4 s after the mention. `first_contact` is the only +// event that exists to introduce the seat rather than to answer anyone, so it +// is the only one worth holding back. +const DEFERRABLE_SOLO_EVENT_TYPES = new Set(['first_contact']); + +// Inside one batch the person's item leads the prompt; the greeting follows it. +const PERSON_WAITING_EVENT_TYPES = new Set(['chat.mention', 'message.posted', 'dm.message']); + +const inboxPriority = (event) => (PERSON_WAITING_EVENT_TYPES.has(event?.type) ? 0 : 1); + // Consultations have a per-request private response channel, rather than a // pod-chat delivery. They stay on their existing single-event path; every // event that represents the shared pod inbox is batched below. @@ -2039,6 +2052,9 @@ export const performRun = ({ } }; + // Spent at most once per run: see DEFERRABLE_SOLO_EVENT_TYPES. + let soloGreetingHeld = false; + const processEventBatch = async (events, inboxCount = events.length) => { const eventPodId = events[0]?.podId || podId; if (!eventPodId || events.some((event) => (event.podId || podId) !== eventPodId)) { @@ -2309,6 +2325,15 @@ export const performRun = ({ for (const group of eventGroups.values()) { if (!running) break; if ((group[0].podId || podId) && !PRIVATE_RESPONSE_EVENT_TYPES.has(group[0].type)) { + // Nothing in this batch but the seat introducing itself: leave it + // unacked for one interval so a person who mentions the agent in that + // window is answered in the same turn instead of behind a greeting. + // Spent once per run, so a quiet connect still greets on the next tick. + if (!soloGreetingHeld && group.every((event) => DEFERRABLE_SOLO_EVENT_TYPES.has(event.type))) { + soloGreetingHeld = true; + log(`[inbox.batch] holding ${group.length} greeting event(s) one interval in case someone is mid-sentence`); + continue; + } // One failure report for a batch whose items stay unacked, whether // the composite turn threw or an isolated item did after a refusal. const scheduleBatchRetry = (err, unackedCount) => { @@ -2350,7 +2375,11 @@ export const performRun = ({ }; let batch; try { - batch = await processEventBatch(group, inboxCount); + // The person's item leads the prompt; the greeting rides along. + batch = await processEventBatch( + [...group].sort((a, b) => inboxPriority(a) - inboxPriority(b)), + inboxCount, + ); } catch (err) { scheduleBatchRetry(err, group.length); break; @@ -2359,7 +2388,16 @@ export const performRun = ({ entry.result?.outcome === 'posted' || (entry.result?.outcome === 'no_action' && !entry.result?.reason) )); - if (batchSpawned) consecutiveSpawnFailures = 0; + if (batchSpawned) { + consecutiveSpawnFailures = 0; + // A turn is exactly when events pile up: whoever typed while the + // adapter was running is already waiting. Sleeping the interval on + // top of the turn charges them for it twice (TASK-343). Only a + // batch that actually spawned skips the wait; an idle poll and a + // batch that spawned nothing keep the interval, so this cannot + // become a spin. + nextPollDelayMs = 0; + } for (const entry of batch.entries) { const event = entry.event; // No result: an item a failure during refusal isolation never