From 88f170e19a2f753bac3154d2a6c2a08d649cc6af Mon Sep 17 00:00:00 2001 From: Colin McDonnell Date: Tue, 19 May 2026 18:40:53 +0000 Subject: [PATCH] fix: 7 log-audit / run-audit findings (mega-PR) (#769) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * 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 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 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 for InstallationRateLimitError typed throw The Result 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. --- agents/claude.ts | 17 ++++++++++++- agents/opencode.ts | 40 ++++++++++++++++++++++++------ mcp/git.ts | 24 ++++++++++++++++++ utils/activity.ts | 59 ++++++++++++++++++++++++++++++++++++++++++++- utils/github.ts | 26 +++++++++++++++++--- utils/shell.ts | 10 +++++++- utils/subprocess.ts | 15 ++++++++++++ 7 files changed, 177 insertions(+), 14 deletions(-) diff --git a/agents/claude.ts b/agents/claude.ts index f128094..9189cfb 100644 --- a/agents/claude.ts +++ b/agents/claude.ts @@ -18,7 +18,13 @@ import { performance } from "node:perf_hooks"; import { pullfrogMcpName } from "../external.ts"; import { BEDROCK_MODEL_ID_ENV, isBedrockAnthropicId } from "../models.ts"; -import { getIdleMs, markActivity } from "../utils/activity.ts"; +import { + getIdleMs, + isActivitySuspended, + markActivity, + resumeActivity, + suspendActivity, +} from "../utils/activity.ts"; import { formatJsonValue, log } from "../utils/cli.ts"; import { installFromNpmTarball } from "../utils/install.ts"; import { findProviderErrorMatch } from "../utils/providerErrors.ts"; @@ -367,6 +373,13 @@ export async function runClaude(params: RunParams): Promise { } } else if (block.type === "tool_use") { const toolName = block.name || "unknown"; + // suspend the activity watchdog across the tool call. claude's + // stdout pipe goes silent while it awaits the synchronous MCP + // tools/call HTTP response; without this, long fetches/deepens + // (issue #760) trip the spawn-level idle timer at 300s. paired + // with resumeActivity() in tool_result below; bounded by the + // MAX_TOOL_CALL_SUSPENSION_MS auto-resume in activity.ts. + suspendActivity(); if (params.onToolUse) { params.onToolUse({ toolName, @@ -443,6 +456,7 @@ export async function runClaude(params: RunParams): Promise { for (const block of content) { if (typeof block === "string") continue; if (block.type === "tool_result") { + resumeActivity(); timerFor(label).markToolResult(); const outputContent = @@ -576,6 +590,7 @@ export async function runClaude(params: RunParams): Promise { env: params.env, activityTimeout: 300_000, onActivityTimeout: params.onActivityTimeout, + isPausedExternally: isActivitySuspended, stdio: ["ignore", "pipe", "pipe"], // run claude in its own process group so SIGKILL on activity timeout / // outer cancellation reaches any subprocesses it spawns (rg, file diff --git a/agents/opencode.ts b/agents/opencode.ts index 7064721..22a36dd 100644 --- a/agents/opencode.ts +++ b/agents/opencode.ts @@ -19,7 +19,13 @@ import * as core from "@actions/core"; import { pullfrogMcpName } from "../external.ts"; import { BEDROCK_MODEL_ID_ENV, modelAliases } from "../models.ts"; import type { ToolState } from "../toolState.ts"; -import { getIdleMs, markActivity } from "../utils/activity.ts"; +import { + getIdleMs, + isActivitySuspended, + markActivity, + resumeActivity, + suspendActivity, +} from "../utils/activity.ts"; import { type AgentDiagnostic, formatAgentHangBody } from "../utils/agentHangReport.ts"; import { formatJsonValue, log } from "../utils/cli.ts"; import { installCodexAuth } from "../utils/codexHome.ts"; @@ -651,6 +657,21 @@ async function runOpenCode(params: RunParams): Promise { return; } + // suspend the activity watchdog across the tool call (issue #760). + // for `task` tool dispatches the injected plugin already reverbs + // child.stdout chunks, so this is mostly defense-in-depth there; + // for non-task MCP tools (checkout_pr, etc.) the suspend is the + // only thing keeping a multi-minute fetch from tripping the 300s + // spawn-level idle timer. gate by part status: bus-envelope + // re-dispatches at line 915 fire only on terminal statuses + // (`completed`/`error`) and never produce a paired `tool_result`, + // so suspending on those would leak the watchdog open until the + // 15min auto-resume — exactly the issue #12 zombie-run window. + const status = event.part?.state?.status; + if (status !== "completed" && status !== "error") { + suspendActivity(); + } + // when the orchestrator dispatches a subagent via the `task` tool, push // a label for the upcoming child session so its events are attributable. // record BEFORE label lookup: this event's session is the parent (whose @@ -732,6 +753,7 @@ async function runOpenCode(params: RunParams): Promise { } }, tool_result: (event: OpenCodeToolResultEvent) => { + resumeActivity(); const toolId = event.part?.callID || event.tool_id; const state = event.part?.state; const status = state?.status ?? event.status ?? "unknown"; @@ -979,13 +1001,15 @@ async function runOpenCode(params: RunParams): Promise { // wrapper would grow unbounded for multi-lens Reviews and previously // crashed the wrapper with RangeError at ~1 GiB. see issue #680. retain: "none", - // NB: we used to pass `isPausedExternally: isSubagentInFlight` to suspend - // the activity timer during subagent dispatches. unnecessary now that - // our injected plugin (action/agents/opencodePlugin.ts) re-emits - // subagent `message.part.updated` events on opencode's stdout — those - // arrive at child.stdout here, fire updateActivity(), and reset - // lastActivityTime naturally. verified empirically in PR #634 - // (~3.3 plugin events/sec during a typical subagent run). + // suspend the spawn-level idle watchdog across MCP tool calls (issue + // #760). bracketed by suspendActivity()/resumeActivity() in the + // tool_use/tool_result handlers above, bounded by + // MAX_TOOL_CALL_SUSPENSION_MS in activity.ts. the injected plugin + // (action/agents/opencodePlugin.ts) re-emits subagent + // `message.part.updated` events on opencode's stdout, so subagent + // dispatches keep marking child.stdout activity as well — defense + // in depth (verified empirically in PR #634, ~3.3 plugin events/sec). + isPausedExternally: isActivitySuspended, onStdout: async (chunk) => { const text = chunk.toString(); output.append(text); diff --git a/mcp/git.ts b/mcp/git.ts index 5e96ba5..3aa697d 100644 --- a/mcp/git.ts +++ b/mcp/git.ts @@ -490,6 +490,30 @@ export function GitTool(ctx: ToolContext) { } } + // `git merge-base --is-ancestor` uses exit codes as data: 0 = ancestor, + // 1 = not-an-ancestor, >1 = real error. Surface the binary answer + // instead of throwing on exit 1. see #766. + if (command === "merge-base" && args.includes("--is-ancestor")) { + let isAncestor = true; + $("git", [command, ...args], { + log: false, + onError: (r) => { + if (r.status === 1) { + isAncestor = false; + return; + } + const detail = [r.stderr, r.stdout] + .map((s) => s.trim()) + .filter(Boolean) + .join("\n"); + throw new Error( + `git merge-base --is-ancestor failed (exit ${r.status}): ${detail || "Unknown error"}` + ); + }, + }); + return { success: true, isAncestor }; + } + const output = $("git", [command, ...args], { log: false }); const lineCount = output.split("\n").length; if (lineCount > COLLAPSE_THRESHOLD) { diff --git a/utils/activity.ts b/utils/activity.ts index d8c973d..37fa2cb 100644 --- a/utils/activity.ts +++ b/utils/activity.ts @@ -1,4 +1,5 @@ import { performance } from "node:perf_hooks"; +import { log } from "./log.ts"; function isMonitorDebugEnabled(): boolean { return ( @@ -79,6 +80,19 @@ type WriteFunction = { // 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. @@ -88,12 +102,55 @@ export function markActivity(): void { } /** - * get the time since last activity in milliseconds + * 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, diff --git a/utils/github.ts b/utils/github.ts index 8d55cf3..b630e68 100644 --- a/utils/github.ts +++ b/utils/github.ts @@ -379,10 +379,30 @@ export async function acquireNewToken(opts?: AcquireTokenOptions): Promise s.trim()) + .filter(Boolean) + .join("\n"); throw new Error( - `Command failed with exit code ${errorResult.status}: ${stderr || "Unknown error"}` + `Command failed with exit code ${errorResult.status}: ${detail || "Unknown error"}` ); } diff --git a/utils/subprocess.ts b/utils/subprocess.ts index d1e6294..2874b7d 100644 --- a/utils/subprocess.ts +++ b/utils/subprocess.ts @@ -125,6 +125,14 @@ export interface SpawnOptions { // 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; @@ -276,6 +284,13 @@ export async function spawn(options: SpawnOptions): Promise { `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`