diff --git a/.ai/contexts/trigger-watcher.md b/.ai/contexts/trigger-watcher.md index 1cf5f8b2..388e7471 100644 --- a/.ai/contexts/trigger-watcher.md +++ b/.ai/contexts/trigger-watcher.md @@ -834,13 +834,11 @@ wired to `cliSessionState.getStatus` in `main.js`; `undefined` for a remote session, which has no local descriptor). No new watcher: it reuses the cache `cli-session-state.js` already keeps. -- **Readiness.** A chain step that follows a `/compact` step first waits +- **Readiness.** (Extended to every step, see the next section.) A chain step that follows a `/compact` step first waits (`waitForCliIdleAfter`) for `status: "idle"` with a `statusUpdatedAt` later - than the compact step's send time. Bounded by - `SWITCHBOARD_CLI_READY_WAIT_MS` (default 60 000 ms) and by the step's own - deadline; on expiry the step is written anyway, with the warning `CLI not - idle after /compact within N ms, writing chain step N anyway`. Its time is - counted in the step's and the chain's `waited_ms`. + than the compact step's Enter. Bounded by the step's own deadline; on + expiry the step is not written (see the next section). Its time is counted + in the step's and the chain's `waited_ms`. - **Proof of submission by edge.** When a descriptor with an integer `statusUpdatedAt` is available, a submission counts when the descriptor shows ANY status write (`busy`, `idle` or `waiting`) with a @@ -885,6 +883,80 @@ named, not that the first Enter always lands. Tests: `test/trigger-descriptor-proof.test.js` (fake timers and a fake descriptor for the helpers; the real watcher for the chain wiring). +### Readiness before every step, and the descriptor as busy-fall authority (issues #407, #360) + +Second field case (2026-10-02): step 0 of a `compact-now.sh` chain, with no +`/compact` before it, landed in the composer and its Enter became a line +break, while four background subagents had just been spawned (three still +running). The #407 readiness wait only covered the step after a `/compact`; +nothing waited before step 0. + +**The mechanism is NOT established.** The working hypothesis is that text +written while the CLI is mid-turn has its Enter absorbed as a newline, but #360 +shows the opposite: a step written mid-turn was enqueued and submitted +normally. What is known is only that the step was typed while the descriptor +read `busy`. The rule below stops typing in that state; it does not prove that +state was the cause. + +- **The wait runs before EVERY chain step**, step 0 included + (`waitForCliIdleAfter`, after the composer-free and liveness checks, so the + descriptor is read as close to the write as possible). Before a step that + follows `/compact` the idle must also be newer than the compact's Enter + (`enterAt` from `submitWithVerify`); before any other step any `idle` counts. + The idle must hold for the busy-fall settle window + (`SWITCHBOARD_BUSY_FALL_SETTLE_MS`, 300 ms) with an unchanged + `statusUpdatedAt`, so a `busy` that follows an `idle` within the window is + not mistaken for readiness. +- **The wait is bounded by the step's own deadline only** (the per-step + `timeout_ms`, capped by the chain's). `SWITCHBOARD_CLI_READY_WAIT_MS` is gone. + A parent session keeps its descriptor `busy` for as long as a delegated + agent runs (`cli-session-state.md`), so a shorter bound would write into the + very state this rule exists for. +- **Not idle at the deadline means not written, whatever the status**: + `busy`, `waiting` (a dialog is open) and any status this code does not know + (e.g. `shell`) are all not-idle and not-writable. The step fails: result + `ok: false`, `error` `not sent` (step 0) or `chain timeout` (later steps), + `submitted` the weakest of the chain so far, the step recorded with + `submitted: "no"`, and a `reason` naming the cause (dialog open, turn still + running, never idle). A dialog is reported when `waiting` was sampled + anywhere in the final settle window, not only on the last sample. +- **A step typed but not confirmed, with the recovery Enter withheld** (the + descriptor reads `busy` or `waiting` and showed no reaction to our Enter) + stops the chain: `ok: false`, `error` `step not confirmed`, nothing more is + typed into that composer. The step's text may be sitting there. The + recovery Enter is also withheld when input of the user's own is pending in + the composer (`waitForComposerFree`), which stops the chain the same way. +- **No usable descriptor at the FIRST read of the wait** (the wait owns this decision: there is no separate precheck, so a descriptor read once and lost at the next sample is "not idle", never the legacy path) (`getCliStatus` absent, + `undefined`, or a `statusUpdatedAt` that is not an integer): no wait, today's + behaviour (`available: false`). A descriptor lost AFTER it was read (the CLI + rewriting its file, a failed pid probe, a momentary bad timestamp) is not the + same: it may reappear, so the wait goes on, counted as not idle, until the + deadline, then fails like any not-idle case. Nothing is typed on the strength + of a descriptor that merely vanished. +- **Never ready past the deadline, never written past it.** A settle that + completes at or after the deadline is a timeout, not readiness, and the + deadline is checked again immediately before the write (a step timeout of 0 + or a settle of 0 included): the step fails with `not sent`/`chain timeout` + and the reason "the step deadline passed before it could be written". +- **`waitForCliIdleAfter` return shape**: `{ ready, available, timedOut, + sessionExited, waited_ms, lastStatus, waitingSeen }`. `lastStatus` is the + status at the last sample; `waitingSeen` is true when `waiting` was sampled + within the last settle window before the end. +- **Single triggers have the same exposure and it is not addressed here.** + They keep their own `wait` field (`idle` by the level probe, or `none`) and + no descriptor wait; they can still be typed into a busy composer. +- **Busy-fall authority (#360).** `waitForBusyFall` receives the Enter's + timestamp. A descriptor `idle` with `statusUpdatedAt >= enterAt`, held for the + settle window, ends the wait even when `_cliBusy` is stuck true. An idle + older than the Enter proves nothing (the Enter may have been absorbed) and + leaves the `_cliBusy` logic in charge, as it does when no usable descriptor + exists. Not measured as fixed for sessions with background agents: the + descriptor stays `busy` until the last agent ends, so the busy-fall still + waits for it. + +Tests: `test/trigger-every-step-readiness.test.js` (the real watcher with a +fake descriptor, plus the wait helpers under mocked timers). + ### Why `composerEmptyAfterWrite` cannot be made to prove submission, even by feeding it our own writes A proposal, considered and rejected 2026-09-04: since `submitToPty` writes diff --git a/CHANGELOG.md b/CHANGELOG.md index a3b913d3..b3b7619a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,8 +10,8 @@ What changes for you in each release of Switchboard. How to write an entry: [doc ### Changed - After three failed refreshes of a remote host in a row, a row that would have attached opens its transcript and says why in its tooltip, instead of failing when clicked. Stop is never disabled: it runs its own ssh. (#218) ### Fixed +- A step of a trigger chain, the first one included, is no longer typed while the CLI reads busy or waiting on a dialog: it waits for the CLI to be at its prompt, up to the step's deadline, then fails cleanly with a reason instead of being written; a step whose Enter did not start a turn is retried once, or stops the chain when that retry is withheld because the CLI is busy or waiting on a dialog, or you have typed input pending, and is reported as "not confirmed submitted" instead of "sent". Without a readable CLI descriptor a step is still written as before, but no longer once its own deadline has passed. Single triggers are not covered. (#407, #360) - After an upgrade, schedules keep running in a project that has settings of its own and in a git checkout that already holds a schedule; any other project, opened before the upgrade or not, runs no schedule until you open a session in it or add it. (#385) -- A step of a trigger chain that follows `/compact` now waits for the CLI to be back at its prompt before it is written, and a step whose Enter did not start a turn is retried once and then reported as "not confirmed submitted" in the log and the result instead of "sent". (#407) - Stopping a terminal twice in quick succession, or resizing it while it is being stopped, no longer closes the Windows pseudo console twice, which could kill the whole app with no error. (#405) - A sandboxed session, or a sandboxed schedule, whose Additional Directories include a `.claude` or `.git` directory, or a path inside one, is now refused instead of binding it read-write over its read-only protection; add the project directory instead. A session started in a `.claude` or `.git` directory is refused too, except below `.claude/worktrees`, and Additional Directories naming your home directory or a parent of it are refused however the path is written. A relative `add-dirs` entry in a schedule is taken from the schedule's directory. (#385) - A session that has exited no longer keeps a busy dot in the sidebar, and the status bar's running count drops as soon as the session ends instead of waiting for the next refresh. (#375) diff --git a/docs/automation.md b/docs/automation.md index 85b4f59a..ab4ea40c 100644 --- a/docs/automation.md +++ b/docs/automation.md @@ -264,7 +264,6 @@ spends the same budget. | `SWITCHBOARD_TRIGGER_MAX_AGE_MS` | The staleness limit | 300 000 | | `SWITCHBOARD_SUBMIT_ENTER_DELAY_MS` | Delay between the text and its Enter | 50 | | `SWITCHBOARD_SUBMIT_VERIFY_MS` | How long a submission is watched for a turn | 2 000 | -| `SWITCHBOARD_CLI_READY_WAIT_MS` | How long a chain step after `/compact` waits for the CLI to report idle | 60 000 | | `SWITCHBOARD_BUSY_FALL_SETTLE_MS` | How long "not busy" must hold between chain steps | 300 | The triggers directory does not move with `SWITCHBOARD_DATA_DIR`: an instance @@ -435,6 +434,7 @@ never in `error`: `not sent: input pending` is not `not sent`. |---|---|---| | `not sent` | **not one byte reached the session**: no idle came, politeness never allowed a write, or the trigger was refused before any write (stale, bad `wait`, bad `expectedCwd`, target guard) | nothing happened; it is safe to send again | | `chain timeout` | at least one step **was written**, and the expected effect was not observed before the deadline | assume the written steps landed | +| `step not confirmed` | a chain step **was written**, its submission was not confirmed by the CLI's descriptor, and the recovery Enter was withheld (the descriptor reads `busy` or `waiting`, or input of your own is pending in the composer); the chain stopped there and nothing more was typed | the step may sit unsubmitted in the composer: look before sending again | | anything else | free text: `session not found`, `target process not running`, `missing required field`, `invalid timeout_ms`, `command and chain are mutually exclusive`, `trigger too large (max 64 KB)`, `command too long (max 4 KB)`, `trigger must be a regular file`, `pty write failed: …` | read `submitted` to know whether anything landed | The two reserved values mean opposite things: @@ -447,6 +447,7 @@ The two reserved values mean opposite things: `partial: false` for a `chain`. A session reports itself busy for as long as any subagent runs, so `idle` is often unreachable; `not sent` there tells the caller the payload never left. +- A chain step is held until the CLI's descriptor reads `idle`, up to the step's deadline. If it still reads `busy` or `waiting` (or any status other than `idle`) then, the step is not written: `not sent` for the first step, `chain timeout` for a later one, with the cause in `reason`. A session with delegated agents running keeps the parent descriptor `busy`, so such a chain fails cleanly instead of typing into a busy composer. Without a readable descriptor at the first read nothing is waited for, but a step is never written once its own deadline has passed (it then fails `not sent` or `chain timeout`). - A session that exits during that initial wait reports `submitted: "no"` and a `reason` saying nothing was written (`partial: false` on a chain). diff --git a/test/trigger-descriptor-proof.test.js b/test/trigger-descriptor-proof.test.js index 61c085ae..f6e92bc2 100644 --- a/test/trigger-descriptor-proof.test.js +++ b/test/trigger-descriptor-proof.test.js @@ -263,14 +263,14 @@ function chainSession(sessionId, { log, onEnter }) { return { ctx, written, desc, setBusy(v) { busy = v; } }; } -async function runChain(chain, session, uuid) { +async function runChain(chain, session, uuid, timeoutMs = 20000) { const tmp = mkTmp(); process.env.SWITCHBOARD_TRIGGERS_DIR = tmp; process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS = '2000'; const watcher = start(session.ctx); try { fs.writeFileSync(path.join(tmp, uuid + '.json'), - JSON.stringify({ sessionId: uuid, wait: 'idle', chain, timeout_ms: 20000 }), 'utf8'); + JSON.stringify({ sessionId: uuid, wait: 'idle', chain, timeout_ms: timeoutMs }), 'utf8'); const resultPath = path.join(tmp, 'processed', uuid + '.result.json'); const deadline = Date.now() + 15000; while (!fs.existsSync(resultPath)) { @@ -321,38 +321,33 @@ test('chain: the step after /compact is held until the descriptor is idle after assert.ok(!log.lines.some((l) => /Chain step 1 sent/.test(l.text))); }); -test('chain: a CLI that never goes idle after /compact -> bounded wait, warning, step still written', async () => { - process.env.SWITCHBOARD_CLI_READY_WAIT_MS = '300'; - try { - const uuid = 'sess-desc-timeout-' + Date.now(); - const log = recordingLog(); - const session = chainSession(uuid, { - log, - onEnter(n, desc) { - if (n === 1) { - desc.status = 'busy'; desc.statusUpdatedAt = Date.now(); - setTimeout(() => session.setBusy(false), 60); - } - }, - }); - session.setBusy(false); +test('chain: a CLI that never goes idle after /compact -> held to the step deadline, step never written, chain fails', async () => { + const uuid = 'sess-desc-timeout-' + Date.now(); + const log = recordingLog(); + const session = chainSession(uuid, { + log, + onEnter(n, desc) { + if (n === 1) { + desc.status = 'busy'; desc.statusUpdatedAt = Date.now(); + setTimeout(() => session.setBusy(false), 60); + } + }, + }); + session.setBusy(false); - const started = Date.now(); - const result = await runChain([{ command: '/compact' }, { command: 'resume the work' }], session, uuid); + const started = Date.now(); + const result = await runChain([{ command: '/compact' }, { command: 'resume the work' }], session, uuid, 2500); - const nextText = session.written.find((w) => w.data === 'resume the work'); - assert.ok(nextText, 'the step must still be written after the bounded wait'); - assert.ok(log.lines.some((l) => l.level === 'warn' && /CLI not idle after \/compact/.test(l.text))); - assert.ok(nextText.at - started >= 300, 'the readiness wait must have been honoured up to its bound'); - assert.equal(result.ok, true); - } finally { - delete process.env.SWITCHBOARD_CLI_READY_WAIT_MS; - } + assert.ok(!session.written.some((w) => w.data === 'resume the work'), 'a step must never be typed while the CLI reads busy'); + assert.ok(Date.now() - started >= 2000, 'the wait must run to the step deadline'); + assert.equal(result.ok, false); + assert.equal(result.error, 'chain timeout'); + assert.match(result.reason, /busy/); + assert.equal(result.steps_completed, 1); }); test('chain: an Enter that never starts a turn is reported "not confirmed submitted", never "sent"', async () => { - process.env.SWITCHBOARD_CLI_READY_WAIT_MS = '200'; - try { + { const uuid = 'sess-desc-unconfirmed-' + Date.now(); const log = recordingLog(); const session = chainSession(uuid, { @@ -374,7 +369,5 @@ test('chain: an Enter that never starts a turn is reported "not confirmed submit assert.equal(result.steps[1].submitted, 'assumed'); assert.deepEqual(result.unconfirmed_steps, [1]); assert.equal(result.submitted, 'assumed'); - } finally { - delete process.env.SWITCHBOARD_CLI_READY_WAIT_MS; } }); diff --git a/test/trigger-every-step-readiness.test.js b/test/trigger-every-step-readiness.test.js new file mode 100644 index 00000000..4a3a6ffa --- /dev/null +++ b/test/trigger-every-step-readiness.test.js @@ -0,0 +1,421 @@ +// test/trigger-every-step-readiness.test.js +// +// The descriptor readiness wait before EVERY chain step, and the descriptor as +// the authority for the busy-fall wait. See +// .ai/contexts/trigger-watcher.md, "Readiness before every step". +'use strict'; + +process.env.SWITCHBOARD_SUBMIT_ENTER_DELAY_MS = '1'; +process.env.SWITCHBOARD_SUBMIT_VERIFY_MS = '400'; +process.env.SWITCHBOARD_BUSY_FALL_SETTLE_MS = '50'; +process.env.SWITCHBOARD_BUSY_RISE_WAIT_MS = '100'; + +const test = require('node:test'); +const assert = require('node:assert/strict'); +const fs = require('fs'); +const os = require('os'); +const path = require('path'); + +const { start, waitForBusyFall, waitForCliIdleAfter } = require('../trigger-watcher'); + +function mkTmp() { + return fs.realpathSync.native(fs.mkdtempSync(path.join(os.tmpdir(), 'sw-trigger-every-'))); +} + +function recordingLog() { + const lines = []; + const mk = (level) => (...args) => { lines.push({ level, text: args.join(' ') }); }; + return { lines, info: mk('info'), warn: mk('warn'), error: mk('error'), debug: () => {} }; +} + +function chainSession(sessionId, { log, onEnter, withDescriptor = true }) { + const written = []; + const desc = { status: 'idle', statusUpdatedAt: Date.now() - 10_000 }; + const ptyProcess = { + pid: process.pid, + write(data) { + written.push({ data, at: Date.now() }); + if (data === '\r') onEnter(written.filter((w) => w.data === '\r').length, desc); + }, + }; + let busy = false; + const ctx = { + log, + getPtyForSession: (id) => (id === sessionId ? { ptyProcess } : null), + isSessionBusy: () => busy, + isPtyAlive: () => true, + getComposerState: () => ({ pending: 0, lastInputAt: 0 }), + }; + if (withDescriptor) ctx.getCliStatus = (id) => (id === sessionId ? { ...desc } : undefined); + return { ctx, written, desc, setBusy(v) { busy = v; } }; +} + +async function runChain(chain, session, uuid, timeoutMs = 20000) { + const tmp = mkTmp(); + process.env.SWITCHBOARD_TRIGGERS_DIR = tmp; + process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS = '2000'; + const watcher = start(session.ctx); + try { + fs.writeFileSync(path.join(tmp, uuid + '.json'), + JSON.stringify({ sessionId: uuid, wait: 'idle', chain, timeout_ms: timeoutMs }), 'utf8'); + const resultPath = path.join(tmp, 'processed', uuid + '.result.json'); + const deadline = Date.now() + 15000; + while (!fs.existsSync(resultPath)) { + if (Date.now() > deadline) throw new Error('no result file'); + await new Promise((r) => setTimeout(r, 20)); + } + await new Promise((r) => setTimeout(r, 20)); + return JSON.parse(fs.readFileSync(resultPath, 'utf8')); + } finally { + watcher.close(); + delete process.env.SWITCHBOARD_TRIGGERS_DIR; + delete process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS; + fs.rmSync(tmp, { recursive: true, force: true }); + } +} + +function quickTurn(session) { + return (_n, desc) => { + desc.status = 'busy'; desc.statusUpdatedAt = Date.now(); + setTimeout(() => { desc.status = 'idle'; desc.statusUpdatedAt = Date.now(); }, 100); + }; +} + +test('step 0 while the descriptor reads busy: nothing is written until it reads idle', async () => { + { + const uuid = 'sess-every-busy-' + Date.now(); + const session = chainSession(uuid, { log: recordingLog(), onEnter: (n, d) => quickTurn(session)(n, d) }); + session.desc.status = 'busy'; + session.desc.statusUpdatedAt = Date.now(); + let idleAt = null; + setTimeout(() => { session.desc.status = 'idle'; session.desc.statusUpdatedAt = Date.now(); idleAt = Date.now(); }, 700); + + const result = await runChain([{ command: 'first step' }], session, uuid); + + assert.ok(idleAt, 'the descriptor never went idle'); + assert.equal(session.written[0].data, 'first step'); + assert.ok(session.written[0].at >= idleAt, `step 0 written ${idleAt - session.written[0].at} ms before the descriptor read idle`); + assert.equal(result.ok, true); + } +}); + +test('a dialog open ("waiting"): never written into, the step fails at the deadline with the dialog reason', async () => { + { + const uuid = 'sess-every-waiting-' + Date.now(); + const session = chainSession(uuid, { log: recordingLog(), onEnter: () => {} }); + session.desc.status = 'waiting'; + session.desc.statusUpdatedAt = Date.now(); + + const result = await runChain([{ command: 'first step' }, { command: 'second step' }], session, uuid, 1500); + + assert.deepEqual(session.written, []); + assert.equal(result.ok, false); + assert.equal(result.error, 'not sent'); + assert.match(result.reason, /dialog/); + assert.equal(result.steps_completed, 0); + assert.equal(result.steps[0].submitted, 'no'); + } +}); + +test('#360: _cliBusy stuck true but the descriptor idle after the Enter -> the chain proceeds to step 1', async () => { + const uuid = 'sess-every-stuck-' + Date.now(); + const session = chainSession(uuid, { + log: recordingLog(), + onEnter(n, desc) { + session.setBusy(true); + quickTurn(session)(n, desc); + }, + }); + + const result = await runChain([{ command: 'first step' }, { command: 'second step' }], session, uuid, 4000); + + assert.ok(session.written.some((w) => w.data === 'second step'), 'step 1 was never written'); + assert.equal(result.ok, true); +}); + +test('no descriptor: the chain behaves as before, nothing waits before step 0', async () => { + const uuid = 'sess-every-none-' + Date.now(); + const session = chainSession(uuid, { + log: recordingLog(), + withDescriptor: false, + onEnter(n) { + session.setBusy(true); + setTimeout(() => session.setBusy(false), 100); + }, + }); + + const started = Date.now(); + const result = await runChain([{ command: 'first step' }, { command: 'second step' }], session, uuid); + + assert.ok(session.written[0].at - started < 1000, 'step 0 was held although no descriptor exists'); + assert.deepEqual(session.written.map((w) => w.data).filter((d) => d !== '\r'), ['first step', 'second step']); + assert.equal(result.ok, true); +}); + +test('waitForBusyFall: a descriptor idle that predates the Enter does not end the wait', async (t) => { + t.mock.timers.enable({ apis: ['Date', 'setTimeout'], now: 1_000_000 }); + const ctx = { + getPtyForSession: () => ({}), + isSessionBusy: () => true, + getCliStatus: () => ({ status: 'idle', statusUpdatedAt: 999_000 }), + }; + const p = waitForBusyFall('sid', ctx, 1_000_000 + 2000, 1_000_000); + let result; + p.then((r) => { result = r; }); + for (let i = 0; i < 600 && !result; i += 1) { + t.mock.timers.tick(5); + await new Promise((r) => setImmediate(r)); + } + assert.equal(result.timedOut, true); +}); + +for (const status of ['busy', 'shell']) { + test(`step 0 while the descriptor reads "${status}" to the deadline: never written, the step fails "not sent" with a reason`, async () => { + const uuid = 'sess-every-never-' + status + Date.now(); + const session = chainSession(uuid, { log: recordingLog(), onEnter: () => {} }); + session.desc.status = status; + session.desc.statusUpdatedAt = Date.now(); + + const started = Date.now(); + const result = await runChain([{ command: 'first step' }], session, uuid, 1500); + await new Promise((r) => setTimeout(r, 300)); + + assert.deepEqual(session.written, []); + assert.ok(Date.now() - started >= 1400, 'the wait must run to the step deadline, not stop early'); + assert.equal(result.ok, false); + assert.equal(result.error, 'not sent'); + assert.ok(result.reason && result.reason.length > 0); + assert.equal(result.steps_completed, 0); + }); +} + +test('a later step held by a busy descriptor to the deadline: not written, "chain timeout", the first step stays completed', async () => { + const uuid = 'sess-every-later-' + Date.now(); + const session = chainSession(uuid, { + log: recordingLog(), + onEnter(n, desc) { + desc.status = 'busy'; desc.statusUpdatedAt = Date.now(); + session.setBusy(true); + setTimeout(() => session.setBusy(false), 100); + }, + }); + + const result = await runChain([{ command: 'first step' }, { command: 'second step' }], session, uuid, 2500); + + assert.ok(!session.written.some((w) => w.data === 'second step')); + assert.equal(result.ok, false); + assert.equal(result.error, 'chain timeout'); + assert.match(result.reason, /busy/); + assert.equal(result.steps_completed, 1); +}); + +test('a step not confirmed with the recovery Enter withheld stops the chain: nothing more is typed', async () => { + const uuid = 'sess-every-stop-' + Date.now(); + const session = chainSession(uuid, { + log: recordingLog(), + onEnter(n, desc) { desc.status = 'busy'; }, + }); + + const result = await runChain([{ command: 'first step' }, { command: 'second step' }], session, uuid, 4000); + + assert.deepEqual(session.written.map((w) => w.data), ['first step', '\r']); + assert.equal(result.ok, false); + assert.equal(result.error, 'step not confirmed'); + assert.ok(result.reason && result.reason.length > 0); + assert.equal(result.steps_completed, 0); + assert.equal(result.steps[0].submit_confirmed, false); +}); + +function fakeClock(t) { + t.mock.timers.enable({ apis: ['Date', 'setTimeout'], now: 1_000_000 }); +} + +async function settleRun(t, promise, maxMs = 5000) { + let done = false; + let value; + promise.then((v) => { done = true; value = v; }); + for (let i = 0; i < maxMs && !done; i += 5) { + t.mock.timers.tick(5); + await new Promise((r) => setImmediate(r)); + } + assert.ok(done, 'still pending'); + return value; +} + +function stateCtx(state) { + return { getPtyForSession: () => ({}), getCliStatus: () => ({ ...state }) }; +} + +test('readiness settle: an idle followed by busy inside the settle window is not ready; ready only once idle has held', async (t) => { + fakeClock(t); + const state = { status: 'idle', statusUpdatedAt: 1_000_000 }; + setTimeout(() => { state.status = 'busy'; state.statusUpdatedAt = Date.now(); }, 150); + setTimeout(() => { state.status = 'idle'; state.statusUpdatedAt = Date.now(); }, 400); + const r = await settleRun(t, waitForCliIdleAfter('sid', stateCtx(state), -Infinity, 1_000_000 + 5000, 300)); + assert.equal(r.ready, true); + assert.ok(r.waited_ms >= 700, 'ready after ' + r.waited_ms + ' ms, expected the settle to restart at the second idle'); +}); + +test('readiness settle: a new statusUpdatedAt while idle restarts the settle window', async (t) => { + fakeClock(t); + const state = { status: 'idle', statusUpdatedAt: 1_000_000 }; + setTimeout(() => { state.statusUpdatedAt = Date.now(); }, 200); + const r = await settleRun(t, waitForCliIdleAfter('sid', stateCtx(state), -Infinity, 1_000_000 + 5000, 300)); + assert.equal(r.ready, true); + assert.ok(r.waited_ms >= 500, 'ready after ' + r.waited_ms + ' ms, expected the settle to restart at the new timestamp'); +}); + +test('readiness: a dialog seen anywhere in the final settle window is reported even when the last sample is busy', async (t) => { + fakeClock(t); + const state = { status: 'busy', statusUpdatedAt: 1_000_000 }; + setTimeout(() => { state.status = 'waiting'; state.statusUpdatedAt = Date.now(); }, 1800); + setTimeout(() => { state.status = 'busy'; state.statusUpdatedAt = Date.now(); }, 1900); + const r = await settleRun(t, waitForCliIdleAfter('sid', stateCtx(state), -Infinity, 1_000_000 + 2000, 300)); + assert.equal(r.ready, false); + assert.equal(r.timedOut, true); + assert.equal(r.lastStatus, 'busy'); + assert.equal(r.waitingSeen, true); +}); + +test('readiness: an unknown status is not idle', async (t) => { + fakeClock(t); + const state = { status: 'shell', statusUpdatedAt: 1_000_000 }; + const r = await settleRun(t, waitForCliIdleAfter('sid', stateCtx(state), -Infinity, 1_000_000 + 1000, 0)); + assert.equal(r.ready, false); + assert.equal(r.timedOut, true); +}); + +test('waitForBusyFall: an idle that flickers back to busy inside the settle window does not end the wait early', async (t) => { + fakeClock(t); + const state = { status: 'idle', statusUpdatedAt: 1_000_000 }; + setTimeout(() => { state.status = 'busy'; state.statusUpdatedAt = Date.now(); }, 20); + setTimeout(() => { state.status = 'idle'; state.statusUpdatedAt = Date.now(); }, 200); + const ctx = { getPtyForSession: () => ({}), isSessionBusy: () => true, getCliStatus: () => ({ ...state }) }; + const r = await settleRun(t, waitForBusyFall('sid', ctx, 1_000_000 + 5000, 1_000_000)); + assert.equal(r.timedOut, false); + assert.ok(r.waited_ms >= 240, 'ended after ' + r.waited_ms + ' ms, before the second idle had held'); +}); + +test('a descriptor that vanishes after it was read keeps the wait going to the deadline: nothing is written', async () => { + const uuid = 'sess-every-vanish-' + Date.now(); + const session = chainSession(uuid, { log: recordingLog(), onEnter: () => {} }); + session.desc.status = 'busy'; + session.desc.statusUpdatedAt = Date.now(); + setTimeout(() => { session.ctx.getCliStatus = () => undefined; }, 500); + + const started = Date.now(); + const result = await runChain([{ command: 'first step' }], session, uuid, 1800); + await new Promise((r) => setTimeout(r, 300)); + + assert.deepEqual(session.written, []); + assert.ok(Date.now() - started >= 1700, 'the wait must run to the deadline'); + assert.equal(result.ok, false); + assert.equal(result.error, 'not sent'); +}); + +test('a descriptor that vanishes and reappears idle: the wait resumes and the step is written', async () => { + const uuid = 'sess-every-reappear-' + Date.now(); + const session = chainSession(uuid, { log: recordingLog(), onEnter: (n, d) => quickTurn(session)(n, d) }); + session.desc.status = 'busy'; + session.desc.statusUpdatedAt = Date.now(); + const started = Date.now(); + const original = session.ctx.getCliStatus; + setTimeout(() => { session.ctx.getCliStatus = () => undefined; }, 200); + setTimeout(() => { + session.desc.status = 'idle'; session.desc.statusUpdatedAt = Date.now(); + session.ctx.getCliStatus = original; + }, 700); + + const result = await runChain([{ command: 'first step' }], session, uuid, 5000); + + assert.equal(result.ok, true); + assert.ok(session.written[0].at - started >= 650, 'written before the descriptor reappeared idle'); +}); + +test('readiness: a settle that completes after the deadline is a timeout, never ready', async (t) => { + fakeClock(t); + const state = { status: 'idle', statusUpdatedAt: 1_000_000 }; + const r = await settleRun(t, waitForCliIdleAfter('sid', stateCtx(state), -Infinity, 1_000_000 + 290, 300)); + assert.equal(r.ready, false); + assert.equal(r.timedOut, true); +}); + +test('readiness: a deadline already passed is a timeout even for an idle descriptor with no settle', async (t) => { + fakeClock(t); + const state = { status: 'idle', statusUpdatedAt: 1_000_000 }; + const r = await settleRun(t, waitForCliIdleAfter('sid', stateCtx(state), -Infinity, 1_000_000, 0)); + assert.equal(r.ready, false); + assert.equal(r.timedOut, true); +}); + +test('a step whose deadline has passed is not written, even with no descriptor to wait for', async () => { + const uuid = 'sess-every-expired-' + Date.now(); + const session = chainSession(uuid, { log: recordingLog(), withDescriptor: false, onEnter: () => {} }); + session.ctx.getComposerState = () => { + const t = Date.now(); + while (Date.now() - t < 5) { /* let the 1 ms step budget lapse */ } + return { pending: 0, lastInputAt: 0 }; + }; + const tmp = mkTmp(); + process.env.SWITCHBOARD_TRIGGERS_DIR = tmp; + const watcher = start(session.ctx); + try { + fs.writeFileSync(path.join(tmp, uuid + '.json'), + JSON.stringify({ sessionId: uuid, wait: 'none', chain: [{ command: 'first step', timeout_ms: 1 }], timeout_ms: 20000 }), 'utf8'); + const resultPath = path.join(tmp, 'processed', uuid + '.result.json'); + const deadline = Date.now() + 10000; + while (!fs.existsSync(resultPath)) { + if (Date.now() > deadline) throw new Error('no result file'); + await new Promise((r) => setTimeout(r, 20)); + } + await new Promise((r) => setTimeout(r, 20)); + const result = JSON.parse(fs.readFileSync(resultPath, 'utf8')); + assert.deepEqual(session.written, []); + assert.equal(result.ok, false); + assert.equal(result.error, 'not sent'); + } finally { + watcher.close(); + delete process.env.SWITCHBOARD_TRIGGERS_DIR; + fs.rmSync(tmp, { recursive: true, force: true }); + } +}); + +test('post-compact readiness is anchored on the compact\'s own Enter, not on when the step began', async () => { + process.env.SWITCHBOARD_SUBMIT_ENTER_DELAY_MS = '250'; + try { + const uuid = 'sess-every-anchor-' + Date.now(); + const session = chainSession(uuid, { log: recordingLog(), onEnter: () => {} }); + const realWrite = session.ctx.getPtyForSession(uuid).ptyProcess.write; + session.ctx.getPtyForSession(uuid).ptyProcess.write = function (data) { + realWrite.call(this, data); + if (data === '/compact') { + setTimeout(() => { session.desc.status = 'idle'; session.desc.statusUpdatedAt = Date.now(); }, 60); + } + }; + + const result = await runChain([{ command: '/compact' }, { command: 'second step' }], session, uuid, 3500); + + assert.ok(!session.written.some((w) => w.data === 'second step'), 'an idle older than the compact Enter must not release the next step'); + assert.equal(result.ok, false); + assert.equal(result.error, 'chain timeout'); + } finally { + process.env.SWITCHBOARD_SUBMIT_ENTER_DELAY_MS = '1'; + } +}); + +test('the only readable sample is the first one, then the descriptor is unreadable: the wait owns the start decision, nothing is written', async () => { + const uuid = 'sess-every-first-read-' + Date.now(); + const session = chainSession(uuid, { log: recordingLog(), onEnter: () => {} }); + let reads = 0; + session.ctx.getCliStatus = () => { + reads += 1; + return reads === 1 ? { status: 'busy', statusUpdatedAt: Date.now() } : undefined; + }; + + const result = await runChain([{ command: 'first step' }], session, uuid, 1500); + await new Promise((r) => setTimeout(r, 300)); + + assert.deepEqual(session.written, []); + assert.equal(result.ok, false); + assert.equal(result.error, 'not sent'); +}); diff --git a/trigger-watcher.js b/trigger-watcher.js index 8e06be54..0e021d99 100644 --- a/trigger-watcher.js +++ b/trigger-watcher.js @@ -88,6 +88,11 @@ const SUBMITTED_RANK = { const ERROR_NOT_SENT = 'not sent'; const ERROR_CHAIN_TIMEOUT = 'chain timeout'; +const ERROR_UNCONFIRMED = 'step not confirmed'; +const REASON_DIALOG_OPEN = 'the CLI reports a dialog open (waiting); nothing was written into it'; +const REASON_DEADLINE_BEFORE_WRITE = 'the step deadline passed before it could be written; nothing was written'; +const REASON_CLI_BUSY = 'the CLI still reported a turn running (busy) at the deadline; nothing was written'; +const REASON_CLI_NOT_IDLE = 'the CLI never reported idle before the deadline; nothing was written'; const ACCEPTED_WAITS = ['idle', 'none']; @@ -341,13 +346,6 @@ function pollForBusyObserved(sessionId, ctx, windowMs, deadlineMs, probe) { }); } -// see .ai/contexts/trigger-watcher.md, "Readiness and edge proof from the CLI descriptor" -const DEFAULT_CLI_READY_WAIT_MS = 60_000; // ms -function getCliReadyWaitMs() { - const v = envNumber('SWITCHBOARD_CLI_READY_WAIT_MS'); - return v !== undefined ? v : DEFAULT_CLI_READY_WAIT_MS; -} - function readCliStatusRaw(ctx, sessionId) { if (typeof ctx.getCliStatus !== 'function') return null; try { @@ -379,31 +377,47 @@ function cliForbidsRecoveryEnter(ctx, sessionId) { return !!s && (s.status === 'waiting' || s.status === 'busy'); } -/** - * Wait until the CLI's own descriptor reports "idle" with a statusUpdatedAt - * later than `afterMs`, bounded by `deadlineMs`. - * - * Returns { ready, available, timedOut, sessionExited, waited_ms }. `available: - * false` means no descriptor could be read (at the start or later): the caller - * keeps its pre-descriptor behaviour. - */ -function waitForCliIdleAfter(sessionId, ctx, afterMs, deadlineMs) { +// see .ai/contexts/trigger-watcher.md, "Readiness before every step" (return shape, descriptor loss, deadline) +function waitForCliIdleAfter(sessionId, ctx, afterMs, deadlineMs, settleMs = 0) { const start = Date.now(); + let idleSince = null; + let idleStamp = null; + let lastStatus = null; + let lastWaitingAt = null; + let everRead = false; return pollLoop((resolve, scheduleNext) => { const now = Date.now(); const waited_ms = now - start; + const waitingSeen = lastWaitingAt !== null && now - lastWaitingAt <= settleMs; if (!ctx.getPtyForSession(sessionId)) { - return resolve({ ready: false, available: true, timedOut: false, sessionExited: true, waited_ms }); + return resolve({ ready: false, available: true, timedOut: false, sessionExited: true, waited_ms, lastStatus, waitingSeen }); } const s = readCliStatus(ctx, sessionId); + if (!s && !everRead) { + return resolve({ ready: false, available: false, timedOut: false, sessionExited: false, waited_ms, lastStatus, waitingSeen }); + } + let idleHeld = false; if (!s) { - return resolve({ ready: false, available: false, timedOut: false, sessionExited: false, waited_ms }); + idleSince = null; + } else { + everRead = true; + lastStatus = s.status; + if (s.status === 'waiting') lastWaitingAt = now; + if (s.status === 'idle' && s.statusUpdatedAt > afterMs) { + if (idleSince === null || idleStamp !== s.statusUpdatedAt) { + idleSince = now; + idleStamp = s.statusUpdatedAt; + } + idleHeld = now - idleSince >= settleMs; + } else { + idleSince = null; + } } - if (s.status === 'idle' && Number.isInteger(s.statusUpdatedAt) && s.statusUpdatedAt > afterMs) { - return resolve({ ready: true, available: true, timedOut: false, sessionExited: false, waited_ms }); + if (idleHeld && now < deadlineMs) { + return resolve({ ready: true, available: true, timedOut: false, sessionExited: false, waited_ms, lastStatus, waitingSeen }); } if (now >= deadlineMs) { - return resolve({ ready: false, available: true, timedOut: true, sessionExited: false, waited_ms }); + return resolve({ ready: false, available: true, timedOut: true, sessionExited: false, waited_ms, lastStatus, waitingSeen: lastWaitingAt !== null && now - lastWaitingAt <= settleMs }); } scheduleNext(); }); @@ -466,6 +480,7 @@ async function submitWithVerify(handle, sessionId, command, ctx, deadlineMs) { const first = await pollForBusyObserved(sessionId, ctx, windowMs, effectiveDeadline, probe); if (first.sawBusy || first.sessionExited || first.timedOut) { return { + enterAt, submit_retries: 0, sawBusy: first.sawBusy, confirmed: edgeMode ? first.sawBusy : null, @@ -483,6 +498,7 @@ async function submitWithVerify(handle, sessionId, command, ctx, deadlineMs) { const recoveryDeadline = Math.min(effectiveDeadline, Date.now() + windowMs); if (cliForbidsRecoveryEnter(ctx, sessionId)) { return { + enterAt, submit_retries: 0, sawBusy: false, confirmed: edgeMode ? false : null, @@ -497,6 +513,7 @@ async function submitWithVerify(handle, sessionId, command, ctx, deadlineMs) { const polite = await waitForComposerFree(sessionId, ctx, recoveryDeadline); if (!polite.free) { return { + enterAt, submit_retries: 0, sawBusy: false, confirmed: edgeMode ? false : null, @@ -514,6 +531,7 @@ async function submitWithVerify(handle, sessionId, command, ctx, deadlineMs) { } catch (err) { // Surface as a sessionExited-like failure; caller maps to an error result. return { + enterAt, submit_retries: 1, sawBusy: false, confirmed: edgeMode ? false : null, @@ -527,6 +545,7 @@ async function submitWithVerify(handle, sessionId, command, ctx, deadlineMs) { const second = await pollForBusyObserved(sessionId, ctx, windowMs, effectiveDeadline, probe); return { + enterAt, submit_retries: 1, sawBusy: second.sawBusy, confirmed: edgeMode ? second.sawBusy : null, @@ -550,9 +569,15 @@ async function submitWithVerify(handle, sessionId, command, ctx, deadlineMs) { * * see .ai/contexts/trigger-watcher.md, "waitForBusyFall waits for the rise too" * + * With `enterAtMs` and a usable descriptor, the descriptor is the authority: idle + * with a statusUpdatedAt at or after the Enter, held for the settle window, + * ends the wait whatever `isSessionBusy` says. Without one the level probe decides. + * + * see .ai/contexts/trigger-watcher.md, "Readiness before every step" + * * Returns { timedOut, sessionExited, waited_ms }. */ -function waitForBusyFall(sessionId, ctx, deadlineMs) { +function waitForBusyFall(sessionId, ctx, deadlineMs, enterAtMs) { const start = Date.now(); const settleMs = getBusyFallSettleMs(); const riseDeadline = start + getBusyRiseWaitMs(); @@ -561,6 +586,8 @@ function waitForBusyFall(sessionId, ctx, deadlineMs) { // Set the instant busy first reads false (after having risen); reset to // null on every re-assertion. let idleSince = null; + let descIdleSince = null; + let descIdleStamp = null; return pollLoop((resolve, scheduleNext) => { const now = Date.now(); @@ -570,6 +597,18 @@ function waitForBusyFall(sessionId, ctx, deadlineMs) { if (!ctx.getPtyForSession(sessionId)) { return resolve({ timedOut: false, sessionExited: true, waited_ms: now - start }); } + const desc = Number.isFinite(enterAtMs) ? readCliStatus(ctx, sessionId) : null; + if (desc && desc.status === 'idle' && desc.statusUpdatedAt >= enterAtMs) { + if (descIdleSince === null || descIdleStamp !== desc.statusUpdatedAt) { + descIdleSince = now; + descIdleStamp = desc.statusUpdatedAt; + } + if (now - descIdleSince >= settleMs) { + return resolve({ timedOut: false, sessionExited: false, waited_ms: now - start }); + } + } else { + descIdleSince = null; + } if (ctx.isSessionBusy(sessionId)) { hasRisen = true; idleSince = null; @@ -1192,7 +1231,6 @@ async function processTriggerFile(name, ctx, triggersDir, processedDir, onEntryR // Inject the step command const stepSentAt = new Date().toISOString(); if (i === 0) step0SentAt = stepSentAt; - if (isCompactCommand(step.command)) compactSentAtMs = Date.parse(stepSentAt); // Per-step timeout_ms (if set) bounds THIS whole step (verify + retry + the // busy-fall wait for non-final steps), capped by the remaining global @@ -1241,12 +1279,8 @@ async function processTriggerFile(name, ctx, triggersDir, processedDir, onEntryR } let readyWaitedMs = 0; - if (readyAfterMs !== null && !readCliStatus(ctx, sessionId)) { - ctx.log.info(`[trigger-watcher] No usable CLI descriptor for ${sessionId}, readiness wait skipped before chain step ${i}`); - } - if (readyAfterMs !== null && readCliStatus(ctx, sessionId)) { - const readyDeadline = Math.min(stepDeadline, Date.now() + getCliReadyWaitMs()); - const ready = await waitForCliIdleAfter(sessionId, ctx, readyAfterMs, readyDeadline); + { + const ready = await waitForCliIdleAfter(sessionId, ctx, readyAfterMs === null ? -Infinity : readyAfterMs, stepDeadline, getBusyFallSettleMs()); readyWaitedMs = ready.waited_ms; totalWaitedMs += readyWaitedMs; if (ready.sessionExited) { @@ -1255,13 +1289,45 @@ async function processTriggerFile(name, ctx, triggersDir, processedDir, onEntryR return; } if (!ready.available) { - ctx.log.info(`[trigger-watcher] CLI descriptor vanished for ${sessionId}, readiness wait ended early before chain step ${i}`); + ctx.log.info(`[trigger-watcher] No usable CLI descriptor for ${sessionId} at the start of the readiness wait before chain step ${i}`); } if (ready.timedOut) { - ctx.log.warn(`[trigger-watcher] CLI not idle after /compact within ${readyWaitedMs} ms, writing chain step ${i} anyway:`, sessionId); + const dialog = ready.waitingSeen || ready.lastStatus === 'waiting'; + const reason = dialog ? REASON_DIALOG_OPEN : (ready.lastStatus === 'busy' ? REASON_CLI_BUSY : REASON_CLI_NOT_IDLE); + ctx.log.warn(`[trigger-watcher] CLI not ready (${ready.lastStatus}) after ${readyWaitedMs} ms, chain step ${i} not written:`, sessionId); + steps.push({ + idx: i, command: step.command, sent_at: stepSentAt, waited_ms: polite.waited_ms + readyWaitedMs, + submit_retries: 0, submitted: SUBMITTED_NO, + }); + await writeResult({ + ok: false, + submitted: weakestSubmitted(chainSubmitted, SUBMITTED_NO), + error: (i === 0) ? ERROR_NOT_SENT : ERROR_CHAIN_TIMEOUT, + reason, + partial: i > 0, steps_completed: i, sessionId, sent_at: step0SentAt, steps, + total_waited_ms: totalWaitedMs, + }); + return; } } + if (Date.now() >= stepDeadline) { + ctx.log.warn(`[trigger-watcher] Step deadline passed before chain step ${i} could be written:`, sessionId); + steps.push({ + idx: i, command: step.command, sent_at: stepSentAt, waited_ms: polite.waited_ms + readyWaitedMs, + submit_retries: 0, submitted: SUBMITTED_NO, + }); + await writeResult({ + ok: false, + submitted: weakestSubmitted(chainSubmitted, SUBMITTED_NO), + error: (i === 0) ? ERROR_NOT_SENT : ERROR_CHAIN_TIMEOUT, + reason: REASON_DEADLINE_BEFORE_WRITE, + partial: i > 0, steps_completed: i, sessionId, sent_at: step0SentAt, steps, + total_waited_ms: totalWaitedMs, + }); + return; + } + // Submit the step, then look for activity on the session. // The verify poll IS this step's Phase 1 — for non-final steps we proceed // straight to the busy-FALL wait, never re-observing busy. @@ -1285,6 +1351,9 @@ async function processTriggerFile(name, ctx, triggersDir, processedDir, onEntryR await writeResult({ ok: false, error: 'pty write failed: ' + verify.writeError.message, partial: true, steps_completed: i, sessionId, sent_at: step0SentAt, steps, total_waited_ms: totalWaitedMs }); return; } + if (isCompactCommand(step.command)) { + compactSentAtMs = Number.isFinite(verify.enterAt) ? verify.enterAt : Date.parse(stepSentAt); + } submitRetries = verify.submit_retries; stepWaitedMs += verify.waited_ms; totalWaitedMs += verify.waited_ms; @@ -1322,6 +1391,19 @@ async function processTriggerFile(name, ctx, triggersDir, processedDir, onEntryR return; } + if (stepConfirmed === false && verify.recoverySkipped) { + steps.push({ idx: i, command: step.command, sent_at: stepSentAt, waited_ms: stepWaitedMs, submit_retries: submitRetries, submitted: stepSubmitted, submit_confirmed: false }); + await writeResult({ + ok: false, + submitted: chainSubmitted, + error: ERROR_UNCONFIRMED, + reason: `chain step ${i} was typed but its submission was not confirmed and the recovery Enter was withheld (${verify.recoveryReason}); nothing more was typed`, + partial: true, steps_completed: i, sessionId, sent_at: step0SentAt, steps, + total_waited_ms: totalWaitedMs, + }); + return; + } + // For non-final steps, wait for the turn to FINISH (busy falling edge). // submitWithVerify already consumed the observation. If busy was never // observed (instant-reply / unconfirmed submit), busy is already false, @@ -1331,7 +1413,7 @@ async function processTriggerFile(name, ctx, triggersDir, processedDir, onEntryR // could not confirm a turn. if (i < chain.length - 1) { // Same per-step deadline as the verify above — bounds the busy-fall wait. - const result = await waitForBusyFall(sessionId, ctx, stepDeadline); + const result = await waitForBusyFall(sessionId, ctx, stepDeadline, verify.enterAt); stepWaitedMs += result.waited_ms; totalWaitedMs += result.waited_ms; @@ -1521,4 +1603,4 @@ function start(ctx) { }; } -module.exports = { start, weakestSubmitted, SUBMITTED_RANK, normalizeCwd, submitWithVerify, waitForCliIdleAfter, isCompactCommand }; +module.exports = { start, weakestSubmitted, SUBMITTED_RANK, normalizeCwd, submitWithVerify, waitForCliIdleAfter, waitForBusyFall, isCompactCommand };