88f170e19a
* 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.
252 lines
8.7 KiB
TypeScript
252 lines
8.7 KiB
TypeScript
import { performance } from "node:perf_hooks";
|
|
import { log } from "./log.ts";
|
|
|
|
function isMonitorDebugEnabled(): boolean {
|
|
return (
|
|
process.env.ACTIONS_STEP_DEBUG === "true" ||
|
|
process.env.RUNNER_DEBUG === "1" ||
|
|
process.env.LOG_LEVEL === "debug"
|
|
);
|
|
}
|
|
|
|
export const DEFAULT_ACTIVITY_TIMEOUT_MS = 300_000;
|
|
export const DEFAULT_ACTIVITY_CHECK_INTERVAL_MS = 5_000;
|
|
|
|
/**
|
|
* chunks whose every non-empty line matches one of these patterns do not
|
|
* count as agent activity. mcp-proxy SSE reconnects and provider-error
|
|
* retries happen on their own schedule and were keeping the outer activity
|
|
* timer alive long after the agent subprocess had been killed for inactivity,
|
|
* producing multi-hour zombie runs.
|
|
*
|
|
* both patterns anchor to the start of the (optionally debug-timestamped)
|
|
* log line so they don't accidentally match agent output that happens to
|
|
* mention "[mcp-proxy]" or "provider error detected" in analysis text.
|
|
*/
|
|
const DEBUG_TS_PREFIX = /^(?:\[\d{4}-\d{2}-\d{2}T[^\]]+\]\s+)?/.source;
|
|
// our own internal monitors (this file's bypass + subprocess.ts's spawn
|
|
// activity timer) emit high-frequency diagnostic logs when debug logging is
|
|
// enabled. in the past those lines reached the wrapped process.stdout.write,
|
|
// missed the noise check, and marked activity every interval — which in
|
|
// debug-enabled runs kept the outer timer alive after the agent subprocess
|
|
// was already dead, re-creating the #12 zombie-run bug. the `(?:spawn|process)
|
|
// activity ` patterns below explicitly filter our own diagnostic lines in both
|
|
// local-debug (`[DEBUG] …`) and GH-runner-debug (`::debug::…`) formats.
|
|
export const ACTIVITY_NOISE_PATTERNS: readonly RegExp[] = [
|
|
new RegExp(`${DEBUG_TS_PREFIX}\\[mcp-proxy\\]`),
|
|
new RegExp(`${DEBUG_TS_PREFIX}» provider error detected`),
|
|
new RegExp(`${DEBUG_TS_PREFIX}\\[DEBUG\\]\\s+(?:spawn|process) activity `),
|
|
/^::debug::(?:spawn|process) activity /,
|
|
];
|
|
|
|
export function isActivityNoise(chunk: string | Uint8Array): boolean {
|
|
const text = typeof chunk === "string" ? chunk : Buffer.from(chunk).toString("utf8");
|
|
if (!text.trim()) return true;
|
|
return text.split("\n").every((line) => {
|
|
const trimmed = line.trim();
|
|
if (!trimmed) return true;
|
|
return ACTIVITY_NOISE_PATTERNS.some((pattern) => pattern.test(trimmed));
|
|
});
|
|
}
|
|
|
|
type ActivityTimeoutContext = {
|
|
timeoutMs: number;
|
|
checkIntervalMs: number;
|
|
};
|
|
|
|
export type ActivityTimeout = {
|
|
promise: Promise<never>;
|
|
stop: () => void;
|
|
/** force the timeout to reject immediately with a custom reason */
|
|
forceReject: (reason: string) => void;
|
|
};
|
|
|
|
type OutputMonitorContext = {
|
|
timeoutMs: number;
|
|
checkIntervalMs: number;
|
|
onTimeout: (idleMs: number) => void;
|
|
};
|
|
|
|
type OutputMonitor = {
|
|
stop: () => void;
|
|
};
|
|
|
|
type WriteCallback = (error?: Error | null) => void;
|
|
type WriteFunction = {
|
|
(chunk: string | Uint8Array, cb?: WriteCallback): boolean;
|
|
(chunk: string | Uint8Array, encoding?: BufferEncoding, cb?: WriteCallback): boolean;
|
|
};
|
|
|
|
// module-level activity tracking - allows agents to mark activity on any event
|
|
let _lastActivity = performance.now();
|
|
|
|
/**
|
|
* upper bound on how long a single tool call can suspend the activity
|
|
* watchdog. matched against the typical worst-case `checkout_pr`
|
|
* fetch+deepen on a large monorepo (issue #760: 4-5min) plus generous
|
|
* headroom for slower MCP tools, while still bounding the worst case if
|
|
* a tool genuinely hangs and `tool_result` never arrives — auto-resume
|
|
* fires here and the normal idle clock takes over from a fresh baseline.
|
|
*/
|
|
export const MAX_TOOL_CALL_SUSPENSION_MS = 15 * 60 * 1000;
|
|
|
|
let _suspendedAt: number | null = null;
|
|
let _suspensionTimer: NodeJS.Timeout | null = null;
|
|
|
|
/**
|
|
* mark activity to reset the no-output timeout.
|
|
* call this whenever the agent emits any event, even if it isn't logged to stdout.
|
|
*/
|
|
export function markActivity(): void {
|
|
_lastActivity = performance.now();
|
|
}
|
|
|
|
/**
|
|
* get the time since last activity in milliseconds.
|
|
* returns 0 while the watchdog is suspended (issue #760).
|
|
*/
|
|
export function getIdleMs(): number {
|
|
if (_suspendedAt !== null) return 0;
|
|
return Math.round(performance.now() - _lastActivity);
|
|
}
|
|
|
|
/**
|
|
* suspend the activity watchdog while a long-running, in-flight unit of
|
|
* work is happening (e.g. an MCP `tools/call` that synchronously awaits
|
|
* a multi-minute git fetch). bracket calls with `resumeActivity()` from
|
|
* the agent harness's `tool_use` / `tool_result` event handlers.
|
|
*
|
|
* - idempotent: nested suspends are no-ops; the first resume wins.
|
|
* - bounded: auto-resumes after `maxMs` so a buggy tool that never
|
|
* produces a `tool_result` can't pin the watchdog open forever.
|
|
* - safe: only the *agent harness* (claude.ts / opencode.ts) on explicit,
|
|
* paired CLI events should call this. NEVER blanket-suspend on internal
|
|
* noise — that would resurrect issue #12 zombie runs.
|
|
*/
|
|
export function suspendActivity(maxMs: number = MAX_TOOL_CALL_SUSPENSION_MS): void {
|
|
if (_suspendedAt !== null) return;
|
|
_suspendedAt = performance.now();
|
|
_suspensionTimer = setTimeout(() => {
|
|
log.warning(`activity watchdog suspended >${Math.round(maxMs / 1000)}s — auto-resuming`);
|
|
resumeActivity();
|
|
}, maxMs);
|
|
_suspensionTimer.unref?.();
|
|
}
|
|
|
|
/**
|
|
* resume the activity watchdog. resets the idle baseline so a stale
|
|
* idle window before the suspend can't immediately re-fire.
|
|
*/
|
|
export function resumeActivity(): void {
|
|
if (_suspendedAt === null) return;
|
|
_suspendedAt = null;
|
|
if (_suspensionTimer) {
|
|
clearTimeout(_suspensionTimer);
|
|
_suspensionTimer = null;
|
|
}
|
|
_lastActivity = performance.now();
|
|
}
|
|
|
|
export function isActivitySuspended(): boolean {
|
|
return _suspendedAt !== null;
|
|
}
|
|
|
|
function wrapWrite(original: WriteFunction, onActivity: () => void): WriteFunction {
|
|
const wrapped: WriteFunction = (
|
|
chunk: string | Uint8Array,
|
|
encodingOrCb?: BufferEncoding | WriteCallback,
|
|
cb?: WriteCallback
|
|
): boolean => {
|
|
if (!isActivityNoise(chunk)) {
|
|
onActivity();
|
|
}
|
|
if (typeof encodingOrCb === "function") {
|
|
return original(chunk, encodingOrCb);
|
|
}
|
|
return original(chunk, encodingOrCb, cb);
|
|
};
|
|
return wrapped;
|
|
}
|
|
|
|
function startProcessOutputMonitor(ctx: OutputMonitorContext): OutputMonitor {
|
|
let timedOut = false;
|
|
|
|
const originalStdoutWrite: WriteFunction = process.stdout.write.bind(process.stdout);
|
|
const originalStderrWrite: WriteFunction = process.stderr.write.bind(process.stderr);
|
|
|
|
// stdout/stderr writes also mark activity
|
|
process.stdout.write = wrapWrite(originalStdoutWrite, markActivity);
|
|
process.stderr.write = wrapWrite(originalStderrWrite, markActivity);
|
|
|
|
// route the monitor's own diagnostics through the captured original write
|
|
// instead of log.debug — otherwise those lines feed back through the
|
|
// wrapped process.stdout.write, miss isActivityNoise, and call
|
|
// markActivity() themselves. in debug mode the periodic check below would
|
|
// then reset the timer every interval and the timeout would never fire,
|
|
// re-creating the exact zombie-run bug #12 was meant to kill.
|
|
const debugBypass = (msg: string): void => {
|
|
if (!isMonitorDebugEnabled()) return;
|
|
originalStdoutWrite(`[${new Date().toISOString()}] [DEBUG] ${msg}\n`);
|
|
};
|
|
|
|
debugBypass(`process activity monitor started: timeout=${ctx.timeoutMs}ms`);
|
|
|
|
const intervalId = setInterval(() => {
|
|
const idleMs = getIdleMs();
|
|
debugBypass(`process activity check: idle=${idleMs}ms / ${ctx.timeoutMs}ms`);
|
|
if (timedOut || idleMs <= ctx.timeoutMs) return;
|
|
timedOut = true;
|
|
ctx.onTimeout(idleMs);
|
|
}, ctx.checkIntervalMs);
|
|
|
|
function stop(): void {
|
|
clearInterval(intervalId);
|
|
process.stdout.write = originalStdoutWrite;
|
|
process.stderr.write = originalStderrWrite;
|
|
}
|
|
|
|
return { stop };
|
|
}
|
|
|
|
export function createProcessOutputActivityTimeout(ctx: ActivityTimeoutContext): ActivityTimeout {
|
|
markActivity(); // reset baseline
|
|
|
|
let rejectFn: ((error: Error) => void) | null = null;
|
|
const promise = new Promise<never>((_, reject) => {
|
|
rejectFn = reject;
|
|
});
|
|
|
|
let monitor: OutputMonitor | null = null;
|
|
monitor = startProcessOutputMonitor({
|
|
timeoutMs: ctx.timeoutMs,
|
|
checkIntervalMs: ctx.checkIntervalMs,
|
|
onTimeout: (idleMs) => {
|
|
if (!rejectFn) return;
|
|
const idleSec = Math.round(idleMs / 1000);
|
|
if (monitor) {
|
|
monitor.stop();
|
|
}
|
|
const reject = rejectFn;
|
|
rejectFn = null;
|
|
reject(new Error(`activity timeout: no output for ${idleSec}s`));
|
|
},
|
|
});
|
|
|
|
return {
|
|
promise,
|
|
// stop() also disarms forceReject so a late safety-net fire can't reject
|
|
// the promise after the run has already succeeded.
|
|
stop: () => {
|
|
monitor?.stop();
|
|
rejectFn = null;
|
|
},
|
|
forceReject: (reason: string) => {
|
|
if (!rejectFn) return;
|
|
monitor?.stop();
|
|
const reject = rejectFn;
|
|
rejectFn = null;
|
|
reject(new Error(reason));
|
|
},
|
|
};
|
|
}
|