Files
shockbot/utils/activity.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

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));
},
};
}