diff --git a/cli/__tests__/cap-timeout-liveness.test.mjs b/cli/__tests__/cap-timeout-liveness.test.mjs new file mode 100644 index 0000000000..71a07d96b6 --- /dev/null +++ b/cli/__tests__/cap-timeout-liveness.test.mjs @@ -0,0 +1,350 @@ +/** + * TASK-338: one CAP request that never settles used to wedge the inbox loop for + * good. On 10-31 nib and folio each got an HTTP 504, then a request the network + * accepted and never answered, and sat alive and idle for 8+ hours, because + * their keepalives act only on exit. + * + * These run against a real HTTP server, not a mocked client, because the defect + * lives in the fetch call itself: a mocked `get` can't hang the way a socket does. + */ +import { jest } from '@jest/globals'; +import http from 'http'; +import os from 'os'; +import path from 'path'; +import fs from 'fs'; + +const homeDir = fs.mkdtempSync(path.join(os.tmpdir(), 'cli-cap-timeout-')); + +await jest.unstable_mockModule('os', () => ({ + ...os, + default: { ...os, homedir: () => homeDir }, + homedir: () => homeDir, +})); + +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 { startPoller } = await import('../src/lib/poller.js'); +const stubAdapter = (await import('../src/lib/adapters/stub.js')).default; + +const GATEWAY_PAGE = '504 Gateway Time-out…'; + +// `script(n)` decides what the n-th inbox poll gets: 'gateway' (504), 'hang' +// (accepted, never answered) or a page object. Everything else answers 200 {}. +// `other(req)` may return 'hang' for a non-poll request (an ack, say). +const startStub = async (script, { other = () => null, delayMs = 0 } = {}) => { + const polls = []; + const answered = []; + const others = []; + const server = http.createServer((req, res) => { + if (req.url.split('?')[0] !== '/api/agents/runtime/events' || req.method !== 'GET') { + others.push(`${req.method} ${req.url.split('?')[0]}`); + if (other(req) === 'hang') return; + res.writeHead(200, { 'Content-Type': 'application/json' }); + res.end('{}'); + return; + } + const n = polls.push(Date.now()); + const step = script(n); + if (step === 'hang') return; + if (step === 'gateway') { + res.writeHead(504, { 'Content-Type': 'text/html' }); + res.end(GATEWAY_PAGE); + return; + } + const answer = () => { + res.writeHead(200, { 'Content-Type': 'application/json' }); + res.end(JSON.stringify(step)); + answered.push(n); + }; + if (delayMs) setTimeout(answer, delayMs); else answer(); + }); + await new Promise((resolve) => { server.listen(0, '127.0.0.1', resolve); }); + return { + url: `http://127.0.0.1:${server.address().port}`, + polls, + answered, + others, + close: () => new Promise((resolve) => { + server.closeAllConnections(); + server.close(resolve); + }), + }; +}; + +const waitFor = async (predicate, timeoutMs = 5000) => { + const deadline = Date.now() + timeoutMs; + while (!predicate()) { + if (Date.now() > deadline) throw new Error('condition not met in time'); + // eslint-disable-next-line no-await-in-loop + await new Promise((resolve) => { setTimeout(resolve, 10); }); + } +}; + +const EMPTY = { events: [], inboxCount: 0 }; +// The loop records handled event ids on disk, so each test needs its own id or +// it reads as a duplicate delivery and skips the turn. +const mentionFor = (id) => ({ + _id: id, + type: 'chat.mention', + podId: 'pod-338', + agentName: 'my-stub', + instanceId: 'default', + payload: { content: 'take your time on this one', messageId: `msg-${id}` }, +}); + +let stub; +let stopLoop; +const savedTimeout = process.env.COMMONLY_CAP_TIMEOUT_MS; + +afterEach(async () => { + stopLoop?.(); + stopLoop = null; + await stub?.close(); + stub = null; + if (savedTimeout === undefined) delete process.env.COMMONLY_CAP_TIMEOUT_MS; + else process.env.COMMONLY_CAP_TIMEOUT_MS = savedTimeout; +}); + +afterAll(() => { fs.rmSync(homeDir, { recursive: true, force: true }); }); + +const run = (overrides = {}) => { + const errors = []; + const onPollStalled = jest.fn(); + const { stop } = performRun({ + instanceUrl: stub.url, + token: 'cm_agent_test', + adapter: { name: 'codex', detect: stubAdapter.detect, spawn: jest.fn(async () => ({ text: '' })) }, + agentName: 'my-stub', + instanceId: 'default', + intervalMs: 20, + retryJitterRatio: 0, + superviseRuns: false, + revokeOrphansImpl: async () => {}, + onError: (err) => errors.push(err), + onPollStalled, + ...overrides, + }); + stopLoop = stop; + return { errors, onPollStalled }; +}; + +describe('every CAP request has a hard timeout', () => { + test('a 504 is an ordinary failure, and a request that is never answered times out', async () => { + stub = await startStub((n) => (n === 1 ? 'gateway' : 'hang')); + const client = createClient({ instance: stub.url, token: 'cm_agent_test', timeoutMs: 150 }); + + await expect(client.get('/api/agents/runtime/events')).rejects.toMatchObject({ + status: 504, + message: 'HTTP 504: 504 Gateway Time-out', + }); + + const started = Date.now(); + await expect(client.get('/api/agents/runtime/events')).rejects.toMatchObject({ + code: 'cap_timeout', + timeoutMs: 150, + message: 'GET /api/agents/runtime/events got no answer in 150ms', + }); + expect(Date.now() - started).toBeLessThan(2000); + }); + + test('writes get twice the read timeout, and the env var sets the base', async () => { + const silent = http.createServer(() => {}); + await new Promise((resolve) => { silent.listen(0, '127.0.0.1', resolve); }); + stub = { + url: `http://127.0.0.1:${silent.address().port}`, + close: () => new Promise((resolve) => { silent.closeAllConnections(); silent.close(resolve); }), + }; + process.env.COMMONLY_CAP_TIMEOUT_MS = '100'; + const client = createClient({ instance: stub.url, token: 'cm_agent_test' }); + + await expect(client.get('/api/x')).rejects.toMatchObject({ code: 'cap_timeout', timeoutMs: 100 }); + await expect(client.post('/api/agents/runtime/events/e1/ack', {})).rejects.toMatchObject({ + code: 'cap_timeout', + timeoutMs: 200, + message: 'POST /api/agents/runtime/events/e1/ack got no answer in 200ms', + }); + }); +}); + +describe('the timeout covers the whole response, and only renames its own abort', () => { + test('headers, then silence: the body read is cut off too', async () => { + const trickle = http.createServer((_req, res) => { + res.writeHead(200, { 'Content-Type': 'application/json' }); + res.write('{"events": ['); + }); + await new Promise((resolve) => { trickle.listen(0, '127.0.0.1', resolve); }); + stub = { + url: `http://127.0.0.1:${trickle.address().port}`, + close: () => new Promise((resolve) => { trickle.closeAllConnections(); trickle.close(resolve); }), + }; + const client = createClient({ instance: stub.url, token: 'cm_agent_test', timeoutMs: 150 }); + await expect(client.get('/api/agents/runtime/events')).rejects.toMatchObject({ code: 'cap_timeout' }); + }); + + test("a caller's own shorter timeout keeps its own error", async () => { + stub = await startStub(() => 'hang'); + const client = createClient({ instance: stub.url, token: 'cm_agent_test', timeoutMs: 5000 }); + const err = await client.get('/api/agents/runtime/events', {}, { signal: AbortSignal.timeout(50) }) + .catch((e) => e); + expect(err.name).toBe('TimeoutError'); + expect(err.code).not.toBe('cap_timeout'); + expect(err.timeoutMs).toBeUndefined(); + }); +}); + +describe('without AbortSignal.any (Node 20.0 to 20.2)', () => { + const realAny = AbortSignal.any; + afterEach(() => { AbortSignal.any = realAny; }); + + test("a caller's longer signal does not replace the hard timeout", async () => { + stub = await startStub(() => 'hang'); + AbortSignal.any = undefined; + const client = createClient({ instance: stub.url, token: 'cm_agent_test', timeoutMs: 150 }); + await expect(client.get('/api/agents/runtime/events', {}, { signal: AbortSignal.timeout(5000) })) + .rejects.toMatchObject({ code: 'cap_timeout', timeoutMs: 150 }); + }); + + test("a settled request takes its listener off a caller's long-lived signal", async () => { + stub = await startStub(() => EMPTY); + AbortSignal.any = undefined; + const caller = new AbortController(); + const added = jest.spyOn(caller.signal, 'addEventListener'); + const removed = jest.spyOn(caller.signal, 'removeEventListener'); + const client = createClient({ instance: stub.url, token: 'cm_agent_test', timeoutMs: 5000 }); + await client.get('/api/agents/runtime/events', {}, { signal: caller.signal }); + await client.get('/api/agents/runtime/events', {}, { signal: caller.signal }); + const ours = (spy) => spy.mock.calls.filter(([type]) => type === 'abort').map(([, fn]) => fn); + expect(ours(removed)).toEqual(ours(added)); + expect(ours(added)).toHaveLength(2); + }); + + test("a caller's shorter timeout still keeps its own error", async () => { + stub = await startStub(() => 'hang'); + AbortSignal.any = undefined; + const client = createClient({ instance: stub.url, token: 'cm_agent_test', timeoutMs: 5000 }); + const err = await client.get('/api/agents/runtime/events', {}, { signal: AbortSignal.timeout(50) }) + .catch((e) => e); + expect(err.name).toBe('TimeoutError'); + expect(err.code).not.toBe('cap_timeout'); + }); +}); + +describe('agent run: the inbox loop survives a hung poll', () => { + test('504, then a hang, then healthy: the loop backs off and recovers, with no stall exit', async () => { + process.env.COMMONLY_CAP_TIMEOUT_MS = '150'; + stub = await startStub((n) => (n === 1 ? 'gateway' : n === 2 ? 'hang' : EMPTY)); + const { errors, onPollStalled } = run(); + + await waitFor(() => stub.answered.length >= 2); + + expect(errors.map((e) => e.status ?? e.code).slice(0, 2)).toEqual([504, 'cap_timeout']); + expect(onPollStalled).not.toHaveBeenCalled(); + }); + + test('a poll that outlives the liveness limit stops the loop and asks for an exit', async () => { + // A timeout longer than the liveness limit: the second net has to catch it. + process.env.COMMONLY_CAP_TIMEOUT_MS = '60000'; + stub = await startStub(() => 'hang'); + const { errors, onPollStalled } = run({ pollLivenessMs: 200, pollLivenessCheckMs: 20 }); + + await waitFor(() => onPollStalled.mock.calls.length === 1); + + expect(onPollStalled.mock.calls[0][0].stalledMs).toBeGreaterThanOrEqual(200); + expect(errors.at(-1).message).toMatch(/^poll stalled: no inbox poll settled for 1s/); + // Stopped: no second poll is ever sent. + await new Promise((resolve) => { setTimeout(resolve, 150); }); + expect(stub.polls).toHaveLength(1); + }); + + test('a turn longer than the liveness limit is not a stall', async () => { + process.env.COMMONLY_CAP_TIMEOUT_MS = '1000'; + stub = await startStub((n) => (n === 1 ? { events: [mentionFor('evt-long-turn')], inboxCount: 1 } : EMPTY)); + let turnEnded = 0; + const spawn = jest.fn(async () => { + await new Promise((resolve) => { setTimeout(resolve, 2500); }); + turnEnded = Date.now(); + return { text: '' }; + }); + const { onPollStalled } = run({ + adapter: { name: 'codex', detect: stubAdapter.detect, spawn }, + pollLivenessMs: 1000, + pollLivenessCheckMs: 50, + }); + + // The loop polls again after the 3s post-turn collection window. + await waitFor(() => stub.answered.length >= 2, 10000); + + expect(spawn).toHaveBeenCalledTimes(1); + expect(turnEnded).toBeGreaterThan(0); + expect(onPollStalled).not.toHaveBeenCalled(); + }, 15000); +}); + +describe('agent run: what the liveness clock covers', () => { + test('an ack that hangs after the turn is a stall too', async () => { + process.env.COMMONLY_CAP_TIMEOUT_MS = '60000'; + stub = await startStub((n) => (n === 1 ? { events: [mentionFor('evt-hung-ack')], inboxCount: 1 } : EMPTY), { + other: (req) => (req.url.includes('/ack') ? 'hang' : null), + }); + const spawn = jest.fn(async () => ({ text: '' })); + const { onPollStalled } = run({ + adapter: { name: 'codex', detect: stubAdapter.detect, spawn }, + pollLivenessMs: 300, + pollLivenessCheckMs: 20, + }); + + await waitFor(() => onPollStalled.mock.calls.length === 1); + expect(spawn).toHaveBeenCalledTimes(1); + expect(stub.others.some((line) => line.endsWith('/ack'))).toBe(true); + }); + + test('stop() during an in-flight poll is a stop, not a stall', async () => { + process.env.COMMONLY_CAP_TIMEOUT_MS = '5000'; + stub = await startStub(() => ({ events: [mentionFor('evt-stop-race')], inboxCount: 1 }), { delayMs: 300 }); + const spawn = jest.fn(async () => ({ text: '' })); + const { onPollStalled } = run({ + adapter: { name: 'codex', detect: stubAdapter.detect, spawn }, + pollLivenessMs: 200, + pollLivenessCheckMs: 20, + }); + await waitFor(() => stub.polls.length === 1); + stopLoop(); + + // Past the poll's answer and past the liveness limit. + await new Promise((resolve) => { setTimeout(resolve, 700); }); + expect(onPollStalled).not.toHaveBeenCalled(); + // The stopped loop leaves the page to requeue, as it did before this change. + expect(spawn).not.toHaveBeenCalled(); + expect(stub.polls).toHaveLength(1); + }); +}); + +describe('agent connect: the poller has the same liveness exit', () => { + test('a hung poll stops the poller and asks for an exit', async () => { + process.env.COMMONLY_CAP_TIMEOUT_MS = '60000'; + stub = await startStub(() => 'hang'); + const onPollStalled = jest.fn(); + const errors = []; + const { stop } = startPoller({ + instanceUrl: stub.url, + token: 'cm_agent_test', + agentName: 'my-stub', + intervalMs: 20, + onEvent: jest.fn(), + onError: (err) => errors.push(err), + pollLivenessMs: 200, + pollLivenessCheckMs: 20, + onPollStalled, + }); + stopLoop = stop; + + await waitFor(() => onPollStalled.mock.calls.length === 1); + expect(errors.at(-1).message).toMatch(/^poll stalled/); + }); +}); diff --git a/cli/__tests__/inbox.test.mjs b/cli/__tests__/inbox.test.mjs index 32955b51a6..e7e57a928b 100644 --- a/cli/__tests__/inbox.test.mjs +++ b/cli/__tests__/inbox.test.mjs @@ -28,6 +28,7 @@ const { const { extractToken, filterItems, nextCursorFrom, parseCursor, formatCursor, formatItemLine, createScrubber, retryDelayMs, DEFAULT_BACKOFF_MS, MAX_BACKOFF_MS, + createInboxRequest, InboxRequestError, } = await import('../src/lib/inbox.js'); const tmpDir = fs.mkdtempSync(path.join(os.tmpdir(), 'cli-inbox-')); @@ -1089,3 +1090,48 @@ describe('item line and pure helpers', () => { expect(printed.join('')).toContain('There is no fallback to the saved login'); }); }); + +// TASK-338: the inbox's own fetch gets the same hard timeout as every other CAP +// request, and a timeout, from the fetch or from the body read, reads as an +// unanswered request rather than a bare DOMException. +describe('a request that is never answered', () => { + // The limits below are the defaults; an operator's own override must not leak in. + const savedTimeout = process.env.COMMONLY_CAP_TIMEOUT_MS; + beforeEach(() => { delete process.env.COMMONLY_CAP_TIMEOUT_MS; }); + afterAll(() => { + if (savedTimeout !== undefined) process.env.COMMONLY_CAP_TIMEOUT_MS = savedTimeout; + }); + const timeoutError = () => new DOMException('The operation was aborted due to timeout', 'TimeoutError'); + const request = (fetchImpl) => createInboxRequest({ + baseUrl: 'https://example.test', token: 'cm_agent_x', tokenFile: '/tmp/t', fetchImpl, + }); + + test('sends a timeout signal with every request', async () => { + const fetchImpl = stubFetch({ '/api/activity/decision-queue': jsonRes({ items: [] }) }); + await request(fetchImpl)('/api/activity/decision-queue'); + expect(fetchImpl.calls[0].init.signal).toBeInstanceOf(AbortSignal); + }); + + test('a fetch that times out becomes an InboxRequestError with no status', async () => { + const err = await request(jest.fn(async () => { throw timeoutError(); }))('/api/activity/decision-queue') + .catch((e) => e); + expect(err).toBeInstanceOf(InboxRequestError); + expect(err.status).toBeNull(); + expect(err.message).toBe('GET /api/activity/decision-queue got no answer in 30s'); + }); + + test('so does a body read that times out', async () => { + const fetchImpl = jest.fn(async () => ({ ok: true, status: 200, text: async () => { throw timeoutError(); } })); + const err = await request(fetchImpl)('/api/activity/decision-queue', { method: 'POST', body: {} }) + .catch((e) => e); + expect(err).toBeInstanceOf(InboxRequestError); + expect(err.status).toBeNull(); + expect(err.message).toBe('POST /api/activity/decision-queue got no answer in 60s'); + }); + + test('any other fetch failure passes through unchanged', async () => { + const boom = new TypeError('fetch failed'); + const err = await request(jest.fn(async () => { throw boom; }))('/api/x').catch((e) => e); + expect(err).toBe(boom); + }); +}); diff --git a/cli/src/commands/agent.js b/cli/src/commands/agent.js index cb18583f76..8eacc09d30 100644 --- a/cli/src/commands/agent.js +++ b/cli/src/commands/agent.js @@ -55,6 +55,7 @@ import { import { catchUpBeforeTurn } from '../lib/pod-catch-up.js'; import { readLongTerm, syncBack } from '../lib/memory-bridge.js'; import { pollRetryPolicy } from '../lib/poll-retry.js'; +import { createPollLiveness, formatStall, resolvePollLivenessMs } from '../lib/poll-liveness.js'; import { detectMemorySources, composeImport, importMemory } from '../lib/memory-import.js'; import { detectSkills, importSkills, parseSkillMeta } from '../lib/skills-import.js'; import { compileServerSkills } from '../lib/server-skills.js'; @@ -1486,6 +1487,14 @@ export const performRun = ({ // ~/.commonly/state/turns/.jsonl once delivery settles. Off, the spawn // path is the plain adapter call it has always been, and nothing is written. superviseRuns, + // TASK-338. No poll settling for this long, outside a model turn and outside + // a scheduled wait, means the loop is wedged: it stops, says so through + // onError, and calls onPollStalled, which the `agent run` command turns into a + // non-zero exit for the keepalive to see. Undefined reads + // COMMONLY_POLL_LIVENESS_MS, then the ten-minute default (lib/poll-liveness.js). + pollLivenessMs, + pollLivenessCheckMs, + onPollStalled, }) => { const supervising = superviseRuns ?? superviseRunsByDefault(adapter?.name); reportRuntime = reportRuntime && WALKED_HARNESSES.includes(adapter?.name); @@ -1589,6 +1598,26 @@ export const performRun = ({ const MAX_AUTH_ERRORS = 3; let consecutivePollFailures = 0; let consecutiveSpawnFailures = 0; + let pollStalled = false; + const pollLiveness = createPollLiveness({ + limitMs: resolvePollLivenessMs(pollLivenessMs), + checkEveryMs: pollLivenessCheckMs, + onStall: ({ stalledMs }) => { + // A loop that already stopped itself (auth, a superseded delivery) is + // draining, not wedged. + if (!running) return; + pollStalled = true; + running = false; + pollLiveness.stop(); + // The same teardown as stop(): a held retry must not keep renewing its + // lease on a loop that will never deliver it. + clearHeldRenewal(); + const line = `poll stalled: no inbox poll settled for ${formatStall(stalledMs)} ` + + '— exiting so a clean process can take over'; + if (onError) onError(new Error(line)); else log(line); + onPollStalled?.({ stalledMs }); + }, + }); const spawnJitterRatio = retryJitterRatio ?? spawnRetryJitter(agentName); // Per-seat cascade state — lives with the process, like the session store. // A wrapper restart forgets the streak; the decay window covers that gap. @@ -3093,6 +3122,13 @@ export const performRun = ({ } }; + // A model turn is not a stall, however long it runs: the liveness clock + // stops for it and restarts when it ends. + const duringTurn = async (turn) => { + pollLiveness.pause(); + try { return await turn(); } finally { pollLiveness.arm(); } + }; + const tick = async () => { if (!running) return; let nextPollDelayMs = intervalMs; @@ -3106,10 +3142,19 @@ export const performRun = ({ // do not reintroduce a mixed-pod `limit: 10` here. // TASK-317: name this CLI for the chat chip. The server keeps it as a // display-only label (runtime.reportedCli) and never as a binding. - const { events = [], inboxCount } = await client.get('/api/agents/runtime/events', { + // The liveness clock runs from here until the next scheduled wait, paused + // only while a model turn runs (lib/poll-liveness.js). + pollLiveness.arm(); + const page = await client.get('/api/agents/runtime/events', { agentName, instanceId, limit: batchLimit, ...(adapter?.name ? { reportedCli: adapter.name } : {}), }); + pollLiveness.arm(); + // A stall fired while this request hung: the loop has already given up on + // it. A plain stop() falls through instead, to the group loop's own + // `running` check, which leaves the page's rows to requeue as it always has. + if (pollStalled) return; + const { events = [], inboxCount } = page; consecutiveAuthErrors = 0; consecutivePollFailures = 0; // A deployed CLI can briefly run against an older server that still @@ -3223,10 +3268,10 @@ export const performRun = ({ let batch; try { // The person's item leads the prompt; the greeting rides along. - batch = await processEventBatch( + batch = await duringTurn(() => processEventBatch( [...group].sort((a, b) => inboxPriority(a) - inboxPriority(b)), pageInboxCount, - ); + )); } catch (err) { await scheduleBatchRetry(err, group); break; @@ -3283,7 +3328,7 @@ export const performRun = ({ } else { const eventWillSpawn = Boolean(extractPrompt(event) && (event.podId || podId)); try { - result = await processEvent(event); + result = await duringTurn(() => processEvent(event)); } catch (err) { if (isContentRefusal(err)) { // A refused private item is acked without a pod notice: it has no @@ -3431,6 +3476,8 @@ export const performRun = ({ // before the next inbox read, independent of the idle polling cadence. A // retry scheduled in the same tick keeps its own delay: the failure report // names it, and a sibling's completed turn must not shorten the backoff. + // A wait the loop schedules itself always ends, so it is not a stall. + pollLiveness.pause(); if (running) setTimeoutImpl(tick, completedModelTurn && !retryScheduled ? 3000 : nextPollDelayMs); }; @@ -3438,6 +3485,7 @@ export const performRun = ({ return { stop: () => { running = false; + pollLiveness.stop(); clearHeldRenewal(); }, }; @@ -3822,6 +3870,8 @@ Docs: onError: (err) => { console.error(`[poll error] ${err.message}`); }, + // TASK-338: a wedged poll ends the process instead of idling forever. + onPollStalled: () => process.exit(1), }); // Graceful shutdown @@ -4194,6 +4244,9 @@ Docs: // collapsed the duplication. The conclusion survived the premise; the // sentence did not, and nothing in the diff pointed at it.) onError: (err) => console.error(`${stamp()} [${name}] ${err.message}`), + // TASK-338: a wedged poll ends the process, so tmux-keepalive or + // launchd KeepAlive, which act only on exit, start a clean one. + onPollStalled: () => process.exit(1), }); // SIGTERM is the daemon's idle-boundary handoff signal. `stop()` stops diff --git a/cli/src/lib/api.js b/cli/src/lib/api.js index b98eb1ab23..4f4e595207 100644 --- a/cli/src/lib/api.js +++ b/cli/src/lib/api.js @@ -56,7 +56,82 @@ const handleResponse = async (res, session = null) => { return body; }; -export const createClient = ({ instance = null, token = undefined } = {}) => { +// TASK-338: every CAP request carries a hard timeout. Without one, a request +// that a proxy or the network accepts and never answers leaves its promise +// pending for good, and the run loop awaiting it is alive but wedged: nib and +// folio each sat 8+ hours on one unanswered poll on 10-31, and their keepalives, +// which respawn only on exit, could not see it. The poll-retry backoff +// (TASK-025) only handles a fetch that throws, so a timeout throws: it is an +// ordinary failed request, retried with backoff, and never an ack. +// +// Reads get the base timeout; writes and uploads carry a body and a server-side +// write, so they get a multiple of it. COMMONLY_CAP_TIMEOUT_MS sets the base. +export const CAP_TIMEOUT_DEFAULT_MS = 30_000; +const TIMEOUT_SCALE = { read: 1, write: 2, upload: 4 }; + +export const capTimeoutMs = (kind, { baseMs, env = process.env } = {}) => { + const fromEnv = Number(env.COMMONLY_CAP_TIMEOUT_MS); + const base = [baseMs, fromEnv].find((value) => Number.isFinite(value) && value > 0) + ?? CAP_TIMEOUT_DEFAULT_MS; + return Math.min(base * (TIMEOUT_SCALE[kind] || 1), 2_147_483_647); +}; + +// A caller's own signal (doctor, and the 5s identity and skills reads in the +// run loop) still applies; the hard timeout is added beside it, never instead. +// AbortSignal.any is Node 20.3+, and `engines` allows 20.0, so the fallback +// joins the two by hand. Either way the abort carries the source's own reason, +// which is what nameTimeout matches on. +// The fallback's listeners are removed when the request settles, so a caller +// that reuses one long-lived signal does not collect one per request. +const capSignal = (capTimeout, callerSignal) => { + if (!callerSignal) return { signal: capTimeout, release: () => {} }; + if (typeof AbortSignal.any === 'function') { + return { signal: AbortSignal.any([callerSignal, capTimeout]), release: () => {} }; + } + const joined = new AbortController(); + const listeners = []; + for (const source of [callerSignal, capTimeout]) { + if (source.aborted) { + joined.abort(source.reason); + break; + } + const onAbort = () => joined.abort(source.reason); + source.addEventListener('abort', onAbort, { once: true }); + listeners.push([source, onAbort]); + } + return { + signal: joined.signal, + release: () => listeners.forEach(([source, onAbort]) => source.removeEventListener('abort', onAbort)), + }; +}; + +export const formatLimit = (ms) => (ms < 1000 ? `${ms}ms` : `${Math.round(ms / 1000)}s`); + +// The cap's timeout rejects with a DOMException named TimeoutError, from the +// fetch or from the body read. Name the request and the limit instead, so the +// log line reads as an unanswered request rather than "operation was aborted". +// Only the cap's own timeout is renamed: a caller's abort or its own shorter +// timeout passes through as it was thrown. +const nameTimeout = (capTimeout, method, path, ms) => (err) => { + // By identity: the caller's timeout can fire first and the cap's a moment + // later, and then `capTimeout.aborted` alone would claim the caller's error. + if (err?.name !== 'TimeoutError' || err !== capTimeout.reason) throw err; + throw Object.assign( + new Error(`${method} ${path} got no answer in ${formatLimit(ms)}`), + { code: 'cap_timeout', timeoutMs: ms }, + ); +}; + +const timedFetch = (url, init, { method, path, ms, session }) => { + const capTimeout = AbortSignal.timeout(ms); + const { signal, release } = capSignal(capTimeout, init.signal); + return fetch(url, { ...init, signal }) + .then((res) => handleResponse(res, session)) + .catch(nameTimeout(capTimeout, method, path, ms)) + .finally(release); +}; + +export const createClient = ({ instance = null, token = undefined, timeoutMs = undefined } = {}) => { const baseUrl = resolveInstanceUrl(instance); const resolved = resolveInstance(instance); const authToken = token === undefined ? getToken(instance) : token; @@ -64,30 +139,33 @@ export const createClient = ({ instance = null, token = undefined } = {}) => { instanceKey: resolved?.key || (typeof instance === 'string' && instance && !/^https?:\/\//i.test(instance) ? instance : 'default'), baseUrl, }; + const limit = (kind) => capTimeoutMs(kind, { baseMs: timeoutMs }); const get = (path, params = {}, options = {}) => { const url = new URL(`${baseUrl}${path}`); Object.entries(params).forEach(([k, v]) => v != null && url.searchParams.set(k, v)); - return fetch(url.toString(), { headers: headers(authToken), ...options }).then((res) => handleResponse(res, session)); + return timedFetch(url.toString(), { headers: headers(authToken), ...options }, { + method: 'GET', path, ms: limit('read'), session, + }); }; - const post = (path, body = {}) => fetch(`${baseUrl}${path}`, { + const post = (path, body = {}) => timedFetch(`${baseUrl}${path}`, { method: 'POST', headers: headers(authToken), body: JSON.stringify(body), - }).then((res) => handleResponse(res, session)); + }, { method: 'POST', path, ms: limit('write'), session }); - const patch = (path, body = {}) => fetch(`${baseUrl}${path}`, { + const patch = (path, body = {}) => timedFetch(`${baseUrl}${path}`, { method: 'PATCH', headers: headers(authToken), body: JSON.stringify(body), - }).then((res) => handleResponse(res, session)); + }, { method: 'PATCH', path, ms: limit('write'), session }); - const del = (path, body) => fetch(`${baseUrl}${path}`, { + const del = (path, body) => timedFetch(`${baseUrl}${path}`, { method: 'DELETE', headers: headers(authToken), ...(body === undefined ? {} : { body: JSON.stringify(body) }), - }).then((res) => handleResponse(res, session)); + }, { method: 'DELETE', path, ms: limit('write'), session }); // Multipart upload via native FormData/Blob (Node 18+) — no runtime deps. // Content-Type is deliberately NOT set: fetch writes the multipart boundary. @@ -103,11 +181,11 @@ export const createClient = ({ instance = null, token = undefined } = {}) => { for (const [k, v] of Object.entries(fields)) { if (v !== undefined && v !== null) form.append(k, String(v)); } - return fetch(`${baseUrl}${path}`, { + return timedFetch(`${baseUrl}${path}`, { method: 'POST', headers: authToken ? { Authorization: `Bearer ${authToken}` } : {}, body: form, - }).then((res) => handleResponse(res, session)); + }, { method: 'POST', path, ms: limit('upload'), session }); }; return { @@ -116,11 +194,11 @@ export const createClient = ({ instance = null, token = undefined } = {}) => { }; // Convenience: login doesn't need a token -export const login = async (instanceUrl, email, password) => { - const res = await fetch(`${instanceUrl}/api/auth/login`, { +export const login = (instanceUrl, email, password) => { + const ms = capTimeoutMs('write'); + return timedFetch(`${instanceUrl}/api/auth/login`, { method: 'POST', headers: { 'Content-Type': 'application/json' }, body: JSON.stringify({ email, password }), - }); - return handleResponse(res); + }, { method: 'POST', path: '/api/auth/login', ms, session: null }); }; diff --git a/cli/src/lib/inbox.js b/cli/src/lib/inbox.js index 4c942bc784..2fd8b12ee1 100644 --- a/cli/src/lib/inbox.js +++ b/cli/src/lib/inbox.js @@ -62,6 +62,7 @@ import { mkdirSync, readFileSync, renameSync, writeFileSync } from 'fs'; import { dirname } from 'path'; +import { capTimeoutMs, formatLimit } from './api.js'; export const INBOX_KINDS = ['mention', 'decision', 'handoff', 'approval']; export const TOKEN_FILE_ENV = 'COMMONLY_TOKEN_FILE'; @@ -394,19 +395,29 @@ export const createInboxRequest = ({ for (const [key, value] of Object.entries(params)) { if (value !== undefined && value !== null) url.searchParams.set(key, String(value)); } + // TASK-338: the same hard timeout as every other CAP request (api.js). + const timeoutMs = capTimeoutMs(method === 'GET' ? 'read' : 'write'); for (let attempt = 0; ; attempt += 1) { - // eslint-disable-next-line no-await-in-loop - const res = await fetchImpl(url.toString(), { - method, - headers: { - Authorization: `Bearer ${token}`, - 'Content-Type': 'application/json', - 'User-Agent': 'commonly-cli/0.1', - }, - ...(body === undefined ? {} : { body: JSON.stringify(body) }), - }); - // eslint-disable-next-line no-await-in-loop - const text = await res.text(); + let res; + let text; + try { + // eslint-disable-next-line no-await-in-loop + res = await fetchImpl(url.toString(), { + method, + headers: { + Authorization: `Bearer ${token}`, + 'Content-Type': 'application/json', + 'User-Agent': 'commonly-cli/0.1', + }, + ...(body === undefined ? {} : { body: JSON.stringify(body) }), + signal: AbortSignal.timeout(timeoutMs), + }); + // eslint-disable-next-line no-await-in-loop + text = await res.text(); + } catch (err) { + if (err?.name !== 'TimeoutError') throw err; + throw new InboxRequestError(`${method} ${path} got no answer in ${formatLimit(timeoutMs)}`, null); + } let parsed; try { parsed = JSON.parse(text); diff --git a/cli/src/lib/poll-liveness.js b/cli/src/lib/poll-liveness.js new file mode 100644 index 0000000000..1545824db9 --- /dev/null +++ b/cli/src/lib/poll-liveness.js @@ -0,0 +1,60 @@ +/** + * Poll liveness for the inbox loops (TASK-338). + * + * The hard timeout in api.js bounds every CAP request, so no single request can + * hang for good any more. This is the second net, for a loop that stops making + * progress anyway: if no poll has settled within the limit while the loop was + * doing its own work, it is wedged, and the only thing that heals it is a fresh + * process. Measured on 10-31: nib's and folio's loops sat 8+ hours on one + * unanswered request, alive the whole time, and their keepalives (tmux, launchd + * KeepAlive) respawn only on exit. So a stall ends the process, loudly, and the + * keepalive does the rest. + * + * The clock runs while the loop is polling, acking or holding work, and is + * paused while a model turn runs and while the loop waits on its own scheduled + * retry. A two-hour turn never trips it, and neither does a fifteen-minute + * backoff: those always end on their own. A settled poll or a finished turn + * restarts the clock. + * + * Monotonic time, not Date.now: a laptop seat that sleeps, or a clock corrected + * by ten minutes, must not read as a stall. + */ +import { performance } from 'perf_hooks'; + +export const POLL_LIVENESS_DEFAULT_MS = 10 * 60 * 1000; + +export const resolvePollLivenessMs = (value, env = process.env) => { + const candidate = [value, Number(env.COMMONLY_POLL_LIVENESS_MS)] + .find((ms) => Number.isFinite(ms) && ms > 0); + return candidate ?? POLL_LIVENESS_DEFAULT_MS; +}; + +export const formatStall = (ms) => (ms < 60_000 + ? `${Math.max(1, Math.round(ms / 1000))}s` + : `${Math.round(ms / 60_000)} min`); + +export const createPollLiveness = ({ limitMs, onStall, checkEveryMs }) => { + let armedSince = null; + let stalled = false; + // A quarter of the limit, so a stall is caught within 1.25x of it, bounded + // to a check a second at most and one a minute at least. + const every = Number.isFinite(checkEveryMs) && checkEveryMs > 0 + ? checkEveryMs + : Math.min(60_000, Math.max(1000, Math.floor(limitMs / 4))); + const timer = setInterval(() => { + if (stalled || armedSince === null) return; + const stalledMs = performance.now() - armedSince; + if (stalledMs < limitMs) return; + stalled = true; + onStall({ stalledMs, limitMs }); + }, every); + // The check must never be what keeps a stopped loop's process alive. + timer.unref?.(); + return { + // (Re)start the clock: the loop is doing its own work, or just made progress. + arm: () => { armedSince = performance.now(); }, + // Stop the clock: a model turn, or a wait the loop scheduled itself. + pause: () => { armedSince = null; }, + stop: () => { clearInterval(timer); }, + }; +}; diff --git a/cli/src/lib/poller.js b/cli/src/lib/poller.js index da56a9743d..aad58930ba 100644 --- a/cli/src/lib/poller.js +++ b/cli/src/lib/poller.js @@ -9,6 +9,7 @@ import { createClient } from './api.js'; import { formatDigestFrame } from './digest-frame.js'; import { EMPTY_OUTPUT } from './claim-outcome.js'; +import { createPollLiveness, formatStall, resolvePollLivenessMs } from './poll-liveness.js'; // Delivery failures that must stop a consumer rather than fall through to the // normal at-least-once retry path. A stale delivery belongs to a replacement @@ -39,6 +40,9 @@ export const startPoller = ({ loginInstance, // the --instance the connect ran with, so the login hint names it onEvent, // async (event) => { outcome, content? } onError, // (err) => void + pollLivenessMs, // TASK-338: see lib/poll-liveness.js + pollLivenessCheckMs, + onPollStalled, // ({ stalledMs }) => void; the connect command exits on it }) => { const client = createClient({ instance: instanceUrl, token }); let running = true; @@ -49,16 +53,35 @@ export const startPoller = ({ // reprovision-all; 5+ wastes rate-limit budget after the real-revoke case. let consecutiveAuthErrors = 0; const MAX_AUTH_ERRORS = 3; + let pollStalled = false; + const pollLiveness = createPollLiveness({ + limitMs: resolvePollLivenessMs(pollLivenessMs), + checkEveryMs: pollLivenessCheckMs, + onStall: ({ stalledMs }) => { + if (!running) return; + pollStalled = true; + running = false; + pollLiveness.stop(); + onError?.(new Error(`poll stalled: no inbox poll settled for ${formatStall(stalledMs)} — stopping poller`)); + onPollStalled?.({ stalledMs }); + }, + }); const poll = async () => { if (!running) return; try { - const { events = [] } = await client.get('/api/agents/runtime/events', { + // Same clock as `agent run`: running from here to the scheduled wait, + // paused while the local handler takes the event. + pollLiveness.arm(); + const page = await client.get('/api/agents/runtime/events', { agentName, instanceId, limit: 10, }); + pollLiveness.arm(); + if (pollStalled) return; + const { events = [] } = page; // A digest is received context, not a webhook invocation. The runtime // inbox claims it only alongside a wake from the same pod. @@ -83,9 +106,12 @@ export const startPoller = ({ let result = { outcome: 'no_action' }; try { // A handler that returns nothing said nothing: not a read of the digest. + pollLiveness.pause(); result = (await onEvent(forwarded)) || { outcome: 'no_action', reason: EMPTY_OUTPUT }; } catch (handlerErr) { result = { outcome: 'error', reason: handlerErr.message }; + } finally { + pollLiveness.arm(); } // Acknowledge the event @@ -150,11 +176,14 @@ export const startPoller = ({ } consecutiveErrors++; onError?.(err); - // Back off on repeated errors (max 60s) + // Back off on repeated errors (max 60s). A wait this loop scheduled + // itself always ends, so the liveness clock stops for it. const backoff = Math.min(intervalMs * consecutiveErrors, 60_000); + pollLiveness.pause(); await new Promise((r) => setTimeout(r, backoff)); } + pollLiveness.pause(); if (running) setTimeout(poll, intervalMs); }; @@ -162,6 +191,9 @@ export const startPoller = ({ poll(); return { - stop: () => { running = false; }, + stop: () => { + running = false; + pollLiveness.stop(); + }, }; }; diff --git a/docs/cli/README.md b/docs/cli/README.md index 1e5b331884..f6c35eb5bd 100644 --- a/docs/cli/README.md +++ b/docs/cli/README.md @@ -300,6 +300,8 @@ Written by `commonly agent run` during spawn cycles. Per-pod session IDs so wrap |----------|--------| | `COMMONLY_TOKEN` | Overrides the saved user token for every command (CI / scripts). | | `COMMONLY_BASE_URL` | Overrides the base URL (Python SDK `run()` honors this). | +| `COMMONLY_CAP_TIMEOUT_MS` | How long a request to Commonly may go unanswered before it fails, in ms. Default 30000 for reads; writes get twice that and uploads four times. A timed-out poll is retried with backoff like any other failed request. Keep it well below `COMMONLY_POLL_LIVENESS_MS`, or a slow answer becomes an exit instead of a retry. | +| `COMMONLY_POLL_LIVENESS_MS` | How long `agent run` or `agent connect` may go without a poll settling before it exits non-zero, in ms. Default 600000 (10 minutes). Time inside a model turn and the loop's own retry waits doesn't count. | | `COMMONLY_NO_UPDATE_CHECK=1` | Silences the start-up "your CLI is N versions behind" line on `agent run` and `daemon run`. `daemon install` carries it into the service when set ([doctor.md](doctor.md)). | --- @@ -371,6 +373,10 @@ commonly agent detach --force See [LOCAL_CLI_WRAPPER.md §Token revocation](../agents/LOCAL_CLI_WRAPPER.md#token-revocation). +### `commonly agent run` exits with "poll stalled: no inbox poll settled" + +For 10 minutes (`COMMONLY_POLL_LIVENESS_MS`) the loop polled, acked or held work without a poll ever settling, which means a request it was waiting on never ended. The loop exits non-zero on purpose, so a keepalive (tmux, launchd, systemd), which acts only on exit, starts a clean process. Before this exit, a loop in that state stayed alive and idle until someone killed it. If you run `agent run` by hand, start it again. If it keeps happening, the network or a proxy between you and the instance is holding requests open. + ### `commonly agent run` fails with `spawn claude ENOENT` Two causes look identical: