Files
shockbot/utils/subprocess.ts
T
Colin McDonnell 88f170e19a fix: 7 log-audit / run-audit findings (mega-PR) (#769)
* fix(#765): silence Clerk 400 (revoked OAuth) noise from getTokenForClerkId

Branch on isClerkAPIResponseError + status<500 so the well-understood
revoked-token redirect doesn't emit a level=error line in Better Stack
on every request. Vercel maps console.warn -> error for non-streaming
routes, so a downgrade to log.warn wouldn't help; only the unexpected
shape (5xx, network) is worth surfacing.

* fix(#742): stop logging input verbatim from yes.op retry-failure paths

GitHub OAuth user tokens (ghu_...) were leaking to Better Stack on every
yes.op retry-failure for any utils/github/get* helper that takes a token
field — 38 leaks/7d in the most recent audit window. The leak path is
console.log inside the yes package (its own log shim, not utils/log.ts).

Drop input from the four log sites + the cache-key-derivation throw site.
key (SHA-1 of input) is sufficient for retry correlation; error already
carries request URL + status. Defense-in-depth comment so future
contributors don't re-add the field.

Operational follow-up (separate task): inventory ghu_... strings in
Better Stack ingested in the last 90d, revoke matching Clerk grants,
scrub cold-tier S3, rotate the BS source token.

* fix(#759): handle GraphqlResponseError "Could not resolve to a node" as 404

When the stored planCommentNodeId references a comment that's been
deleted on GitHub, octokit.graphql throws GraphqlResponseError before
the existing `node === null` 404 branch is reached. Add a narrow
isGraphqlNodeNotFound predicate in utils/errors.ts and a new catch
branch in the plan-comment route. The action treats 404 as "no prior
plan comment" and creates a fresh one, so behavior matches existing
contract.

* fix(#747): convert webhook GraphQL rate-limit 5xx into a Result<T> sentinel + 200 ack

When GitHub's GraphQL responds with "API rate limit exceeded for
installation ID N", _getReviewCommentsWithReplies threw, propagated
through the bare yes.op wrapper (no rate-limit bail), out of the bare
await in handleWebhook, and crashed /api/webhook/github with 500 — 77
webhook 500s/24h on the most recent audit window. GitHub redelivery
plus R2 dedup also silently masked the legitimate handler from
re-running once the rate-limit window cleared.

Mirror the #658 / _getRepository pattern: detect GraphqlResponseError
matching /rate limit (already )?exceeded/i, log.warn with the
x-ratelimit-reset value (and [Installation N] prefix when available),
return failure(...) with status 429. Webhook handler short-circuits
the case with 200 + log.info so GitHub stops the redelivery storm
against an exhausted budget, and the trigger page surfaces a clean
ThrowClientError. Document the new pattern as a Tier 2 false-positive
in wiki/log-audit.md so the next audit cron doesn't re-flag it.

Note that returning [] silently (the issue's first suggestion) would
have dropped @pullfrog mentions inline in review comments and
dispatched an agent run that re-rate-limits — skip-the-whole-case is
the correct semantics. Co-vulnerable getPullRequest / getWorkflow
have zero occurrences in this window; per #737 policy, defer until
they show up.

NOTE: this commit and the bracket of touched files revert as a unit —
the Result<T> shape change in getReviewCommentsWithReplies is
breaking; partial revert breaks the type chain.

* fix(#766): fold stderr+stdout into shell.ts errors + carve out merge-base --is-ancestor

action/utils/shell.ts dropped stdout when constructing failure messages
($\{stderr || "Unknown error"\}), so git subcommands that write
context-bearing diagnostics to stdout (merge conflicts, cherry-pick
rejections, diff --exit-code, ls-files --error-unmatch) surfaced as
"Command failed with exit code 1: Unknown error" through
mcp__pullfrog__git. The agent burned an extra MCP round-trip calling
git status to recover.

Fold stderr + stdout into the thrown error message (stderr first,
stdout fallback) so the agent always sees the real diagnostic. Plus
a narrow carve-out for `git merge-base --is-ancestor` in
action/mcp/git.ts: that subcommand uses exit code as data (0=ancestor,
1=not-an-ancestor, >1=error), so return { success: true, isAncestor }
instead of throwing on exit 1.

No caller in action/ string-matches on the old error format
(verified). diff --exit-code and ls-files --error-unmatch are not
carved out — both are zero-occurrence in the May audit window, and
the stderr+stdout fold renders their output usefully anyway.

* fix(#739): point customers at the actual fix when permissions: id-token: write is missing

When a customer workflow runs in GitHub Actions but lacks
permissions: id-token: write, ACTIONS_ID_TOKEN_REQUEST_URL/_TOKEN
aren't injected, isOIDCAvailable() is false, and acquireNewToken
falls through to the local-dev-only acquireTokenViaGitHubApp path,
which throws "GITHUB_APP_ID and GITHUB_PRIVATE_KEY must be set" —
pointing at a self-hosted-app fix that doesn't apply. One affected
customer burned 13 dispatches in 24h on this misleading error.

Detect (GITHUB_ACTIONS=true) AND (no OIDC env vars) inside
acquireNewToken before falling through to the local-dev branch, and
throw an actionable message naming the missing permissions block,
the exact YAML, and the docs anchor. The error surfaces via
##[error]action failed: ... in the workflow log (the only customer
surface available before main()'s inner try opens). Local-dev path
keeps the existing GITHUB_APP_ID message.

* fix(#760): suspend activity watchdog across in-flight tool calls

mcp__pullfrog__checkout_pr was hard-failing 6/24h on SenecaLabs/senecaWeb
because git fetch+deepen on a large monorepo can take 4-5 min, the
agent's stdout pipe goes silent the entire time (FastMCP is in-process
HTTP, but Claude/opencode CLIs await the synchronous tools/call
response), and both the spawn-level activity timer (300s in
subprocess.ts) and the process-level activity monitor (300s in
activity.ts) fire and kill the run.

Re-introduce the bracket pattern that PR #634 removed: bracket
suspendActivity()/resumeActivity() around tool_use -> tool_result in
both agent harnesses, plumb isPausedExternally into spawn() so both
timers suspend in lockstep. Bounded by MAX_TOOL_CALL_SUSPENSION_MS
(15 min auto-resume) plus the outer 1h agent timeout — neither
zombie-run avenue from #12 is reopened (subprocess.close still
resolves on death; outer timeout is suspend-agnostic; suspends gated
on explicit paired CLI events, not internal noise).

opencode tool_use handler: gate suspendActivity() on non-terminal
status (running/pending) so the bus_event re-dispatch path at line
915 — which only fires for completed/error subagent parts and never
emits a paired tool_result — doesn't latch the watchdog into
suspension until the 15min ceiling.

Add a heuristic:activity-watchdog-ceiling classifier to
scripts/analyze-logs.ts so a tool that genuinely hangs past
MAX_TOOL_CALL_SUSPENSION_MS surfaces in run-audit instead of being
bucketed into failure:unknown.

NOTE: this commit and the bracket of touched files revert as a unit
— activity.ts, subprocess.ts, and the two harnesses must move
together or the bracketing breaks.

* refactor(#747): swap Result<T> for InstallationRateLimitError typed throw

The Result<T> shape from 3ebf6c4c was cargo-culted from the #658
_getRepository pattern, but _getReviewCommentsWithReplies has only one
expected-error case (installation rate-limit) and two callers — Result
imposes branching on the trigger-page caller that never cared about
the rate-limit case specifically. A typed error class is lighter (~10
LoC vs ~33) and matches the actual need:

- new InstallationRateLimitError(resetAt) thrown from
  _getReviewCommentsWithReplies; rate-limit log.warn unchanged.
- handleWebhook catches it and breaks with log.info (unchanged
  semantics: 200 ack, no redelivery storm).
- trigger page reverts to direct array access; any failure propagates
  to the page error boundary (the pre-#747-commit shape).
- log-audit.md wording updated to match.
2026-05-19 18:40:53 +00:00

450 lines
17 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();
});
}
/**
* Controls what the wrapper retains in memory across the child's lifetime
* for the post-hoc `SpawnResult.stdout` / `SpawnResult.stderr` snapshots.
*
* Streaming callbacks (`onStdout` / `onStderr`) fire regardless — `retain`
* only governs the buffered snapshot returned in `SpawnResult`.
*
* - `"tail"` (default): keep the last `maxRetainedBytes` UTF-16 code units
* of each stream. Once the cap is exceeded, oldest bytes are sliced off
* and the result is prefixed with a `... [N MiB truncated] ...` sentinel.
* Right default for short-lived commands whose failure mode is in their
* final output (git errors, install failures, hook scripts).
* - `"none"`: skip the buffer entirely. `SpawnResult.stdout` / `.stderr`
* are empty strings. Use this for long-lived streaming agents that already
* drain via `onStdout` / `onStderr` and never read the buffered snapshot.
*
* Default cap is 8 MiB — well below V8's ~1 GiB `kMaxLength` so `+= chunk`
* can never throw `RangeError: Invalid string length`.
*/
export type RetainMode = "tail" | "none";
export const DEFAULT_MAX_RETAINED_BYTES = 8 * 1024 * 1024;
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;
// optional pause predicate consulted on every activity check. when true,
// the spawn watchdog (a) skips its kill decision, (b) advances
// `lastActivityTime` so a stale baseline can't fire on resume. used by
// agent harnesses (claude.ts / opencode.ts) to suspend the watchdog
// across long synchronous MCP `tools/call` round-trips that the child's
// stdout pipe can't see (issue #760). bounded externally by
// `MAX_TOOL_CALL_SUSPENSION_MS` plus the outer agent timeout.
isPausedExternally?: () => boolean;
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;
retain?: RetainMode;
maxRetainedBytes?: number;
}
/**
* Bounded string accumulator that keeps the tail of appended chunks.
* Once the cap is exceeded, oldest bytes are sliced off and `toString()`
* prefixes the survivors with a sentinel describing the elided byte count.
*
* Exported because long-lived agent runtimes (opencode, claude) also
* accumulate per-run narration strings independently of the spawn wrapper
* and need the same protection against V8's `kMaxLength`.
*/
export class TailBuffer {
// explicit field declarations rather than constructor parameter properties:
// node's strip-only TS loader (used by action/test/run.ts in CI) rejects
// `constructor(private readonly cap: number)` with ERR_UNSUPPORTED_TYPESCRIPT_SYNTAX.
private readonly cap: number;
private buffer = "";
private truncatedBytes = 0;
constructor(cap: number) {
this.cap = cap;
}
append(chunk: string): void {
if (this.cap <= 0) return;
this.buffer += chunk;
if (this.buffer.length > this.cap) {
const drop = this.buffer.length - this.cap;
this.truncatedBytes += drop;
this.buffer = this.buffer.slice(drop);
}
}
toString(): string {
if (this.truncatedBytes === 0) return this.buffer;
const mib = (this.truncatedBytes / 1024 / 1024).toFixed(1);
return `... [${mib} MiB truncated by retain:tail cap] ...\n${this.buffer}`;
}
}
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();
// capped accumulators — unbounded `+= chunk` previously crashed the wrapper
// with `RangeError: Invalid string length` once V8's ~1 GiB kMaxLength was
// breached on long-lived agent subprocesses (e.g. multi-lens opencode
// Reviews on large monorepos). retain:"none" skips the buffer entirely
// for callers that already drain via onStdout/onStderr.
const retain: RetainMode = options.retain ?? "tail";
const cap = options.maxRetainedBytes ?? DEFAULT_MAX_RETAINED_BYTES;
const stdoutBuffer = retain === "none" ? null : new TailBuffer(cap);
const stderrBuffer = retain === "none" ? null : new TailBuffer(cap);
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(() => {
if (options.isPausedExternally?.()) {
// reset the baseline so a clean resume can't immediately fire on
// the pre-pause idle window.
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();
}
// wrap handlers in try/catch as defense in depth for synchronous throws
// inside the listener body. the historical `+= chunk` RangeError was such
// a throw — synchronous and fatal under node's default uncaught-exception
// policy. with the TailBuffer cap in place the wrapper-side `append` can
// no longer throw, but the catch keeps protecting against any future
// synchronous regression in this path.
//
// note: this does NOT catch rejections from async user callbacks —
// `options.onStdout?.(chunk)` returns a Promise in the agent callers
// (claude.ts, opencode.ts) and a throw inside an async callback surfaces
// as an unhandled Promise rejection, not a synchronous exception. agent
// callers handle their own NDJSON-parse failures internally; the
// synchronous protection here is what matters for the RangeError class
// of bugs (issue #680).
if (child.stdout) {
child.stdout.on("data", (data: Buffer) => {
try {
updateActivity();
const chunk = data.toString();
stdoutBuffer?.append(chunk);
options.onStdout?.(chunk);
} catch (err) {
log.debug(
`spawn stdout handler threw: ${err instanceof Error ? err.message : String(err)}`
);
}
});
}
if (child.stderr) {
child.stderr.on("data", (data: Buffer) => {
try {
const chunk = data.toString();
stderrBuffer?.append(chunk);
options.onStderr?.(chunk);
} catch (err) {
log.debug(
`spawn stderr handler threw: ${err instanceof Error ? err.message : String(err)}`
);
}
});
}
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?.toString() ?? "";
if (exitCode === null && signal) {
const killMsg = `[spawn] ${options.cmd}: killed by signal ${signal}`;
resolvedStderr = resolvedStderr ? `${resolvedStderr}\n${killMsg}` : killMsg;
resolvedExitCode = 1;
}
resolve({
stdout: stdoutBuffer?.toString() ?? "",
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);
const existingStderr = stderrBuffer?.toString() ?? "";
const finalStderr = existingStderr ? `${existingStderr}\n${errMsg}` : errMsg;
resolve({
stdout: stdoutBuffer?.toString() ?? "",
stderr: finalStderr,
exitCode: 1,
durationMs,
});
});
if (options.input && child.stdin && options.stdio?.[0] !== "ignore") {
child.stdin.write(options.input);
child.stdin.end();
}
});
}