Compare commits

...
4 changed files with 392 additions and 12 deletions

No files matched your search

+20 -5
View File
@@ -20,18 +20,33 @@ function buildLiveShellProbe(marker) {
}
function probeKindFromName(name) {
return name === "fish" ? "fish"
: /^(?:ba|da|z|k|a)?sh$/.test(name) ? "posix" : null;
}
function parseLiveShellProbe(output, marker) {
const lines = String(output).replace(/\r/g, "\n").split("\n");
if (!lines.some((line) => line.startsWith(`${marker}_Q`))) return null;
for (const line of lines) {
if (!line.startsWith(`${marker}_P:`)) continue;
const name = line.slice(marker.length + 3).trim().split("/").pop().replace(/^-/, "");
return {
kind: name === "fish" ? "fish"
: /^(?:ba|da|z|k|a)?sh$/.test(name) ? "posix" : null,
};
return { kind: probeKindFromName(name) };
}
return { kind: null };
}
module.exports = { buildLiveShellProbe, parseLiveShellProbe };
// Recover the shell kind from a probe reply whose _Q completion marker was
// lost or mangled: the _P line may already have arrived and identified the
// live shell, and the fallback wrapper must still match it (#3449).
function probeShellKindFromPartial(output, marker) {
const lines = String(output).replace(/\r/g, "\n").split("\n");
for (const line of lines) {
if (!line.startsWith(`${marker}_P:`)) continue;
const name = line.slice(marker.length + 3).trim().split("/").pop().replace(/^-/, "");
return probeKindFromName(name);
}
return null;
}
module.exports = { buildLiveShellProbe, parseLiveShellProbe, probeShellKindFromPartial };
+182
View File
@@ -72,6 +72,188 @@ test('cancelled probe never injects user command after a late reply', async () =
assert.ok(writes.every((data) => !data.includes('touch should-not-run')));
});
test('probe deadline delivers the command when the probe reply never arrives', async () => {
const pty = new EventEmitter();
const writes = [];
pty.write = (data) => writes.push(data);
const aborted = [];
const job = startPtyJob(pty, 'printf silent-command', {
shellKind: 'posix', probeLiveShell: true, timeoutMs: 5000, probeDeadlineMs: 80,
onProbeAborted: (marker) => aborted.push(marker),
});
assert.equal(writes.length, 1);
assert.ok(!writes.join('').includes('printf silent-command'));
// The paced probe (~1s) plus the probe deadline must pass, then the paced
// wrapped command is typed even though no probe reply ever came back.
const deadline = Date.now() + 3000;
while (Date.now() < deadline && !writes.join('').includes('printf silent-command')) {
await new Promise((resolve) => setTimeout(resolve, 30));
}
assert.ok(writes.join('').includes('printf silent-command'), writes.join('|'));
// The display reset must NOT be sent when the probe is abandoned: the
// preload treats _R as a permanent abort for the marker, which would stop
// the fallback wrapper's _I from re-arming echo suppression. It is
// deferred to finish() and only sent when the command never starts.
assert.deepEqual(aborted, []);
pty.emit('data', `${job.marker}_S\r\nsilent-ok\r\n${job.marker}_E:0\r\n`);
const result = await job.resultPromise;
assert.equal(result.exitCode, 0, JSON.stringify(result));
assert.match(result.stdout, /silent-ok/);
assert.equal(aborted.length, 0, 'no display reset once the command has started');
});
test('probe deadline fires before the command timers for short timeouts', async () => {
const pty = new EventEmitter();
const writes = [];
pty.write = (data) => writes.push(data);
const job = startPtyJob(pty, 'printf short-timeout', {
shellKind: 'posix', probeLiveShell: true, timeoutMs: 2000,
enforceWallTimeout: true,
});
assert.equal(writes.length, 1);
// With a 2s command timeout (and an active wall clock), the probe deadline
// must fire strictly before the output/wall timers so the wrapped command
// is still delivered instead of the job being finished as a timeout.
const deadline = Date.now() + 5000;
while (Date.now() < deadline && !writes.join('').includes('printf short-timeout')) {
await new Promise((resolve) => setTimeout(resolve, 30));
}
assert.ok(writes.join('').includes('printf short-timeout'), writes.join('|'));
assert.ok(!writes.includes('\x03'), 'the output/wall timeout must not interrupt first');
pty.emit('data', `${job.marker}_S\r\nok\r\n${job.marker}_E:0\r\n`);
const result = await job.resultPromise;
assert.equal(result.exitCode, 0, JSON.stringify(result));
assert.match(result.stdout, /ok/);
});
test('wall timeout does not finish the job before the wrapped command is delivered', async () => {
const pty = new EventEmitter();
const writes = [];
pty.write = (data) => writes.push(data);
const job = startPtyJob(pty, 'printf one-second-budget', {
shellKind: 'posix', probeLiveShell: true, timeoutMs: 1000,
enforceWallTimeout: true,
});
assert.equal(writes.length, 1);
// With a 1s wall budget the paced probe alone takes most of it: the wall
// timer must be paused during paced delivery and re-armed with the
// remaining wall time, and the probe recovery must fire against the
// remaining wall clock, so the wrapped command still gets typed instead of
// the job being finished as a wall timeout (#3449).
const deadline = Date.now() + 5000;
while (Date.now() < deadline && !writes.join('').includes('printf one-second-budget')) {
await new Promise((resolve) => setTimeout(resolve, 20));
}
assert.ok(writes.join('').includes('printf one-second-budget'), writes.join('|'));
assert.ok(!writes.includes('\x03'), 'the wall timeout must not interrupt mid-delivery');
pty.emit('data', `${job.marker}_S\r\nok\r\n${job.marker}_E:0\r\n`);
const result = await job.resultPromise;
assert.equal(result.exitCode, 0, JSON.stringify(result));
assert.match(result.stdout, /ok/);
});
test('wall timeout preserves budget for the command after paced delivery completes', async () => {
const pty = new EventEmitter();
const writes = [];
pty.write = (data) => writes.push(String(data));
const job = startPtyJob(pty, 'printf post-delivery-budget', {
shellKind: 'posix', probeLiveShell: true, timeoutMs: 1000,
enforceWallTimeout: true,
});
assert.equal(writes.length, 1);
// Wait for the silent probe's recovery wrapper to be fully delivered (the
// paced writes must have stopped before the success arrives, otherwise the
// paused wall clock hides the re-arm being negative).
let stable = 0;
const deadline = Date.now() + 10000;
while (
Date.now() < deadline
&& (!writes.join('').includes('printf post-delivery-budget') || stable < 2)
) {
const before = writes.length;
await new Promise((resolve) => setTimeout(resolve, 100));
stable = writes.length === before ? stable + 1 : 0;
}
assert.ok(writes.join('').includes('printf post-delivery-budget'), writes.join('|'));
await new Promise((resolve) => setTimeout(resolve, 200));
assert.ok(!writes.includes('\x03'), 'the wall timeout must not fire right after delivery');
pty.emit('data', `${job.marker}_S\r\nok\r\n${job.marker}_E:0\r\n`);
const result = await job.resultPromise;
assert.equal(result.ok, true, JSON.stringify(result));
assert.equal(result.exitCode, 0);
assert.match(result.stdout, /ok/);
});
test('wall deadline stays active while paced input waits for drain', async () => {
const pty = new EventEmitter();
const writes = [];
let finished = false;
// Every write hits backpressure and drains after 300ms: without an active
// wall deadline the drain waits would accumulate far beyond the 1s budget.
pty.write = (data) => {
writes.push(String(data));
setTimeout(() => {
if (!finished) pty.emit('drain');
}, 300);
return false;
};
const job = startPtyJob(pty, 'printf slow-drain-command', {
shellKind: 'posix', probeLiveShell: true, timeoutMs: 1000,
enforceWallTimeout: true,
});
job.resultPromise.then(() => { finished = true; }, () => { finished = true; });
const start = Date.now();
const result = await job.resultPromise;
const elapsed = Date.now() - start;
assert.ok(writes.length >= 2, 'the probe must have been paced across drains');
assert.equal(result.ok, false, JSON.stringify(result));
assert.match(result.error, /timed out/);
assert.ok(elapsed < 3000, `the wall deadline must bound the drain waits (${elapsed}ms)`);
});
test('late probe reply after the deadline is ignored and never double-delivers', async () => {
const pty = new EventEmitter();
const writes = [];
pty.write = (data) => writes.push(data);
const job = startPtyJob(pty, 'printf late-ok', {
shellKind: 'posix', probeLiveShell: true, timeoutMs: 5000, probeDeadlineMs: 60,
});
const deadline = Date.now() + 3000;
while (Date.now() < deadline && !writes.join('').includes('printf late-ok')) {
await new Promise((resolve) => setTimeout(resolve, 30));
}
assert.ok(writes.join('').includes('printf late-ok'));
// Let the paced wrapper delivery finish before snapshotting the writes.
let stable = writes.length;
do {
await new Promise((resolve) => setTimeout(resolve, 100));
stable = writes.length;
} while (writes.length !== stable);
const count = writes.length;
const delivered = writes.join('').split('printf late-ok').length - 1;
pty.emit('data', `${job.marker}_P:fish\n${job.marker}_Q`);
assert.equal(writes.length, count, 'a late reply must not re-trigger the probe');
pty.emit('data', `${job.marker}_S\r\nlate-ok\r\n${job.marker}_E:0\r\n`);
const result = await job.resultPromise;
assert.equal(result.exitCode, 0, JSON.stringify(result));
assert.match(result.stdout, /late-ok/);
assert.equal(writes.join('').split('printf late-ok').length - 1, delivered);
assert.equal(count, writes.length);
});
test('probe deadline abort reset is not duplicated when the command never starts', async () => {
const pty = new EventEmitter();
pty.write = () => {};
const aborted = [];
const job = startPtyJob(pty, 'echo never-runs', {
shellKind: 'posix', probeLiveShell: true, timeoutMs: 300, probeDeadlineMs: 50,
onProbeAborted: (marker) => aborted.push(marker),
});
const result = await job.resultPromise;
assert.equal(result.ok, false, JSON.stringify(result));
assert.equal(aborted.length, 1, aborted);
});
test('cancelling a probe completes when the idle prompt returns', async () => {
const pty = new EventEmitter();
pty.write = () => {};
+154 -5
View File
@@ -28,10 +28,36 @@ const {
} = require("./ptyExecHelpers.cjs");
const { extractTrailingIdlePrompt } = require("./shellUtils.cjs");
const { buildLiveShellProbe, parseLiveShellProbe } = require("./liveShellProbe.cjs");
const { buildLiveShellProbe, parseLiveShellProbe, probeShellKindFromPartial } = require("./liveShellProbe.cjs");
const DEFAULT_FOREGROUND_PTY_CAPTURE_CHARS = 1024 * 1024;
const END_MARKER_PROMPT_WAIT_MS = 30000;
// Bounded deadline for the live shell probe reply. When the probe's _Q
// completion marker never arrives (silent shells, lost or mangled marker
// output, pending canonical input), the job must not stall until the full
// command timeout with the command still undelivered (#3403, #3445).
const DEFAULT_PROBE_DEADLINE_MS = 15000;
// Time reserved after the probe deadline so the recovery path (wrapping and
// paced-delivering the wrapped command) can still run before the command
// deadlines fire: the output timer is armed just before the startup timer
// with the same timeoutMs, and enforceWallTimeout callers start their wall
// clock at job start, so a probe deadline that ties or exceeds those
// deadlines would never deliver the wrapped command (#3449).
const PROBE_RECOVERY_RESERVE_MS = 3000;
// Absolute deadline grace for paced input delivery. While input is
// paced-delivered the wall clock is paused (delivery time is excluded from
// the caller's execution budget), but the request itself must stay inside
// the hard tool-call budget the client advertised: the RPC transport only
// waits RPC_TIMEOUT_BUFFER_MS (5s, capabilities/rpcTimeouts.cjs) beyond the
// operation timeout before giving up. An absolute deadline stays armed from
// job start during pacing so delivery cannot outlast the client while the
// server keeps typing the command and holds the session lock (#3449). The
// grace must stay strictly below RPC_TIMEOUT_BUFFER_MS (5s): the rest of the
// transport buffer is needed for request/response transit and the bridge's
// interrupt + structured timeout reply, otherwise the client reports
// RPC_TIMEOUT at the same instant the paced deadline fires and the
// structured result is lost (#3449).
const PACED_INPUT_DEADLINE_GRACE_MS = 2000;
const promptRecoveryPendingPtys = new WeakSet();
function stripJobMarkerLines(text, marker) {
@@ -69,6 +95,7 @@ function startPtyJob(ptyStream, command, options) {
maxBufferedChars = 0,
normalizeFinalOutput = true,
enforceWallTimeout = false,
probeDeadlineMs = DEFAULT_PROBE_DEADLINE_MS,
} = options || {};
const marker = `__NCMCP_${Date.now().toString(36)}_${crypto.randomBytes(16).toString('hex')}__`;
@@ -183,8 +210,34 @@ function startPtyJob(ptyStream, command, options) {
// model can fall back to terminal_start). Default is off so existing
// foreground execution paths (Catty Agent) keep their inactivity-based
// timeout for long-running streaming commands.
function armWallTimeout() {
// The timer is paused while input is being paced-delivered (writeInput) and
// re-armed with the remaining wall time once delivery completes, so a short
// configured timeout cannot interrupt the probe/wrapper mid-typing (#3449).
let jobStartMs = Date.now();
// Wall-clock accounting excludes paced-input delivery time: the timer is
// paused in writeInput and the paused duration is subtracted from the
// elapsed time, so a short configured budget is preserved for the command
// itself instead of expiring during (or immediately after) delivery (#3449).
let wallPausedTotalMs = 0;
let wallPauseStartedAtMs = 0;
function pauseWallClock() {
if (enforceWallTimeout && maxBufferedChars <= 0 && !wallPauseStartedAtMs) {
wallPauseStartedAtMs = Date.now();
}
}
function resumeWallClock() {
if (!wallPauseStartedAtMs) return;
wallPausedTotalMs += Math.max(0, Date.now() - wallPauseStartedAtMs);
wallPauseStartedAtMs = 0;
}
function remainingWallMs() {
const pausedMs = wallPausedTotalMs
+ (wallPauseStartedAtMs ? Math.max(0, Date.now() - wallPauseStartedAtMs) : 0);
return timeoutMs - ((Date.now() - jobStartMs) - pausedMs);
}
function armWallTimeout(remainingMs = timeoutMs) {
if (!enforceWallTimeout || maxBufferedChars > 0) return;
clearTimeout(wallTimeoutId);
wallTimeoutId = setTimeout(() => {
if (finished) return;
if (pendingEnd) {
@@ -194,7 +247,21 @@ function startPtyJob(ptyStream, command, options) {
sendInterrupt();
const timeoutSec = Math.round(timeoutMs / 1000);
finish(foundStart ? output : preStartOutput, -1, `Command timed out (${timeoutSec}s)`);
}, timeoutMs);
}, Math.max(0, remainingMs));
}
// Absolute pacing deadline: measured from job start (not from the paused
// wall clock) so paced delivery cannot extend the request beyond the
// advertised budget plus the RPC transport's grace buffer. Delivery time
// still stays excluded from the execution budget: once delivery completes,
// completeInputDelivery re-arms a separate budget from the paused-excluded
// remaining wall time (#3449).
function pacedDeadlineRemainingMs() {
return jobStartMs + timeoutMs + PACED_INPUT_DEADLINE_GRACE_MS - Date.now();
}
function armPacedInputDeadline() {
if (!enforceWallTimeout || maxBufferedChars > 0) return;
armWallTimeout(pacedDeadlineRemainingMs());
}
// Bounded startup deadline: we always need a hard limit on how long we
@@ -209,9 +276,55 @@ function startPtyJob(ptyStream, command, options) {
// startup budget instead of counting against it.
const BG_STARTUP_TIMEOUT_MS = 30000;
function armStartupTimeout() {
const startupMs = maxBufferedChars > 0 ? BG_STARTUP_TIMEOUT_MS : timeoutMs;
const baseMs = maxBufferedChars > 0 ? BG_STARTUP_TIMEOUT_MS : timeoutMs;
// While waiting for the live shell probe reply, the startup budget is the
// bounded probe deadline: a probe whose _Q reply never arrives (silent
// shells, lost or mangled marker output) must not stall until the full
// command timeout with the command still undelivered (#3403, #3445).
// The deadline must fire strictly before the competing command timers —
// the output timer is armed with timeoutMs just before this one (same
// expiry loses on insertion order) and enforceWallTimeout callers start
// their wall clock at job start — so the silent probe still gets its
// recovery delivery instead of being finished as a timeout (#3449).
const probeBudgetMs = Math.max(
Math.floor(baseMs / 2),
baseMs - PROBE_RECOVERY_RESERVE_MS,
);
// Wall-clock callers (enforceWallTimeout) start their wall timer at job
// start, so the paced probe delivery already consumed part of the budget:
// cap the probe deadline by the remaining wall time minus the recovery
// reserve so the recovery delivery still fits before the wall deadline
// even with short supported timeouts (#3449). The remaining time excludes
// the paused paced-delivery duration so pacing cannot exhaust it.
const wallBudgetMs = enforceWallTimeout
? Math.max(1, remainingWallMs() - PROBE_RECOVERY_RESERVE_MS)
: Infinity;
const startupMs = probingShell
? Math.min(probeDeadlineMs, probeBudgetMs, wallBudgetMs)
: baseMs;
startupTimeoutId = setTimeout(() => {
if (finished || foundStart) return;
if (probingShell) {
// The probe reply never arrived. Clear the probe state and deliver
// the wrapped command anyway so silent/zero-output commands still
// reach the remote shell and return instead of stalling.
// Do NOT send the display reset (onProbeAborted) here: the preload
// treats _R as a permanent abort for the marker, which would stop
// the fallback wrapper's _I from re-arming echo suppression and
// leak the wrapper echo on width-wrapping terminals (#3449). The
// probe's own _I prime keeps suppression armed until the wrapper's
// _S arrives; finish() sends _R only when the command never starts.
probingShell = false;
// The probe may already have emitted its _P line (e.g. a POSIX login
// where the user entered a nested fish) even though the _Q completion
// marker was lost or mangled. Retain the detected kind so the fallback
// wrapper matches the live shell instead of assuming POSIX (#3449).
const partialKind = probeShellKindFromPartial(stripAnsi(probeOutput), marker);
probeOutput = "";
if (partialKind) resolvedShellKind = partialKind;
writeWrappedCommand();
return;
}
sendInterrupt();
const label = maxBufferedChars > 0 ? "Background job startup" : "Command startup";
finish(preStartOutput, -1, `${label} timed out — start marker never arrived`);
@@ -760,10 +873,19 @@ function startPtyJob(ptyStream, command, options) {
function completeInputDelivery(generation) {
// Input delivery is complete: only now does the startup deadline begin,
// so paced typing time never consumes the startup budget.
// so paced typing time never consumes the startup budget. The wall clock
// (enforceWallTimeout callers) is also paused during delivery and re-armed
// with the preserved remaining budget so pacing cannot consume it or
// interrupt the next delivery mid-typing with a short configured timeout
// (#3449). The remaining budget is measured with the paused time excluded:
// re-arming from raw elapsed time would leave a negative remainder after
// paced probe + wrapper delivery and interrupt the recovered command
// before it can execute.
if (!finished && !cancelRequested && generation === inputWriteGeneration) {
deliveringInput = false;
resumeWallClock();
if (!pendingEnd) armOutputTimeout();
armWallTimeout(remainingWallMs());
if (!foundStart) armStartupTimeout();
}
}
@@ -774,6 +896,14 @@ function startPtyJob(ptyStream, command, options) {
// probe to wrapper. Echo may be disabled while we are still typing.
clearStartupTimeout();
clearTimeout(timeoutId);
// Pause the wall clock while paced-typing so it cannot fire mid-delivery
// with short enforceWallTimeout budgets (#3449); completeInputDelivery
// re-arms it with the preserved remaining wall time. The absolute request
// deadline stays armed during pacing so a long delivered command cannot
// outlast the client's transport buffer while the session lock is held
// (#3449). armWallTimeout clears any previously armed budget first.
pauseWallClock();
armPacedInputDeadline();
deliveringInput = true;
const generation = inputWriteGeneration;
@@ -799,9 +929,28 @@ function startPtyJob(ptyStream, command, options) {
const writable = ptyStream.write(chunk);
if (!isCurrent()) return;
if (writable === false) {
// The wall clock is paused for the delivery: resume it while
// waiting for drain so the enforceWallTimeout hard deadline stays
// active — otherwise a blocked wrapper could retain the session
// lock for a fresh full timeoutMs beyond the advertised limit
// (#3449). Each drained wait re-pauses and the next write re-arms
// with the decreased remaining budget. The wait is also capped by
// the absolute pacing deadline so delivery (including drain
// waits) cannot outlast the client's transport buffer (#3449).
resumeWallClock();
armWallTimeout(Math.min(remainingWallMs(), pacedDeadlineRemainingMs()));
inputDrainListener = () => {
inputDrainListener = null;
clearTimeout(inputWriteTimer);
pauseWallClock();
// The wall clock is paused while delivery waits to resume, so
// the previously armed execution budget (measured at drain
// time) would be stale; replace it with the fresh absolute
// pacing deadline so delivery stays bounded while pacing or
// the drain wait is active. The execution budget is re-armed
// by the next backpressured write or by completeInputDelivery
// (#3449).
armPacedInputDeadline();
scheduleNext();
};
ptyStream.once("drain", inputDrainListener);
@@ -41,6 +41,36 @@ for (const background of [true, false]) {
});
}
test('paced delivery with enforceWallTimeout stays inside the absolute request deadline', async (t) => {
t.mock.timers.enable({ apis: ['setTimeout'] });
const pty = new EventEmitter();
const writes = [];
pty.write = (data) => writes.push(String(data));
// Long enough that paced delivery (128 chars / 30ms) exceeds the absolute
// deadline (timeoutMs + 5s transport grace) from job start.
const command = `echo ${'x'.repeat(40000)}`;
const job = startPtyJob(pty, command, {
shellKind: 'posix', probeLiveShell: true, timeoutMs: 500, enforceWallTimeout: true,
});
try {
const probeLength = 2 + buildLiveShellProbe(job.marker).length;
while (writes.join('').length < probeLength && !writes.includes('\x03')) t.mock.timers.tick(30);
pty.emit('data', `${job.marker}_P:sh\n${job.marker}_Q`);
const totalLength = probeLength + 2 + buildWrappedCommand(command, 'posix', job.marker, true).length;
// Delivery takes ~10s of mock time; the absolute deadline (~5.5s) must
// interrupt mid-pacing instead of letting delivery outlast the client.
while (!writes.includes('\x03') && writes.join('').length < totalLength) t.mock.timers.tick(30);
assert.ok(writes.includes('\x03'), 'paced delivery was not bounded by the absolute deadline');
assert.ok(writes.join('').length < totalLength, 'delivery continued past the absolute deadline');
const result = await job.resultPromise;
assert.equal(result.ok, false);
assert.match(result.error, /timed out/);
} finally {
pty.emit('close');
t.mock.timers.reset();
}
});
test('completed delivery still has a bounded wait for a missing probe reply', async (t) => {
t.mock.timers.enable({ apis: ['setTimeout'] });
const pty = new EventEmitter();
@@ -56,9 +86,13 @@ test('completed delivery still has a bounded wait for a missing probe reply', as
pty.emit('data', 'unrelated output\n');
t.mock.timers.tick(100);
}
// The probe deadline first clears the probe state and delivers the command
// anyway (#3403); after the paced wrapper delivery the re-armed deadline
// then fails the job, so advance until the interrupt/finish happens.
while (!writes.includes('\x03')) t.mock.timers.tick(30);
const result = await job.resultPromise;
assert.match(result.error, /Command startup timed out/);
assert.ok(writes.includes('\x03'));
assert.match(result.error, /timed out/);
assert.ok(writes.join('').includes('echo never'), 'a missing probe reply must still deliver the command');
});
for (const cancel of [false, true]) {