diff --git a/.ai/contexts/session-cache.md b/.ai/contexts/session-cache.md index 3db7eaf8..02d417cc 100644 --- a/.ai/contexts/session-cache.md +++ b/.ai/contexts/session-cache.md @@ -212,6 +212,36 @@ the exact remote command, and the mutation proofs are in delete-then-insert path as the cold-start scan. Parsing 249 MB on the main thread would freeze the UI; `refreshFolder` is deliberately not the remote path. +- **Every child's handlers are bound to that child, not to the alias state** + (audit finding F1, 2026-09-11). `restartWatcherForAlias`'s synchronous + `stop()` then `start()` — and `syncRemoteWatchers` doing the same on a host + toggle — kills child A and immediately spawns child B into the same state; + A's `'close'` (and any late stdout `'data'`) arrives afterwards, on ssh's own + schedule, not kill()'s. `close`/`data` handlers close over the specific + `child` they were attached to and check `s.child === child` before touching + state, so a superseded child's late events are dropped instead of nulling + B out from under `stop()`/`stopAll()` and spawning an unkillable third + child. Proven in `test/remote-watch.test.js` with a fake child whose `kill()` + does not itself emit `'close'` (a real ssh process doesn't either) — a test + drives the late close explicitly via `child.emitClose()`, after the + replacement child already exists. + +- **The ssh child gets a connect timeout and keepalive, and a quick failure is + logged with its stderr tail** (audit finding F4). `buildSshArgs` adds `-o + ConnectTimeout=10 -o ServerAliveInterval=30 -o ServerAliveCountMax=3` (before + the alias, after `-tt`/`BatchMode`) so a half-open TCP session (laptop sleep, + NAT) is detected and reaped instead of leaving `isRunning()` reporting a + channel that receives nothing, forever. The last ≤200 bytes of stderr are + kept per child and logged once per backoff-tier change on a quick failure + (`< HEALTHY_MS`), same throttle as `onHostFailure` above — never on every + attempt, never for a healthy long run that just happened to exit. + +- **A pending coalesce cooldown cannot fire after `stop()`** (audit finding + F11, minor). `killChild` only ever cleared `restartTimer`; a coalesce + cooldown timer (and its `pending` flag) from `emitCoalesced` is now also + cleared and reset inside `stop()`, so a queued trailing event from before + the stop can never reach `s.onEvent` afterwards. + ### Remote hosts — busy spinner (issue #242) Remote transcript-write activity feeds the same `setActivity(sessionId, active, via)` diff --git a/remote-watch.js b/remote-watch.js index e0b6252c..39076eb4 100644 --- a/remote-watch.js +++ b/remote-watch.js @@ -24,7 +24,12 @@ function buildWatchCommand() { } function buildSshArgs(alias) { - return ['-tt', '-o', 'BatchMode=yes', alias, buildWatchCommand()]; + // see .ai/contexts/session-cache.md ("Remote hosts — watch channel") + return [ + '-tt', '-o', 'BatchMode=yes', + '-o', 'ConnectTimeout=10', '-o', 'ServerAliveInterval=30', '-o', 'ServerAliveCountMax=3', + alias, buildWatchCommand(), + ]; } function parseWatchLine(line) { @@ -68,10 +73,12 @@ function createRemoteWatcher(opts = {}) { s.onEvent(s.alias, kind); s.cooldown[kind] = true; const t = setT(() => { + s.cooldownTimer[kind] = null; s.cooldown[kind] = false; if (s.pending[kind]) { s.pending[kind] = false; emitCoalesced(s, kind); } }, COALESCE_MS); if (t && t.unref) t.unref(); + s.cooldownTimer[kind] = t; } function handleLine(s, rawLine) { @@ -106,10 +113,20 @@ function createRemoteWatcher(opts = {}) { if (s.restartTimer && s.restartTimer.unref) s.restartTimer.unref(); } - function onExit(s) { + // identity-guarded: a superseded child's late close must not touch the state — see .ai/contexts/session-cache.md ("watch channel") + function onExit(s, child, code) { + if (s.child !== child) return; s.child = null; if (s.stopped || s.unwatchable) return; - s.failures = (Date.now() - s.spawnedAt) < HEALTHY_MS ? s.failures + 1 : 0; + const isFailure = (Date.now() - s.spawnedAt) < HEALTHY_MS; + const prevDelay = backoffDelayMs(s.failures, RESTART_BASE_MS); + s.failures = isFailure ? s.failures + 1 : 0; + const delay = backoffDelayMs(s.failures, RESTART_BASE_MS); + if (isFailure && delay !== prevDelay) { + const tail = s.stderrTail ? ` — stderr: ${s.stderrTail}` : ''; + log.warn(`[remote-watch:${s.alias}] ssh exited (code ${code}) after ${s.failures} consecutive quick ` + + `failure(s), retrying in ${Math.round(delay / 1000)}s${tail}`); + } scheduleRestart(s); } @@ -127,13 +144,20 @@ function createRemoteWatcher(opts = {}) { s.child = child; s.buf = ''; s.spawnedAt = Date.now(); + s.stderrTail = ''; if (child.stdout) { child.stdout.setEncoding('utf8'); - child.stdout.on('data', (chunk) => onData(s, chunk)); + child.stdout.on('data', (chunk) => { if (s.child === child) onData(s, chunk); }); + } + if (child.stderr) { + child.stderr.setEncoding('utf8'); + child.stderr.on('data', (chunk) => { + if (s.child !== child) return; + s.stderrTail = (s.stderrTail + chunk).slice(-200); + }); } - if (child.stderr) child.stderr.on('data', () => {}); child.on('error', () => {}); - child.on('close', () => onExit(s)); + child.on('close', (code) => onExit(s, child, code)); } function getState(alias) { @@ -142,8 +166,10 @@ function createRemoteWatcher(opts = {}) { s = { alias, child: null, buf: '', stopped: true, unwatchable: false, failures: 0, spawnedAt: 0, restartTimer: null, onEvent: null, onActivity: null, + stderrTail: '', cooldown: { project: false, session: false }, pending: { project: false, session: false }, + cooldownTimer: { project: null, session: null }, }; states.set(alias, s); } @@ -167,6 +193,11 @@ function createRemoteWatcher(opts = {}) { if (!s) return; s.stopped = true; killChild(s); + for (const kind of Object.keys(s.cooldownTimer)) { + if (s.cooldownTimer[kind]) { clearT(s.cooldownTimer[kind]); s.cooldownTimer[kind] = null; } + s.cooldown[kind] = false; + s.pending[kind] = false; + } } function stopAll() { diff --git a/test/remote-watch.test.js b/test/remote-watch.test.js index 5317ad00..22fad1b0 100644 --- a/test/remote-watch.test.js +++ b/test/remote-watch.test.js @@ -9,6 +9,12 @@ // 3. A burst of events collapses to a coalesced signal, not one per line. // 4. A line that does not parse to a safe path is dropped, not forwarded. // 5. A child that exits restarts on the same backoff shape as remote-index. +// 6. A child's handlers are bound to that child, not to the alias state: +// a superseded child's late close/data must never touch the state a +// newer child owns (audit finding F1). The fake child below does NOT +// emit 'close' on kill() — a real ssh process reports its exit on its +// own asynchronous schedule — so a test drives that arrival explicitly +// with child.emitClose(), on whatever tick reproduces the race. const test = require('node:test'); const assert = require('node:assert/strict'); @@ -28,7 +34,10 @@ function fakeChild() { child.stdout = new Readable({ read() {} }); child.stderr = new Readable({ read() {} }); child.killed = 0; - child.kill = () => { child.killed++; child.emit('close', null); }; + // Deliberately does NOT emit 'close' here: a real ssh process's exit is + // reported asynchronously, independent of when kill() was called (F1). + child.kill = () => { child.killed++; }; + child.emitClose = (code = null) => child.emit('close', code); return child; } @@ -57,6 +66,7 @@ function fakeTimers() { test('buildSshArgs passes -tt, BatchMode, and keeps alias/command as separate argv elements', () => { const args = buildSshArgs('planificator'); assert.ok(args.includes('-tt'), '-tt is mandatory: without it a killed ssh leaves the remote inotifywait running'); + assert.equal(args[0], '-tt', '-tt must come first'); assert.ok(args.includes('BatchMode=yes')); assert.equal(args[args.length - 2], 'planificator', 'alias is its own argv element, never concatenated'); const command = args[args.length - 1]; @@ -65,6 +75,18 @@ test('buildSshArgs passes -tt, BatchMode, and keeps alias/command as separate ar assert.ok(command.includes(REMOTE_SESSIONS_REL)); }); +test('buildSshArgs adds a connect timeout and keepalive so a half-open ssh does not hang silently forever (F4)', () => { + const args = buildSshArgs('planificator'); + const aliasIdx = args.indexOf('planificator'); + assert.ok(aliasIdx > 0, 'alias must still be present as its own argv element'); + for (const opt of ['ConnectTimeout=10', 'ServerAliveInterval=30', 'ServerAliveCountMax=3']) { + const idx = args.indexOf(opt); + assert.ok(idx !== -1, `${opt} must be present`); + assert.ok(idx < aliasIdx, `${opt} must come before the alias`); + assert.equal(args[idx - 1], '-o', `${opt} must be introduced by its own -o flag`); + } +}); + test('parseWatchLine recovers kind and rel path for a well-formed line', () => { assert.deepEqual( parseWatchLine(`P|${REMOTE_PROJECTS_REL}/-srv-a/session.jsonl`), @@ -221,6 +243,90 @@ test('a live watcher restarts on exit using the same backoff shape as remote-ind assert.equal(spawn.calls.length, 4, 'each scheduled restart actually respawns the watcher'); }); +test('a quick failing exit logs once with the stderr tail; a duplicate close on the same child never re-logs (F4)', async () => { + const spawn = spawnRecorder(); + const timers = fakeTimers(); + const warnings = []; + const log = { info() {}, warn: (msg) => warnings.push(msg), error() {} }; + const watcher = createRemoteWatcher({ spawn, log, timers }); + + watcher.start('vps', () => {}); + const a = spawn.calls[0].child; + a.stderr.push('Host key verification failed.\n'); + await new Promise((resolve) => setImmediate(resolve)); + a.emit('close', 255); // dies almost immediately -> counts as a failure, tier 1 + + assert.equal(warnings.length, 1, 'the first quick failure at a new backoff tier must log once'); + assert.match(warnings[0], /Host key verification failed\./, 'the captured stderr tail must appear in the warning'); + assert.match(warnings[0], /255/, 'the exit code must appear in the warning'); + + // A duplicate 'close' on the very same, already-handled child (the kind of + // glitch a real child_process can produce) must be a no-op: the F1 + // identity guard already nulled s.child, so this can never log again. + a.emit('close', 255); + assert.equal(warnings.length, 1, 'a duplicate close on the same already-handled child must not log again'); +}); + +test('a stop() immediately followed by start() does not let A\'s late async close orphan B (F1)', async () => { + const spawn = spawnRecorder(); + const timers = fakeTimers(); + const watcher = createRemoteWatcher({ spawn, log: silentLog, timers }); + const events = []; + const onEvent = (alias, kind) => events.push({ alias, kind }); + + watcher.start('vps', onEvent); + const a = spawn.calls[0].child; + + watcher.stop('vps'); + assert.equal(a.killed, 1, 'A must be killed by stop()'); + + watcher.start('vps', onEvent); + assert.equal(spawn.calls.length, 2, 'start() spawns B right away, without waiting for A to actually close'); + const b = spawn.calls[1].child; + + // A's real ssh process reports its exit on its own schedule, independent + // of when kill() was called — arriving here, after B already owns + // s.child, is exactly the race. + a.emitClose(0); + for (const h of timers.scheduled) if (!h.cleared) h.fn(); + assert.equal(spawn.calls.length, 2, "A's late close must never spawn a third child (C) behind B's back"); + assert.equal(watcher.isRunning('vps'), true, 'B must remain the tracked, live watcher'); + + // A data chunk delivered after supersession must never reach onEvent. + a.stdout.push(`P|${REMOTE_PROJECTS_REL}/-srv-a/session.jsonl\n`); + a.stdout.push(null); + await new Promise((resolve) => setImmediate(resolve)); + assert.equal(events.length, 0, 'a chunk from the superseded child A must never reach onEvent'); + + watcher.stopAll(); + assert.equal(b.killed, 1, 'stopAll() must still be able to kill B — it must never be orphaned'); +}); + +test('stop() clears a pending coalesce cooldown so it cannot fire onEvent after stop (F11)', async () => { + const spawn = spawnRecorder(); + const timers = fakeTimers(); + const watcher = createRemoteWatcher({ spawn, log: silentLog, timers }); + const events = []; + + watcher.start('vps', (alias, kind) => events.push({ alias, kind })); + const { child } = spawn.calls[0]; + const rel = `${REMOTE_PROJECTS_REL}/-srv-a/session.jsonl`; + + child.stdout.push(`P|${rel}\n`); + child.stdout.push(`P|${rel}\n`); // second event while still in cooldown -> queued as pending + await new Promise((resolve) => setImmediate(resolve)); + assert.equal(events.length, 1, 'the leading edge fires once; the second event is only pending'); + + const cooldown = timers.scheduled.filter(h => !h.cleared).pop(); + assert.ok(cooldown, 'a cooldown timer must be pending with a queued trailing event'); + + watcher.stop('vps'); + assert.ok(cooldown.cleared, 'stop() must clear the pending coalesce cooldown, not just the restart timer'); + + cooldown.fn(); // simulate the timer firing anyway, in case the clear alone were reverted + assert.equal(events.length, 1, 'a cooldown that outlives stop() must never re-fire onEvent'); +}); + test('stop() kills the live child and cancels any pending restart', () => { const spawn = spawnRecorder(); const timers = fakeTimers();