ca913c76ea
* spawn: kill process group + heartbeat subagent activity two compounding bugs produced zombie agent runs that stalled until the GitHub-Actions job-level timeout (observed on PR #622, run 25577068620). 1. SIGKILL hit the wrong process. node_modules/opencode-ai/bin/opencode is a Node shim that spawnSyncs the native opencode-<plat>-<arch> binary with stdio:"inherit". our spawn() ran without detached, so child.kill("SIGKILL") killed only the shim. the native binary was reparented to PID 1, kept holding our stdout pipe via inherited fds, and child.on("close") never fired — leaving the agent promise pending past the 5min outer safety-net timer ("agent still pending 5min after inner activity kill — forcing exit") and the grandchild running until the runner timed out. fix: SpawnOptions gains killGroup; when set, we spawn detached and route all kill paths (timeout, activity timeout, ctrl-c) through process.kill(-pid, signal). opencode + claude opt in. 2. inner activity timer false-fired during long task subagents. opencode's `task` tool encapsulates subagent execution in-process — subagent-internal events don't reach the parent NDJSON stream — so the parent looked idle for the full subagent duration even when real work was happening, and the 5min DEFAULT_ACTIVITY_TIMEOUT_MS would fire mid-subagent. fix: SpawnOptions gains externalActivitySource; the timer fires on min(local stdout idle, external idle). opencode passes getIdleMs() from the global activity tracker and runs a 30s heartbeat (markActivity()) while at least one task dispatch is in flight. action/utils/subprocess.test.ts covers both: a bash+sleep grandchild that proves close fires <10s with killGroup, and externalActivitySource keeping the timer armed during 8s of stdout silence. * opencode: suspend activity timer instead of heartbeat during subagent runs addresses review on prior commit: replace the 30s markActivity() heartbeat with a boolean isPausedExternally predicate keyed off opencode's existing taskDispatchByCallID + pendingTaskDispatches. no fake activity, no race window between a 30s tick and a subagent that finishes between ticks. while the predicate returns true, spawn's activity check skips the kill decision *and* advances lastActivityTime so a clean unpause can't fire on a stale baseline. tests cover both the suspended case (8s of stdout silence + activityTimeout=1s but paused → process exits cleanly) and the resume case (paused for 500ms then unpaused → 30s sleep gets killed by activity timeout as normal).
358 lines
13 KiB
TypeScript
358 lines
13 KiB
TypeScript
import { type ChildProcess, spawn as nodeSpawn } from "node:child_process";
|
|
import { performance } from "node:perf_hooks";
|
|
import { DEFAULT_ACTIVITY_CHECK_INTERVAL_MS, DEFAULT_ACTIVITY_TIMEOUT_MS } from "./activity.ts";
|
|
import { log } from "./cli.ts";
|
|
import { onExitSignal } from "./exitHandler.ts";
|
|
|
|
export type TrackChildOptions = {
|
|
child: ChildProcess;
|
|
// if true, kill the entire process group (requires detached spawn)
|
|
killGroup?: boolean;
|
|
};
|
|
|
|
// sentinel codes for timeout rejections — callers (e.g. lifecycle.ts) use
|
|
// these to distinguish timeouts from other errors without string-matching
|
|
// on the error message, which is fragile to rewording.
|
|
export const SPAWN_TIMEOUT_CODE = "E_SPAWN_TIMEOUT";
|
|
export const SPAWN_ACTIVITY_TIMEOUT_CODE = "E_SPAWN_ACTIVITY_TIMEOUT";
|
|
|
|
export class SpawnTimeoutError extends Error {
|
|
readonly code: typeof SPAWN_TIMEOUT_CODE | typeof SPAWN_ACTIVITY_TIMEOUT_CODE;
|
|
constructor(
|
|
message: string,
|
|
code: typeof SPAWN_TIMEOUT_CODE | typeof SPAWN_ACTIVITY_TIMEOUT_CODE
|
|
) {
|
|
super(message);
|
|
this.name = "SpawnTimeoutError";
|
|
this.code = code;
|
|
}
|
|
}
|
|
|
|
// track all spawned child processes for cleanup on Ctrl+C
|
|
const activeChildren = new Map<ChildProcess, boolean>();
|
|
|
|
// signal handler override (used by test runner for graceful shutdown)
|
|
export type SignalHandler = (signal: NodeJS.Signals) => void;
|
|
let externalSignalHandler: SignalHandler | null = null;
|
|
|
|
// track a child process for cleanup on Ctrl+C
|
|
export function trackChild(options: TrackChildOptions): void {
|
|
// the signal handler cleans up all tracked children
|
|
// so we only have to install it once some child gets tracked
|
|
installSignalHandler();
|
|
activeChildren.set(options.child, options.killGroup ?? false);
|
|
}
|
|
|
|
// untrack a child process
|
|
export function untrackChild(child: ChildProcess): void {
|
|
activeChildren.delete(child);
|
|
}
|
|
|
|
// allow callers to override default signal handling
|
|
export function setSignalHandler(handler: SignalHandler | null): void {
|
|
externalSignalHandler = handler;
|
|
}
|
|
|
|
// kill all tracked children without exiting
|
|
export function killTrackedChildren() {
|
|
for (const entry of activeChildren) {
|
|
const child = entry[0];
|
|
const killGroup = entry[1];
|
|
if (killGroup && child.pid) {
|
|
try {
|
|
process.kill(-child.pid, "SIGKILL");
|
|
continue;
|
|
} catch {
|
|
// fall through to direct kill
|
|
}
|
|
}
|
|
child.kill("SIGKILL");
|
|
}
|
|
}
|
|
|
|
// install signal handlers once (call early in process lifecycle)
|
|
let handlersInstalled = false;
|
|
function installSignalHandler(): void {
|
|
if (handlersInstalled) return;
|
|
handlersInstalled = true;
|
|
onExitSignal((signal) => {
|
|
if (externalSignalHandler) {
|
|
externalSignalHandler(signal);
|
|
return;
|
|
}
|
|
const count = activeChildren.size;
|
|
if (count > 0) {
|
|
log.info(`» received ${signal}, killing ${count} subprocess(es)...`);
|
|
}
|
|
killTrackedChildren();
|
|
});
|
|
}
|
|
|
|
export interface SpawnOptions {
|
|
cmd: string;
|
|
args: string[];
|
|
env?: NodeJS.ProcessEnv;
|
|
input?: string;
|
|
timeout?: number;
|
|
// activity timeout: kill process if no stdout for this many ms (default: 30s, 0 to disable).
|
|
// only stdout resets the timer — stderr (e.g. provider error retries) does not count as progress.
|
|
activityTimeout?: number;
|
|
// fired synchronously when the activity timeout kills the process. used by
|
|
// callers (main.ts) to tear down shared resources like the MCP HTTP server
|
|
// so that lingering SSE reconnects don't keep the outer activity timer
|
|
// alive after the subprocess is already dead.
|
|
onActivityTimeout?: (() => void) | undefined;
|
|
cwd?: string;
|
|
stdio?: ("pipe" | "ignore" | "inherit")[];
|
|
onStdout?: (chunk: string) => void;
|
|
onStderr?: (chunk: string) => void;
|
|
// when true, spawn the child detached (its own process group) and route all
|
|
// kill paths (timeout, activity timeout, ctrl-c) through `process.kill(-pid, ...)`
|
|
// so signals reach grandchildren too. critical for binaries that fork through
|
|
// a shim (e.g. node_modules/opencode-ai/bin/opencode is a Node shim that
|
|
// spawnSync's the native binary; without killGroup, SIGKILL only hits the
|
|
// shim and the native binary is reparented to PID 1, holds our stdout pipe
|
|
// open, keeps emitting NDJSON, and `child.on("close")` never fires —
|
|
// producing zombie runs that hang until the GitHub Actions job timeout).
|
|
killGroup?: boolean;
|
|
// optional pause predicate consulted on every activity check. when it
|
|
// returns true the activity timer skips the kill decision *and* resets
|
|
// its idle baseline so a clean unpause can't immediately fire on a stale
|
|
// lastActivityTime. opencode uses this because its `task` tool encapsulates
|
|
// subagent execution in-process — subagent-internal events don't surface
|
|
// on the parent's NDJSON stream, so the local stdout-only signal would
|
|
// falsely fire mid-subagent. preferred over fake-activity heartbeats
|
|
// because there's no race window between a heartbeat tick and a subagent
|
|
// that finishes between ticks.
|
|
isPausedExternally?: () => boolean;
|
|
}
|
|
|
|
export interface SpawnResult {
|
|
stdout: string;
|
|
stderr: string;
|
|
exitCode: number;
|
|
durationMs: number;
|
|
}
|
|
|
|
/**
|
|
* Spawn a subprocess with streaming callbacks and buffered results
|
|
*/
|
|
export async function spawn(options: SpawnOptions): Promise<SpawnResult> {
|
|
const activityTimeoutMs = options.activityTimeout ?? DEFAULT_ACTIVITY_TIMEOUT_MS;
|
|
|
|
installSignalHandler();
|
|
|
|
const startTime = performance.now();
|
|
let stdoutBuffer = "";
|
|
let stderrBuffer = "";
|
|
|
|
const killGroup = options.killGroup ?? false;
|
|
|
|
return new Promise((resolve, reject) => {
|
|
// security: caller must provide complete env object, not merged with process.env
|
|
const child = nodeSpawn(options.cmd, options.args, {
|
|
env: options.env || {
|
|
PATH: process.env.PATH || "",
|
|
HOME: process.env.HOME || "",
|
|
},
|
|
stdio: options.stdio || ["pipe", "pipe", "pipe"],
|
|
cwd: options.cwd || process.cwd(),
|
|
detached: killGroup,
|
|
});
|
|
|
|
// sends `signal` to the entire process group when killGroup is set, so
|
|
// grandchildren (e.g. the native opencode binary spawned by the
|
|
// opencode-ai Node shim) die with the parent. falls back to a direct
|
|
// child kill if the process-group send fails (common when the child
|
|
// already exited or was never made a process group leader).
|
|
const killSelf = (signal: NodeJS.Signals): void => {
|
|
if (killGroup && child.pid) {
|
|
try {
|
|
process.kill(-child.pid, signal);
|
|
return;
|
|
} catch {
|
|
// fall through to direct kill
|
|
}
|
|
}
|
|
child.kill(signal);
|
|
};
|
|
|
|
// track child for cleanup on Ctrl+C
|
|
trackChild({ child, killGroup });
|
|
|
|
let timeoutId: NodeJS.Timeout | undefined;
|
|
let sigkillEscalatorId: NodeJS.Timeout | undefined;
|
|
let activityCheckIntervalId: NodeJS.Timeout | undefined;
|
|
let isTimedOut = false;
|
|
let isActivityTimedOut = false;
|
|
let lastActivityTime = performance.now();
|
|
// idle-ms snapshot taken at the moment the activity timer decides to kill.
|
|
// we reuse it when composing the SpawnTimeoutError so a final stdout chunk
|
|
// that races with `close` (and resets lastActivityTime via updateActivity)
|
|
// can't make the error message contradict the "no output for Ns" log line.
|
|
let killedAtIdleMs: number | undefined;
|
|
|
|
// overall timeout
|
|
if (options.timeout) {
|
|
timeoutId = setTimeout(() => {
|
|
isTimedOut = true;
|
|
killSelf("SIGTERM");
|
|
|
|
// track the escalator so a graceful SIGTERM response (close fires
|
|
// before the 5s elapses) can clear it. without capture, this timer
|
|
// was orphaned in the event loop and kept node alive for up to 5s
|
|
// past a timed-out subprocess's clean exit.
|
|
sigkillEscalatorId = setTimeout(() => {
|
|
if (!child.killed) {
|
|
killSelf("SIGKILL");
|
|
}
|
|
}, 5000);
|
|
}, options.timeout);
|
|
}
|
|
|
|
// activity timeout: kill if no output for too long
|
|
if (activityTimeoutMs > 0) {
|
|
log.debug(
|
|
`spawn activity timer: pid=${child.pid} cmd=${options.cmd} timeout=${activityTimeoutMs}ms`
|
|
);
|
|
activityCheckIntervalId = setInterval(() => {
|
|
// when an external pause predicate says we're suspended (e.g.
|
|
// opencode in a long-running task subagent whose internal events
|
|
// don't surface on stdout), advance lastActivityTime to "now" so a
|
|
// clean unpause doesn't immediately fire on a stale baseline, and
|
|
// skip the kill decision for this tick.
|
|
if (options.isPausedExternally?.()) {
|
|
lastActivityTime = performance.now();
|
|
log.debug(`spawn activity check: pid=${child.pid} paused externally`);
|
|
return;
|
|
}
|
|
const idleMs = performance.now() - lastActivityTime;
|
|
log.debug(
|
|
`spawn activity check: pid=${child.pid} idle=${Math.round(idleMs)}ms / ${activityTimeoutMs}ms`
|
|
);
|
|
if (idleMs > activityTimeoutMs) {
|
|
isActivityTimedOut = true;
|
|
killedAtIdleMs = idleMs;
|
|
const idleSec = Math.round(idleMs / 1000);
|
|
log.info(
|
|
`no output for ${idleSec}s from pid=${child.pid} (${options.cmd}), killing process${killGroup ? " group" : ""}`
|
|
);
|
|
killSelf("SIGKILL");
|
|
clearInterval(activityCheckIntervalId);
|
|
try {
|
|
options.onActivityTimeout?.();
|
|
} catch (err) {
|
|
log.debug(
|
|
`spawn onActivityTimeout handler threw: ${err instanceof Error ? err.message : String(err)}`
|
|
);
|
|
}
|
|
}
|
|
}, DEFAULT_ACTIVITY_CHECK_INTERVAL_MS);
|
|
}
|
|
|
|
function updateActivity(): void {
|
|
lastActivityTime = performance.now();
|
|
}
|
|
|
|
if (child.stdout) {
|
|
child.stdout.on("data", (data: Buffer) => {
|
|
updateActivity();
|
|
const chunk = data.toString();
|
|
stdoutBuffer += chunk;
|
|
options.onStdout?.(chunk);
|
|
});
|
|
}
|
|
|
|
if (child.stderr) {
|
|
child.stderr.on("data", (data: Buffer) => {
|
|
const chunk = data.toString();
|
|
stderrBuffer += chunk;
|
|
options.onStderr?.(chunk);
|
|
});
|
|
}
|
|
|
|
child.on("close", (exitCode, signal) => {
|
|
const durationMs = performance.now() - startTime;
|
|
|
|
untrackChild(child);
|
|
if (timeoutId) clearTimeout(timeoutId);
|
|
if (sigkillEscalatorId) clearTimeout(sigkillEscalatorId);
|
|
if (activityCheckIntervalId) clearInterval(activityCheckIntervalId);
|
|
|
|
if (isTimedOut) {
|
|
reject(
|
|
new SpawnTimeoutError(`process timed out after ${options.timeout}ms`, SPAWN_TIMEOUT_CODE)
|
|
);
|
|
return;
|
|
}
|
|
|
|
if (isActivityTimedOut) {
|
|
// prefer the idle-ms captured when the kill fired (killedAtIdleMs).
|
|
// recomputing from lastActivityTime here would be wrong if the child
|
|
// emitted one final stdout chunk between SIGKILL and close — the
|
|
// chunk's updateActivity() would reset lastActivityTime and the error
|
|
// would report near-zero idle, contradicting the kill-site log line.
|
|
const idleMs = killedAtIdleMs ?? performance.now() - lastActivityTime;
|
|
const idleSec = Math.round(idleMs / 1000);
|
|
reject(
|
|
new SpawnTimeoutError(
|
|
`activity timeout: no output for ${idleSec}s`,
|
|
SPAWN_ACTIVITY_TIMEOUT_CODE
|
|
)
|
|
);
|
|
return;
|
|
}
|
|
|
|
// when a child is killed by signal (OOM, segfault, external SIGTERM),
|
|
// node delivers (code=null, signal=<name>). without this branch,
|
|
// `exitCode || 0` coerced null to 0 and lifecycle hooks silently
|
|
// appeared to succeed when they'd actually been killed — caller
|
|
// checked `result.exitCode !== 0` and moved on.
|
|
let resolvedExitCode = exitCode ?? 0;
|
|
let resolvedStderr = stderrBuffer;
|
|
if (exitCode === null && signal) {
|
|
const killMsg = `[spawn] ${options.cmd}: killed by signal ${signal}`;
|
|
resolvedStderr = resolvedStderr ? `${resolvedStderr}\n${killMsg}` : killMsg;
|
|
resolvedExitCode = 1;
|
|
}
|
|
|
|
resolve({
|
|
stdout: stdoutBuffer,
|
|
stderr: resolvedStderr,
|
|
exitCode: resolvedExitCode,
|
|
durationMs,
|
|
});
|
|
});
|
|
|
|
child.on("error", (error) => {
|
|
const durationMs = performance.now() - startTime;
|
|
|
|
untrackChild(child);
|
|
if (timeoutId) clearTimeout(timeoutId);
|
|
if (sigkillEscalatorId) clearTimeout(sigkillEscalatorId);
|
|
if (activityCheckIntervalId) clearInterval(activityCheckIntervalId);
|
|
|
|
// surface the spawn error in stderr so callers (e.g. lifecycle hook
|
|
// warnings) don't just see "exit code 1, output: (empty)" when the
|
|
// command was misspelled, missing, or unexecutable. without this a
|
|
// user with a bad postCheckout script got an opaque failure, retried
|
|
// per the guidance, and hit the same wall every run.
|
|
const errMsg = `[spawn] ${options.cmd}: ${error.message}`;
|
|
console.error(errMsg);
|
|
stderrBuffer = stderrBuffer ? `${stderrBuffer}\n${errMsg}` : errMsg;
|
|
|
|
resolve({
|
|
stdout: stdoutBuffer,
|
|
stderr: stderrBuffer,
|
|
exitCode: 1,
|
|
durationMs,
|
|
});
|
|
});
|
|
|
|
if (options.input && child.stdin && options.stdio?.[0] !== "ignore") {
|
|
child.stdin.write(options.input);
|
|
child.stdin.end();
|
|
}
|
|
});
|
|
}
|