From ff2c98c5218207df64fc825ec56c2080703a4ae6 Mon Sep 17 00:00:00 2001 From: Jean-Baptiste Date: Fri, 2 Oct 2026 18:48:25 +0200 Subject: [PATCH] (triggers): report a dialog when a wait ends on a blocked session A trigger that gave up waiting said only "timeout waiting for idle" even when the CLI descriptor read waiting, a dialog nobody answered. The single-trigger wait, a chain's first wait and a chain step's busy-fall now use the same dialog probe as the readiness wait and put the dialog reason in the result. Nothing written into the PTY changes. Closes #379 --- .ai/contexts/trigger-watcher.md | 23 ++++ CHANGELOG.md | 3 + docs/automation.md | 11 ++ test/trigger-blocked-session.test.js | 159 +++++++++++++++++++++++++++ trigger-watcher.js | 46 +++++--- 5 files changed, 229 insertions(+), 13 deletions(-) create mode 100644 test/trigger-blocked-session.test.js diff --git a/.ai/contexts/trigger-watcher.md b/.ai/contexts/trigger-watcher.md index 388e7471..0cac351f 100644 --- a/.ai/contexts/trigger-watcher.md +++ b/.ai/contexts/trigger-watcher.md @@ -957,6 +957,29 @@ state was the cause. Tests: `test/trigger-every-step-readiness.test.js` (the real watcher with a fake descriptor, plus the wait helpers under mocked timers). +### A blocked session tells its driver (issue #379) + +Every wait that can end a trigger on its deadline reports a dialog, not only +the chain's readiness wait. `createDialogProbe(ctx, sessionId, windowMs)` is +the one mechanism: `sample(now)` reads the descriptor through `readCliStatus` +and remembers when `waiting` last read, `seen(now)` is true when that was +within `windowMs` (the busy-fall settle window, as in `waitForCliIdleAfter`). + +- `waitForIdle` (single trigger wait, chain initial wait) and `waitForBusyFall` + (chain, after a step was written) return `waitingSeen` on a timeout. + `waitForIdle` reads the descriptor only while the session still reads busy, + so a session that is already idle costs no descriptor read (a test counts + the reads of the readiness wait). +- Before a write, `reason` is `REASON_DIALOG_OPEN` ("nothing was written into + it"). After a write, `REASON_DIALOG_OPEN_AFTER_WRITE` says the step had been + written; `error` stays `chain timeout`. Without a dialog the reasons are + unchanged, and none is added to the busy-fall timeout. +- What is written into the PTY, and when, is unchanged. The submit-verify + timeout (`submitWithVerify`) is not covered: it still reports a bare + `chain timeout`. + +Tests: `test/trigger-blocked-session.test.js`. + ### 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 a6877487..adf866c8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,9 @@ What changes for you in each release of Switchboard. How to write an entry: [doc ## Unreleased +### Changed +- A trigger that gave up waiting for a session now says, in its result file's `reason`, when the session was blocked on a dialog such as a permission prompt or a question: for a single trigger, a chain's first wait, and a chain step whose turn never finished. Without a dialog the result is as before. (#379) + ## v0.0.87 — 2026-10-02 ### New diff --git a/docs/automation.md b/docs/automation.md index ab4ea40c..15a48c79 100644 --- a/docs/automation.md +++ b/docs/automation.md @@ -448,6 +448,17 @@ The two reserved values mean opposite things: 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`). +- When the wait ends because the session never got there and the CLI's + descriptor read `waiting` (a dialog is open: a permission prompt or a + question) at any sample in the last few hundred milliseconds of it, `reason` + says so: *the CLI reports a dialog open (waiting); nothing was written into + it* for a `command` or a chain's initial wait, in place of the plain timeout + reason. A chain whose turn was still awaited after a step was written ends + `chain timeout` with `reason` *the CLI reports a dialog open (waiting) while + the turn was awaited; the step had been written*; without a dialog, that + result carries no `reason`. Without a readable descriptor, results are as + before. The result file is the only place this is reported: answer the dialog + in the session. - 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-blocked-session.test.js b/test/trigger-blocked-session.test.js new file mode 100644 index 00000000..f63efc9b --- /dev/null +++ b/test/trigger-blocked-session.test.js @@ -0,0 +1,159 @@ +// test/trigger-blocked-session.test.js +// +// A trigger result that ends because the session waited says so when the CLI +// descriptor read `waiting` (a dialog) during the end of that wait. See +// .ai/contexts/trigger-watcher.md, "A blocked session tells its driver". +'use strict'; + +process.env.SWITCHBOARD_SUBMIT_ENTER_DELAY_MS = '1'; +process.env.SWITCHBOARD_SUBMIT_VERIFY_MS = '300'; +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 } = require('../trigger-watcher'); + +const silent = { info() {}, warn() {}, error() {}, debug() {} }; + +function session(sessionId, { withDescriptor = true, onEnter = () => {} } = {}) { + const written = []; + const desc = { status: 'idle', statusUpdatedAt: Date.now() - 10_000 }; + const state = { busy: false }; + const ptyProcess = { + pid: process.pid, + write(data) { + written.push(data); + if (data === '\r') onEnter(desc, state); + }, + }; + const ctx = { + log: silent, + getPtyForSession: (id) => (id === sessionId ? { ptyProcess } : null), + isSessionBusy: () => state.busy, + isPtyAlive: () => true, + getComposerState: () => ({ pending: 0, lastInputAt: 0 }), + }; + if (withDescriptor) ctx.getCliStatus = (id) => (id === sessionId ? { ...desc } : undefined); + return { ctx, written, desc, state }; +} + +function set(desc, status) { + desc.status = status; + desc.statusUpdatedAt = Date.now(); +} + +async function run(payload, s) { + const tmp = fs.realpathSync.native(fs.mkdtempSync(path.join(os.tmpdir(), 'sw-trigger-blocked-'))); + process.env.SWITCHBOARD_TRIGGERS_DIR = tmp; + const watcher = start(s.ctx); + try { + fs.writeFileSync(path.join(tmp, payload.sessionId + '.json'), JSON.stringify(payload), 'utf8'); + const resultPath = path.join(tmp, 'processed', payload.sessionId + '.result.json'); + const limit = Date.now() + 15000; + while (!fs.existsSync(resultPath)) { + if (Date.now() > limit) 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; + fs.rmSync(tmp, { recursive: true, force: true }); + } +} + +const single = (id) => ({ sessionId: id, command: 'hello', wait: 'idle', timeout_ms: 600 }); +const chain = (id) => ({ sessionId: id, wait: 'idle', chain: [{ command: 'one' }, { command: 'two' }], timeout_ms: 1500 }); + +test('single trigger: still busy at the deadline with a dialog open -> the dialog reason', async () => { + const id = 'sess-blocked-single-' + Date.now(); + const s = session(id); + s.state.busy = true; + set(s.desc, 'waiting'); + const r = await run(single(id), s); + assert.deepEqual(s.written, []); + assert.equal(r.error, 'not sent'); + assert.equal(r.submitted, 'no'); + assert.match(r.reason, /dialog open \(waiting\); nothing was written into it/); +}); + +test('single trigger: still busy at the deadline, descriptor busy -> the plain timeout reason', async () => { + const id = 'sess-blocked-single-busy-' + Date.now(); + const s = session(id); + s.state.busy = true; + set(s.desc, 'busy'); + const r = await run(single(id), s); + assert.equal(r.reason, 'timeout waiting for idle; nothing was written'); +}); + +test('single trigger: no descriptor -> the plain timeout reason', async () => { + const id = 'sess-blocked-single-none-' + Date.now(); + const s = session(id, { withDescriptor: false }); + s.state.busy = true; + const r = await run(single(id), s); + assert.equal(r.reason, 'timeout waiting for idle; nothing was written'); +}); + +test('single trigger: a dialog that closed long before the deadline is not reported', async () => { + const id = 'sess-blocked-single-old-' + Date.now(); + const s = session(id); + s.state.busy = true; + set(s.desc, 'waiting'); + setTimeout(() => set(s.desc, 'busy'), 100); + const r = await run(single(id), s); + assert.equal(r.reason, 'timeout waiting for idle; nothing was written'); +}); + +test('chain initial wait: still busy at the deadline with a dialog open -> the dialog reason', async () => { + const id = 'sess-blocked-chain0-' + Date.now(); + const s = session(id); + s.state.busy = true; + set(s.desc, 'waiting'); + const r = await run({ ...chain(id), timeout_ms: 600 }, s); + assert.deepEqual(s.written, []); + assert.equal(r.error, 'not sent'); + assert.equal(r.partial, false); + assert.match(r.reason, /dialog open \(waiting\); nothing was written into it/); +}); + +test('chain initial wait: descriptor busy -> the plain timeout reason', async () => { + const id = 'sess-blocked-chain0-busy-' + Date.now(); + const s = session(id); + s.state.busy = true; + set(s.desc, 'busy'); + const r = await run({ ...chain(id), timeout_ms: 600 }, s); + assert.equal(r.reason, 'timed out waiting for the session to go idle; nothing was written'); +}); + +test('chain busy-fall: a dialog opens while the turn is awaited -> chain timeout with the dialog reason', async () => { + const id = 'sess-blocked-fall-' + Date.now(); + const s = session(id, { onEnter: (desc, state) => { state.busy = true; set(desc, 'waiting'); } }); + const r = await run(chain(id), s); + assert.deepEqual(s.written.filter((w) => w === 'two'), []); + assert.equal(r.error, 'chain timeout'); + assert.equal(r.partial, true); + assert.equal(r.steps_completed, 0); + assert.match(r.reason, /dialog open \(waiting\) while the turn was awaited; the step had been written/); +}); + +test('chain busy-fall: the turn runs past the deadline, descriptor busy -> chain timeout without a reason', async () => { + const id = 'sess-blocked-fall-busy-' + Date.now(); + const s = session(id, { onEnter: (desc, state) => { state.busy = true; set(desc, 'busy'); } }); + const r = await run(chain(id), s); + assert.equal(r.error, 'chain timeout'); + assert.equal('reason' in r, false); +}); + +test('chain busy-fall: no descriptor -> chain timeout without a reason', async () => { + const id = 'sess-blocked-fall-none-' + Date.now(); + const s = session(id, { withDescriptor: false, onEnter: (desc, state) => { state.busy = true; } }); + const r = await run(chain(id), s); + assert.equal(r.error, 'chain timeout'); + assert.equal('reason' in r, false); +}); diff --git a/trigger-watcher.js b/trigger-watcher.js index 0e021d99..6eae0277 100644 --- a/trigger-watcher.js +++ b/trigger-watcher.js @@ -90,6 +90,7 @@ 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_DIALOG_OPEN_AFTER_WRITE = 'the CLI reports a dialog open (waiting) while the turn was awaited; the step had been written'; 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'; @@ -361,6 +362,21 @@ function readCliStatus(ctx, sessionId) { return s && Number.isInteger(s.statusUpdatedAt) ? s : null; } +// see .ai/contexts/trigger-watcher.md, "A blocked session tells its driver" +function createDialogProbe(ctx, sessionId, windowMs) { + let lastWaitingAt = null; + return { + sample(now) { + const s = readCliStatus(ctx, sessionId); + if (s && s.status === 'waiting') lastWaitingAt = now; + return s; + }, + seen(now) { + return lastWaitingAt !== null && now - lastWaitingAt <= windowMs; + }, + }; +} + const CLI_REACTION_STATUSES = ['busy', 'idle', 'waiting']; function isCompactCommand(command) { @@ -383,16 +399,16 @@ function waitForCliIdleAfter(sessionId, ctx, afterMs, deadlineMs, settleMs = 0) let idleSince = null; let idleStamp = null; let lastStatus = null; - let lastWaitingAt = null; + const dialog = createDialogProbe(ctx, sessionId, settleMs); let everRead = false; return pollLoop((resolve, scheduleNext) => { const now = Date.now(); const waited_ms = now - start; - const waitingSeen = lastWaitingAt !== null && now - lastWaitingAt <= settleMs; + const waitingSeen = dialog.seen(now); if (!ctx.getPtyForSession(sessionId)) { return resolve({ ready: false, available: true, timedOut: false, sessionExited: true, waited_ms, lastStatus, waitingSeen }); } - const s = readCliStatus(ctx, sessionId); + const s = dialog.sample(now); if (!s && !everRead) { return resolve({ ready: false, available: false, timedOut: false, sessionExited: false, waited_ms, lastStatus, waitingSeen }); } @@ -402,7 +418,6 @@ function waitForCliIdleAfter(sessionId, ctx, afterMs, deadlineMs, settleMs = 0) } 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; @@ -417,7 +432,7 @@ function waitForCliIdleAfter(sessionId, ctx, afterMs, deadlineMs, settleMs = 0) 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, lastStatus, waitingSeen: lastWaitingAt !== null && now - lastWaitingAt <= settleMs }); + return resolve({ ready: false, available: true, timedOut: true, sessionExited: false, waited_ms, lastStatus, waitingSeen: dialog.seen(now) }); } scheduleNext(); }); @@ -575,7 +590,7 @@ async function submitWithVerify(handle, sessionId, command, ctx, deadlineMs) { * * see .ai/contexts/trigger-watcher.md, "Readiness before every step" * - * Returns { timedOut, sessionExited, waited_ms }. + * Returns { timedOut, sessionExited, waited_ms, waitingSeen } (waitingSeen only set on a timeout). */ function waitForBusyFall(sessionId, ctx, deadlineMs, enterAtMs) { const start = Date.now(); @@ -588,11 +603,13 @@ function waitForBusyFall(sessionId, ctx, deadlineMs, enterAtMs) { let idleSince = null; let descIdleSince = null; let descIdleStamp = null; + const dialog = createDialogProbe(ctx, sessionId, settleMs); return pollLoop((resolve, scheduleNext) => { const now = Date.now(); + dialog.sample(now); if (now >= deadlineMs) { - return resolve({ timedOut: true, sessionExited: false, waited_ms: now - start }); + return resolve({ timedOut: true, sessionExited: false, waited_ms: now - start, waitingSeen: dialog.seen(now) }); } if (!ctx.getPtyForSession(sessionId)) { return resolve({ timedOut: false, sessionExited: true, waited_ms: now - start }); @@ -675,14 +692,16 @@ function getTriggerMaxAgeMs() { * @param {object} ctx * @param {number} [timeoutMs] explicit timeout in ms; falls back to * getIdleTimeout() (env var → default) when absent. - * Returns { timedOut: boolean, sessionExited: boolean, waited_ms: number }. + * Returns { timedOut: boolean, sessionExited: boolean, waited_ms: number, waitingSeen?: boolean }. */ function waitForIdle(sessionId, ctx, timeoutMs) { const timeout = (timeoutMs !== undefined) ? timeoutMs : getIdleTimeout(); const start = Date.now(); + const dialog = createDialogProbe(ctx, sessionId, getBusyFallSettleMs()); return pollLoop((resolve, scheduleNext) => { - const waited_ms = Date.now() - start; + const now = Date.now(); + const waited_ms = now - start; // W5: detect PTY closure during wait if (!ctx.getPtyForSession(sessionId)) { @@ -692,8 +711,9 @@ function waitForIdle(sessionId, ctx, timeoutMs) { if (!ctx.isSessionBusy(sessionId)) { return resolve({ timedOut: false, sessionExited: false, waited_ms }); } + dialog.sample(now); if (waited_ms >= timeout) { - return resolve({ timedOut: true, sessionExited: false, waited_ms }); + return resolve({ timedOut: true, sessionExited: false, waited_ms, waitingSeen: dialog.seen(now) }); } scheduleNext(); }); @@ -1070,7 +1090,7 @@ async function processTriggerFile(name, ctx, triggersDir, processedDir, onEntryR ok: false, submitted: SUBMITTED_NO, error: ERROR_NOT_SENT, - reason: 'timeout waiting for idle; nothing was written', + reason: result.waitingSeen ? REASON_DIALOG_OPEN : 'timeout waiting for idle; nothing was written', sessionId, waited_ms, }); return; @@ -1196,7 +1216,7 @@ async function processTriggerFile(name, ctx, triggersDir, processedDir, onEntryR ok: false, submitted: SUBMITTED_NO, error: ERROR_NOT_SENT, - reason: 'timed out waiting for the session to go idle; nothing was written', + reason: result.waitingSeen ? REASON_DIALOG_OPEN : 'timed out waiting for the session to go idle; nothing was written', partial: false, steps_completed: 0, sessionId, sent_at: step0SentAt, steps, total_waited_ms: totalWaitedMs, }); @@ -1427,7 +1447,7 @@ async function processTriggerFile(name, ctx, triggersDir, processedDir, onEntryR if (result.timedOut) { ctx.log.warn(`[trigger-watcher] Chain timeout at step ${i}:`, sessionId); steps.push({ idx: i, command: step.command, sent_at: stepSentAt, waited_ms: stepWaitedMs, submit_retries: submitRetries, submitted: stepSubmitted, ...(stepConfirmed === null ? {} : { submit_confirmed: stepConfirmed }) }); - await writeResult({ ok: false, submitted: chainSubmitted, error: 'chain timeout', partial: true, steps_completed: i, sessionId, sent_at: step0SentAt, steps, total_waited_ms: totalWaitedMs }); + await writeResult({ ok: false, submitted: chainSubmitted, error: 'chain timeout', ...(result.waitingSeen ? { reason: REASON_DIALOG_OPEN_AFTER_WRITE } : {}), partial: true, steps_completed: i, sessionId, sent_at: step0SentAt, steps, total_waited_ms: totalWaitedMs }); return; } }