diff --git a/test/trigger-watcher.test.js b/test/trigger-watcher.test.js index 9becbe67..c8916732 100644 --- a/test/trigger-watcher.test.js +++ b/test/trigger-watcher.test.js @@ -8,6 +8,12 @@ // turn-completion timing in makeChainCtx is not perturbed by a 50ms wait. process.env.SWITCHBOARD_SUBMIT_ENTER_DELAY_MS = '1'; +// Submission-verify window: must exceed makeChainCtx's simulated busy-rise +// (50ms after the '\r' write) plus one IDLE_POLL_INTERVAL (100ms) so the poll +// reliably catches the rising edge, yet stay short enough to keep the suite +// fast and deterministic when no rise ever arrives (retry path). +process.env.SWITCHBOARD_SUBMIT_VERIFY_MS = '400'; + const test = require('node:test'); const assert = require('node:assert/strict'); const fs = require('fs'); @@ -131,9 +137,11 @@ test('happy path: trigger → pty.write called, result ok:true, trigger deleted' assert.equal(result.command, '/compact'); assert.ok(result.sent_at, 'result.sent_at should be set'); assert.equal(typeof result.waited_ms, 'number', 'waited_ms should be a number'); + // busy never rises in this ctx → submit-verify retries the Enter once. + assert.equal(result.submit_retries, 1, 'submit_retries should be 1 (no busy-rise observed)'); - // pty.write called with command + \r - assert.deepEqual(ctx._written, ['/compact', '\r'], 'pty.write: command text then discrete Enter'); + // pty.write: command text, discrete Enter, then the verify-retry Enter. + assert.deepEqual(ctx._written, ['/compact', '\r', '\r'], 'pty.write: command text, Enter, then retry Enter'); // Trigger file deleted assert.equal(fs.existsSync(triggerPath), false, 'trigger file should be deleted'); @@ -276,7 +284,8 @@ test('wait:idle while busy → flips to idle after 150ms → write happens, wait result.waited_ms >= 100, `waited_ms (${result.waited_ms}) should be >= 100ms`, ); - assert.deepEqual(ctx._written, ['/compact', '\r'], 'PTY write should happen after idle'); + // busy is false by the time we submit → no rise → verify retries the Enter. + assert.deepEqual(ctx._written, ['/compact', '\r', '\r'], 'PTY write should happen after idle (with verify-retry Enter)'); watcher.close(); } finally { @@ -525,8 +534,10 @@ test('W4 concurrency cap: 12 simultaneous triggers all get processed', async () assert.equal(result.ok, true, `trigger ${uuid} should be ok:true`); } - // 12 PTY writes should have happened - assert.equal(ctx._written.filter((w) => w === '\r').length, COUNT, `expected ${COUNT} submitted commands`); + // 12 command texts should have been written. We count by command texts + // (w !== '\r') rather than Enters, because submit-verify may add a retry '\r' + // per command when no busy-rise is observed. + assert.equal(ctx._written.filter((w) => w !== '\r').length, COUNT, `expected ${COUNT} submitted commands`); watcher.close(); } finally { @@ -628,7 +639,8 @@ test('inFlight dedup: same filename event fired twice → processed at most once assert.equal(result.ok, true); // The trigger file is deleted after first processing, so any second fs.watch // event for the same name finds no file and is silently skipped. - assert.equal(ctx._written.filter((w) => w === '\r').length, 1, 'command submitted exactly once'); + // Count command texts (w !== '\r'): submit-verify may add a retry '\r'. + assert.equal(ctx._written.filter((w) => w !== '\r').length, 1, 'command submitted exactly once'); watcher.close(); } finally { @@ -708,7 +720,8 @@ test('W6 timeout_ms: per-trigger timeout_ms honored, overrides env-var fallback' const result = readResult(path.join(tmp, 'processed'), uuid); assert.equal(result.ok, true, 'result should be ok when timeout_ms overrides short env var'); assert.ok(result.waited_ms >= 100, `waited_ms (${result.waited_ms}) should be >= 100ms`); - assert.deepEqual(ctx._written, ['/compact', '\r'], 'PTY write should happen'); + // busy is false at submit time → no rise → verify retries the Enter once. + assert.deepEqual(ctx._written, ['/compact', '\r', '\r'], 'PTY write should happen (with verify-retry Enter)'); watcher.close(); } finally { @@ -990,7 +1003,8 @@ test('W7 default helper: real-pid mock passes default signal-0 probe → happy p const result = readResult(path.join(tmp, 'processed'), uuid); assert.equal(result.ok, true, 'live pid → default helper returns true → ok'); - assert.deepEqual(ctx._written, ['/help', '\r']); + // busy never rises → verify retries the Enter once. + assert.deepEqual(ctx._written, ['/help', '\r', '\r']); watcher.close(); } finally { @@ -1531,8 +1545,9 @@ test('chain validation: invalid per-step timeout_ms → ok:false, no PTY write', }); // CHAIN-12: instant-reply path on a mid-chain step (i>0) — busy never rises within -// BUSY_RISE_TIMEOUT_MS so the watcher must declare the turn complete and proceed. -test('chain instant-reply mid-chain: step 1 never sets busy → proceeds to step 2 after ~2s', async () => { +// the verify window, so submit-verify retries the Enter once and then the watcher +// declares the turn complete and proceeds. Step 2 (final) also goes through verify. +test('chain instant-reply mid-chain: step 1 never sets busy → verify-retries then proceeds to step 2', async () => { const tmp = mkTmp(); try { process.env.SWITCHBOARD_TRIGGERS_DIR = tmp; @@ -1580,13 +1595,203 @@ test('chain instant-reply mid-chain: step 1 never sets busy → proceeds to step const result = readResult(path.join(tmp, 'processed'), uuid); assert.equal(result.ok, true, 'chain should succeed via instant-reply path'); assert.equal(result.steps.length, 3, 'all 3 steps must have run'); - assert.deepEqual(ctx._written, ['/first', '\r', '/second', '\r', '/third', '\r']); - // Step 1's instant-reply path should have spent ~2s (BUSY_RISE_TIMEOUT_MS) - assert.ok(result.steps[1].waited_ms >= 1900 && result.steps[1].waited_ms <= 2400, - `step 1 should have waited ~2000ms for the rising edge; got ${result.steps[1].waited_ms}ms`); - // Total elapsed dominated by step 1's instant-reply wait - assert.ok(elapsed >= 2000 && elapsed <= 3500, - `total elapsed should reflect the ~2s busy-rise wait; got ${elapsed}ms`); + // Steps 1 and 2 never observe a busy-rise → each gets a single verify-retry '\r'. + assert.deepEqual(ctx._written, ['/first', '\r', '/second', '\r', '\r', '/third', '\r', '\r']); + assert.equal(result.steps[0].submit_retries, 0, 'step 0 rose (busy@20ms) → no retry'); + assert.equal(result.steps[1].submit_retries, 1, 'step 1 never rose → one verify-retry'); + assert.equal(result.steps[2].submit_retries, 1, 'step 2 (final) never rose → one verify-retry'); + // Step 1 spent two verify windows (~2 × SWITCHBOARD_SUBMIT_VERIFY_MS=400ms) probing + // for the rising edge across the initial submit and the retry. + assert.ok(result.steps[1].waited_ms >= 700 && result.steps[1].waited_ms <= 1400, + `step 1 should have waited ~2 verify windows for the rising edge; got ${result.steps[1].waited_ms}ms`); + // Total elapsed dominated by steps 1 & 2's verify+retry windows. + assert.ok(elapsed >= 1500 && elapsed <= 3500, + `total elapsed should reflect the verify+retry windows; got ${elapsed}ms`); + + watcher.close(); + } finally { + delete process.env.SWITCHBOARD_TRIGGERS_DIR; + delete process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS; + cleanup(tmp); + } +}); + +// ── submit-verify tests (2026-06-04 "Enter absorbed in composer" incident) ────── + +// VERIFY-1: single command, busy NEVER rises → submit-verify retries the Enter +// once. _written must carry the retry '\r' and result.submit_retries === 1. +test('submit-verify single: busy never rises → retry Enter, submit_retries:1', async () => { + const tmp = mkTmp(); + try { + process.env.SWITCHBOARD_TRIGGERS_DIR = tmp; + process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS = '2000'; + + const { start } = require('../trigger-watcher'); + const SESSION_ID = 'sess-verify-noRise-' + Date.now(); + const ctx = makeCtx(SESSION_ID, () => false); // busy never rises + const watcher = start(ctx); + + const uuid = 'verify-norise-' + Date.now(); + writeTrigger(tmp, uuid, { sessionId: SESSION_ID, command: 'resume the task' }); + + const resultPath = path.join(tmp, 'processed', uuid + '.result.json'); + await waitForFile(resultPath, 3000); + + const result = readResult(path.join(tmp, 'processed'), uuid); + assert.equal(result.ok, true, 'result should still be ok (instant-reply semantics preserved)'); + assert.equal(result.submit_retries, 1, 'one verify-retry when no busy-rise observed'); + // command text, discrete Enter, then the single retry Enter. + assert.deepEqual(ctx._written, ['resume the task', '\r', '\r'], + 'should write text, Enter, then exactly one retry Enter'); + + watcher.close(); + } finally { + delete process.env.SWITCHBOARD_TRIGGERS_DIR; + delete process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS; + cleanup(tmp); + } +}); + +// VERIFY-2: single command, busy rises promptly after the submit → no retry, +// result.submit_retries === 0 and only one Enter written. +test('submit-verify single: busy rises fast → no retry, submit_retries:0', async () => { + const tmp = mkTmp(); + try { + process.env.SWITCHBOARD_TRIGGERS_DIR = tmp; + process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS = '2000'; + + const { start } = require('../trigger-watcher'); + const SESSION_ID = 'sess-verify-rise-' + Date.now(); + // Busy rises the moment the discrete Enter ('\r') is written — the verify + // poll observes the rising edge on its first tick → no retry. + let busy = false; + const ctx = makeCtx(SESSION_ID, () => busy); + const origWrite = ctx._ptyProcess.write.bind(ctx._ptyProcess); + ctx._ptyProcess.write = function(data) { + origWrite(data); + if (data === '\r') busy = true; // turn starts immediately on submit + }; + const watcher = start(ctx); + + const uuid = 'verify-rise-' + Date.now(); + writeTrigger(tmp, uuid, { sessionId: SESSION_ID, command: 'do the thing' }); + + const resultPath = path.join(tmp, 'processed', uuid + '.result.json'); + await waitForFile(resultPath, 3000); + + const result = readResult(path.join(tmp, 'processed'), uuid); + assert.equal(result.ok, true); + assert.equal(result.submit_retries, 0, 'no retry when busy rises promptly'); + assert.deepEqual(ctx._written, ['do the thing', '\r'], 'only one Enter, no retry'); + + watcher.close(); + } finally { + delete process.env.SWITCHBOARD_TRIGGERS_DIR; + delete process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS; + cleanup(tmp); + } +}); + +// VERIFY-3: chain whose FINAL step never raises busy → the final step still +// gets a submit-verify + retry (the exact 2026-06-04 incident shape), and the +// retry is traced on steps[last].submit_retries. Earlier steps that rise +// normally record submit_retries:0. +test('submit-verify chain final step silent: retry traced on steps[last].submit_retries', async () => { + const tmp = mkTmp(); + try { + process.env.SWITCHBOARD_TRIGGERS_DIR = tmp; + process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS = '10000'; + + const { start } = require('../trigger-watcher'); + const SESSION_ID = 'sess-verify-finalsilent-' + Date.now(); + let busy = false; + const ctx = makeChainCtx(SESSION_ID, { noAutoTurn: true }); + let writeCount = 0; + const origWrite = ctx._ptyProcess.write.bind(ctx._ptyProcess); + ctx._ptyProcess.write = function(data) { + origWrite(data); + writeCount++; + // Step 0 submit ('\r' is the 2nd write): normal turn rises then falls. + if (writeCount === 2) { + setTimeout(() => { busy = true; }, 20); + setTimeout(() => { busy = false; }, 200); + } + // Final step (step 1) never raises busy → must verify-retry the Enter. + }; + ctx.isSessionBusy = (id) => id === SESSION_ID ? busy : false; + + const watcher = start(ctx); + + const uuid = 'verify-finalsilent-' + Date.now(); + writeTrigger(tmp, uuid, { + sessionId: SESSION_ID, + wait: 'none', + chain: [ + { command: '/compact' }, + { command: 'resume and finish' }, // FINAL step — Enter gets absorbed + ], + timeout_ms: 8000, + }); + + const resultPath = path.join(tmp, 'processed', uuid + '.result.json'); + await waitForFile(resultPath, 6000); + + const result = readResult(path.join(tmp, 'processed'), uuid); + assert.equal(result.ok, true, 'chain should complete'); + assert.equal(result.steps.length, 2); + assert.equal(result.steps[0].submit_retries, 0, 'step 0 rose normally → no retry'); + assert.equal(result.steps[1].submit_retries, 1, 'final step never rose → one verify-retry'); + // Final step carries the retry '\r'; step 0 does not. + assert.deepEqual(ctx._written, + ['/compact', '\r', 'resume and finish', '\r', '\r'], + 'final step writes text, Enter, then the verify-retry Enter'); + + watcher.close(); + } finally { + delete process.env.SWITCHBOARD_TRIGGERS_DIR; + delete process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS; + cleanup(tmp); + } +}); + +// VERIFY-4: chain happy path (makeChainCtx auto-turn raises busy on every '\r') +// → no step needs a retry, submit_retries is 0 for every step and no extra '\r' +// appears in _written. +test('submit-verify chain happy: auto-turn rises every step → submit_retries:0 everywhere', async () => { + const tmp = mkTmp(); + try { + process.env.SWITCHBOARD_TRIGGERS_DIR = tmp; + process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS = '5000'; + + const { start } = require('../trigger-watcher'); + const SESSION_ID = 'sess-verify-happy-' + Date.now(); + const ctx = makeChainCtx(SESSION_ID); // auto-turn: busy@50, idle@200 per '\r' + const watcher = start(ctx); + + const uuid = 'verify-happy-' + Date.now(); + writeTrigger(tmp, uuid, { + sessionId: SESSION_ID, + wait: 'idle', + chain: [ + { command: '/compact' }, + { command: 'verify and commit' }, + { command: 'open the PR' }, + ], + timeout_ms: 8000, + }); + + const resultPath = path.join(tmp, 'processed', uuid + '.result.json'); + await waitForFile(resultPath, 8000); + + const result = readResult(path.join(tmp, 'processed'), uuid); + assert.equal(result.ok, true); + assert.equal(result.steps.length, 3); + for (const s of result.steps) { + assert.equal(s.submit_retries, 0, `step ${s.idx} should not retry on a healthy turn`); + } + // No retry '\r' anywhere — exactly one Enter per command. + assert.deepEqual(ctx._written, + ['/compact', '\r', 'verify and commit', '\r', 'open the PR', '\r']); watcher.close(); } finally { diff --git a/trigger-watcher.js b/trigger-watcher.js index 14dc7375..e21d526a 100644 --- a/trigger-watcher.js +++ b/trigger-watcher.js @@ -89,47 +89,43 @@ async function submitToPty(ptyProcess, command) { ptyProcess.write('\r'); } -function getTriggersDir() { - return process.env.SWITCHBOARD_TRIGGERS_DIR || DEFAULT_TRIGGERS_DIR; -} - -function getIdleTimeout() { - const v = process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS; - if (v !== undefined) { - const parsed = parseInt(v, 10); - return Number.isFinite(parsed) ? parsed : DEFAULT_IDLE_TIMEOUT; // I4: NaN guard - } - return DEFAULT_IDLE_TIMEOUT; +// Window (ms) to wait for the busy rising edge when verifying a submission. +// Defaults to BUSY_RISE_TIMEOUT_MS; override via SWITCHBOARD_SUBMIT_VERIFY_MS. +function getSubmitVerifyMs() { + const v = Number(process.env.SWITCHBOARD_SUBMIT_VERIFY_MS); + return Number.isFinite(v) && v >= 0 ? v : BUSY_RISE_TIMEOUT_MS; } /** - * Poll until isSessionBusy(sessionId) returns false, or the timeout expires, - * or the session exits (PTY no longer available). + * Poll ctx.isSessionBusy(sessionId) for a rising edge (busy=true) up to + * `windowMs`, bounded by the absolute `deadlineMs`. Stops early if the PTY + * disappears. * - * @param {string} sessionId - * @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 { rose, timedOut, sessionExited, waited_ms }. + * - rose: busy=true was observed + * - timedOut: global deadline fired before any rise + * - sessionExited: PTY vanished during the poll */ -function waitForIdle(sessionId, ctx, timeoutMs) { +function pollForBusyRise(sessionId, ctx, windowMs, deadlineMs) { return new Promise((resolve) => { - const timeout = (timeoutMs !== undefined) ? timeoutMs : getIdleTimeout(); - const start = Date.now(); + const start = Date.now(); + const windowEnd = start + windowMs; function check() { - const waited_ms = Date.now() - start; + const now = Date.now(); - // W5: detect PTY closure during wait + if (now >= deadlineMs) { + return resolve({ rose: false, timedOut: true, sessionExited: false, waited_ms: now - start }); + } if (!ctx.getPtyForSession(sessionId)) { - return resolve({ timedOut: false, sessionExited: true, waited_ms }); + return resolve({ rose: false, timedOut: false, sessionExited: true, waited_ms: now - start }); } - - if (!ctx.isSessionBusy(sessionId)) { - return resolve({ timedOut: false, sessionExited: false, waited_ms }); + if (ctx.isSessionBusy(sessionId)) { + return resolve({ rose: true, timedOut: false, sessionExited: false, waited_ms: now - start }); } - if (waited_ms >= timeout) { - return resolve({ timedOut: true, sessionExited: false, waited_ms }); + if (now >= windowEnd) { + // Verify window elapsed without a rise — caller decides what to do. + return resolve({ rose: false, timedOut: false, sessionExited: false, waited_ms: now - start }); } setTimeout(check, IDLE_POLL_INTERVAL); } @@ -139,87 +135,156 @@ function waitForIdle(sessionId, ctx, timeoutMs) { } /** - * After injecting a command, wait for the session's busy state to go: - * true (turn started) → false (turn finished). + * Submit a command and verify it actually started a turn. * - * TOCTOU note: Claude may answer so fast that busy=true is never observed - * between IDLE_POLL_INTERVAL (100ms) ticks. We wait up to BUSY_RISE_TIMEOUT_MS - * (2s) for the rising edge; if it doesn't arrive within that window (but - * before the global deadline), we assume the turn completed instantly and - * return immediately. + * 1. submitToPty(text + discrete Enter) + * 2. Poll for busy-rise within SWITCHBOARD_SUBMIT_VERIFY_MS. + * 3. Rise observed → done (submit_retries: 0). + * 4. No rise → write a SINGLE bare '\r' (a no-op on an empty composer, so it is + * harmless if the first submit actually worked; if the text is still sitting + * in the composer because the first Enter was absorbed, this submits it) and + * poll the same window again (submit_retries: 1). * - * Known risk of the instant-reply heuristic: if the model takes longer than - * 2 s to start tokenizing (cold start, network stall, paused mid-stream), - * Phase 1 wrongly returns success and the next chain step's input will be - * appended to the previous turn rather than starting a new prompt. This is - * accepted as the lesser of two evils — the alternative (longer wait) penalises - * the common fast-reply case. Callers that need stronger guarantees should - * set a per-step `timeout_ms` and inspect `waited_ms` to detect the rare - * "near-2000ms then declared instant" pattern. + * The observed rise IS the equivalent of waitForTurnComplete's Phase 1; callers + * MUST NOT then wait for the rise again — they proceed straight to busy-fall. * - * If the global deadline fires first, we return {timedOut: true}. + * Returns { submit_retries, rose, sessionExited, timedOut, waited_ms }. + * - waited_ms is the total time spent polling (both windows + retry). * - * @param {string} sessionId - * @param {object} ctx - * @param {number} deadlineMs absolute epoch-ms deadline (shared global deadline) - * Returns { timedOut: boolean, sessionExited: boolean, waited_ms: number }. + * If sessionExited/timedOut fire, the caller short-circuits with the usual + * error result. If neither rise nor retry produces a rise (and no deadline), + * the caller keeps the legacy instant-reply semantics — submit_retries traces + * that the verification could not confirm a turn started. */ -function waitForTurnComplete(sessionId, ctx, deadlineMs) { +async function submitWithVerify(ptyProcess, sessionId, command, ctx, deadlineMs) { + await submitToPty(ptyProcess, command); + + const windowMs = getSubmitVerifyMs(); + // No explicit (global) deadline → the verify window alone governs; the retry + // must fire on window expiry, so the deadline must NOT coincide with it. + const effectiveDeadline = (deadlineMs !== undefined) ? deadlineMs : Infinity; + + const first = await pollForBusyRise(sessionId, ctx, windowMs, effectiveDeadline); + if (first.rose || first.sessionExited || first.timedOut) { + return { + submit_retries: 0, + rose: first.rose, + sessionExited: first.sessionExited, + timedOut: first.timedOut, + waited_ms: first.waited_ms, + }; + } + + // No rise within the window — retry the Enter ONCE (bare '\r', never the text). + try { + ptyProcess.write('\r'); + } catch (err) { + // Surface as a sessionExited-like failure; caller maps to an error result. + return { + submit_retries: 1, + rose: false, + sessionExited: false, + timedOut: false, + writeError: err, + waited_ms: first.waited_ms, + }; + } + + const second = await pollForBusyRise(sessionId, ctx, windowMs, effectiveDeadline); + return { + submit_retries: 1, + rose: second.rose, + sessionExited: second.sessionExited, + timedOut: second.timedOut, + waited_ms: first.waited_ms + second.waited_ms, + }; +} + +/** + * Wait only for the busy FALLING edge (busy → false), i.e. the turn finishing. + * Used after submitWithVerify has already confirmed (or assumed) the rise. + * + * Returns { timedOut, sessionExited, waited_ms }. + */ +function waitForBusyFall(sessionId, ctx, deadlineMs) { return new Promise((resolve) => { const start = Date.now(); - // busyRiseDeadline is the earliest of: 2s from now, or the global deadline. - // If the global deadline is sooner, Phase 1 times out → timedOut:true. - // If BUSY_RISE_TIMEOUT_MS fires first, we assume instant-reply → timedOut:false. - const busyRiseAt = start + BUSY_RISE_TIMEOUT_MS; - // Phase 1: wait for busy=true (turn started accepting our injected command) - function waitForBusy() { + function check() { const now = Date.now(); - if (now >= deadlineMs) { return resolve({ timedOut: true, sessionExited: false, waited_ms: now - start }); } - if (!ctx.getPtyForSession(sessionId)) { return resolve({ timedOut: false, sessionExited: true, waited_ms: now - start }); } - - if (ctx.isSessionBusy(sessionId)) { - // Rising edge observed — proceed to Phase 2 - return waitForIdle2(); - } - - if (now >= busyRiseAt) { - // TOCTOU: BUSY_RISE_TIMEOUT_MS elapsed without busy rising; - // assume the turn completed so quickly we missed the rising edge. + if (!ctx.isSessionBusy(sessionId)) { return resolve({ timedOut: false, sessionExited: false, waited_ms: now - start }); } - - setTimeout(waitForBusy, IDLE_POLL_INTERVAL); + setTimeout(check, IDLE_POLL_INTERVAL); } - // Phase 2: wait for busy=false (turn finished) - function waitForIdle2() { - const now = Date.now(); - if (now >= deadlineMs) { - return resolve({ timedOut: true, sessionExited: false, waited_ms: now - start }); - } + check(); + }); +} + +function getTriggersDir() { + return process.env.SWITCHBOARD_TRIGGERS_DIR || DEFAULT_TRIGGERS_DIR; +} + +function getIdleTimeout() { + const v = process.env.SWITCHBOARD_TRIGGER_IDLE_TIMEOUT_MS; + if (v !== undefined) { + const parsed = parseInt(v, 10); + return Number.isFinite(parsed) ? parsed : DEFAULT_IDLE_TIMEOUT; // I4: NaN guard + } + return DEFAULT_IDLE_TIMEOUT; +} + +/** + * Poll until isSessionBusy(sessionId) returns false, or the timeout expires, + * or the session exits (PTY no longer available). + * + * @param {string} sessionId + * @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 }. + */ +function waitForIdle(sessionId, ctx, timeoutMs) { + return new Promise((resolve) => { + const timeout = (timeoutMs !== undefined) ? timeoutMs : getIdleTimeout(); + const start = Date.now(); + + function check() { + const waited_ms = Date.now() - start; + // W5: detect PTY closure during wait if (!ctx.getPtyForSession(sessionId)) { - return resolve({ timedOut: false, sessionExited: true, waited_ms: now - start }); + return resolve({ timedOut: false, sessionExited: true, waited_ms }); } if (!ctx.isSessionBusy(sessionId)) { - return resolve({ timedOut: false, sessionExited: false, waited_ms: now - start }); + return resolve({ timedOut: false, sessionExited: false, waited_ms }); } - - setTimeout(waitForIdle2, IDLE_POLL_INTERVAL); + if (waited_ms >= timeout) { + return resolve({ timedOut: true, sessionExited: false, waited_ms }); + } + setTimeout(check, IDLE_POLL_INTERVAL); } - waitForBusy(); + check(); }); } +// NOTE: the previous combined-phase waiter (waitForTurnComplete: busy-rise then +// busy-fall) was split into submitWithVerify (Phase 1, busy-rise + Enter retry) +// and waitForBusyFall (Phase 2, busy-fall) so the chain path can verify each +// submission and retry the Enter once if the turn never starts (2026-06-04 +// "text stuck in composer" incident). The instant-reply semantics are preserved: +// when no rise is confirmed, submitWithVerify still returns and waitForBusyFall +// returns immediately on an already-idle session. + /** * Validate a single timeout_ms value (for top-level or per-step). * Returns null if valid, or an error string if invalid. @@ -469,23 +534,31 @@ async function processTriggerFile(name, ctx, triggersDir, processedDir) { return; } - // Write to PTY: text, then Enter as a discrete keypress (see submitToPty). + // Write to PTY: text, then Enter as a discrete keypress (see submitToPty), + // then verify the submission actually started a turn — retrying the Enter + // once if the busy rising edge never arrives (the 2026-06-04 "text stuck in + // composer, Enter absorbed" incident). + let submitRetries = 0; try { - await submitToPty(ptyProcess, command); + const v = await submitWithVerify(ptyProcess, sessionId, command, ctx); + submitRetries = v.submit_retries; + if (v.writeError) throw v.writeError; } catch (err) { ctx.log.error('[trigger-watcher] PTY write failed:', err.message); await writeResult({ ok: false, error: 'pty write failed: ' + err.message, sessionId }); return; } - ctx.log.info(`[trigger-watcher] Sent command to ${sessionId}: ${command}`); + ctx.log.info(`[trigger-watcher] Sent command to ${sessionId}: ${command}` + + (submitRetries ? ` (submit retried ${submitRetries}x)` : '')); await writeResult({ - ok: true, + ok: true, sessionId, command, - sent_at: new Date().toISOString(), + sent_at: new Date().toISOString(), waited_ms, + submit_retries: submitRetries, }); return; } @@ -551,50 +624,85 @@ async function processTriggerFile(name, ctx, triggersDir, processedDir) { const stepSentAt = new Date().toISOString(); if (i === 0) step0SentAt = 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 + // deadline — mirroring the old combined waitForTurnComplete deadline. + let stepTimeoutMs; + if (step.timeout_ms !== undefined) { + stepTimeoutMs = Math.min(step.timeout_ms, globalDeadline - Date.now()); + } else { + stepTimeoutMs = globalDeadline - Date.now(); + } + const stepDeadline = Date.now() + stepTimeoutMs; + + // Submit the step and verify the turn actually started (busy rising edge). + // The verify poll IS this step's Phase 1 (busy-rise) — for non-final steps + // we proceed straight to the busy-FALL wait, never re-observing the rise. + // The verify window is bounded by this step's deadline; if no rise arrives + // we retry the bare Enter once (harmless no-op if already submitted). + let submitRetries = 0; + let stepWaitedMs = 0; + let verify; try { - await submitToPty(entry.ptyProcess, step.command); + verify = await submitWithVerify(entry.ptyProcess, sessionId, step.command, ctx, stepDeadline); } catch (err) { ctx.log.error(`[trigger-watcher] PTY write failed at chain step ${i}:`, err.message); await writeResult({ ok: false, error: 'pty write failed: ' + err.message, partial: true, steps_completed: i, sessionId, sent_at: step0SentAt, steps, total_waited_ms: totalWaitedMs }); return; } + if (verify.writeError) { + ctx.log.error(`[trigger-watcher] PTY write failed at chain step ${i}:`, verify.writeError.message); + 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; + } + submitRetries = verify.submit_retries; + stepWaitedMs += verify.waited_ms; + totalWaitedMs += verify.waited_ms; - ctx.log.info(`[trigger-watcher] Chain step ${i} sent to ${sessionId}: ${step.command}`); + ctx.log.info(`[trigger-watcher] Chain step ${i} sent to ${sessionId}: ${step.command}` + + (submitRetries ? ` (submit retried ${submitRetries}x)` : '')); - // Wait for the turn to complete (except after the last step — no need to wait) - let stepWaitedMs = 0; - if (i < chain.length - 1) { - // Determine timeout for this step's turn completion. - // Per-step timeout_ms (if set) is the deadline for THIS step's turn wait only. - // It is capped by the remaining global deadline. - let stepTimeoutMs; - if (step.timeout_ms !== undefined) { - stepTimeoutMs = Math.min(step.timeout_ms, globalDeadline - Date.now()); - } else { - stepTimeoutMs = globalDeadline - Date.now(); - } + // Session exited / global timeout observed during verify. + if (verify.sessionExited) { + ctx.log.warn(`[trigger-watcher] Session exited during chain step ${i} submit verify:`, sessionId); + steps.push({ idx: i, command: step.command, sent_at: stepSentAt, waited_ms: stepWaitedMs, submit_retries: submitRetries }); + await writeResult({ ok: false, error: 'session exited during wait', partial: true, steps_completed: i, sessionId, sent_at: step0SentAt, steps, total_waited_ms: totalWaitedMs }); + return; + } + if (verify.timedOut) { + ctx.log.warn(`[trigger-watcher] Chain timeout during step ${i} submit verify:`, sessionId); + steps.push({ idx: i, command: step.command, sent_at: stepSentAt, waited_ms: stepWaitedMs, submit_retries: submitRetries }); + await writeResult({ ok: false, error: 'chain timeout', partial: true, steps_completed: i, sessionId, sent_at: step0SentAt, steps, total_waited_ms: totalWaitedMs }); + return; + } - const stepDeadline = Date.now() + stepTimeoutMs; - const result = await waitForTurnComplete(sessionId, ctx, stepDeadline); - stepWaitedMs = result.waited_ms; - totalWaitedMs += stepWaitedMs; + // For non-final steps, wait for the turn to FINISH (busy falling edge). + // submitWithVerify already consumed the rising edge. If the rise was never + // observed (instant-reply / unconfirmed submit), busy is already false and + // this returns immediately — preserving the legacy instant-reply behaviour + // while submit_retries records that verification 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); + stepWaitedMs += result.waited_ms; + totalWaitedMs += result.waited_ms; if (result.sessionExited) { ctx.log.warn(`[trigger-watcher] Session exited during chain step ${i} turn wait:`, sessionId); - steps.push({ idx: i, command: step.command, sent_at: stepSentAt, waited_ms: stepWaitedMs }); + steps.push({ idx: i, command: step.command, sent_at: stepSentAt, waited_ms: stepWaitedMs, submit_retries: submitRetries }); await writeResult({ ok: false, error: 'session exited during wait', partial: true, steps_completed: i, sessionId, sent_at: step0SentAt, steps, total_waited_ms: totalWaitedMs }); return; } 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 }); + steps.push({ idx: i, command: step.command, sent_at: stepSentAt, waited_ms: stepWaitedMs, submit_retries: submitRetries }); await writeResult({ ok: false, error: 'chain timeout', partial: true, steps_completed: i, sessionId, sent_at: step0SentAt, steps, total_waited_ms: totalWaitedMs }); return; } } - steps.push({ idx: i, command: step.command, sent_at: stepSentAt, waited_ms: stepWaitedMs }); + steps.push({ idx: i, command: step.command, sent_at: stepSentAt, waited_ms: stepWaitedMs, submit_retries: submitRetries }); } await writeResult({