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.
This commit is contained in:
Colin McDonnell
2026-05-19 18:40:53 +00:00
committed by pullfrog[bot]
parent 0abaaa1e37
commit 88f170e19a
7 changed files with 177 additions and 14 deletions
+16 -1
View File
@@ -18,7 +18,13 @@ import { performance } from "node:perf_hooks";
import { pullfrogMcpName } from "../external.ts"; import { pullfrogMcpName } from "../external.ts";
import { BEDROCK_MODEL_ID_ENV, isBedrockAnthropicId } from "../models.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 { formatJsonValue, log } from "../utils/cli.ts";
import { installFromNpmTarball } from "../utils/install.ts"; import { installFromNpmTarball } from "../utils/install.ts";
import { findProviderErrorMatch } from "../utils/providerErrors.ts"; import { findProviderErrorMatch } from "../utils/providerErrors.ts";
@@ -367,6 +373,13 @@ export async function runClaude(params: RunParams): Promise<ClaudeRunResult> {
} }
} else if (block.type === "tool_use") { } else if (block.type === "tool_use") {
const toolName = block.name || "unknown"; 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) { if (params.onToolUse) {
params.onToolUse({ params.onToolUse({
toolName, toolName,
@@ -443,6 +456,7 @@ export async function runClaude(params: RunParams): Promise<ClaudeRunResult> {
for (const block of content) { for (const block of content) {
if (typeof block === "string") continue; if (typeof block === "string") continue;
if (block.type === "tool_result") { if (block.type === "tool_result") {
resumeActivity();
timerFor(label).markToolResult(); timerFor(label).markToolResult();
const outputContent = const outputContent =
@@ -576,6 +590,7 @@ export async function runClaude(params: RunParams): Promise<ClaudeRunResult> {
env: params.env, env: params.env,
activityTimeout: 300_000, activityTimeout: 300_000,
onActivityTimeout: params.onActivityTimeout, onActivityTimeout: params.onActivityTimeout,
isPausedExternally: isActivitySuspended,
stdio: ["ignore", "pipe", "pipe"], stdio: ["ignore", "pipe", "pipe"],
// run claude in its own process group so SIGKILL on activity timeout / // run claude in its own process group so SIGKILL on activity timeout /
// outer cancellation reaches any subprocesses it spawns (rg, file // outer cancellation reaches any subprocesses it spawns (rg, file
+32 -8
View File
@@ -19,7 +19,13 @@ import * as core from "@actions/core";
import { pullfrogMcpName } from "../external.ts"; import { pullfrogMcpName } from "../external.ts";
import { BEDROCK_MODEL_ID_ENV, modelAliases } from "../models.ts"; import { BEDROCK_MODEL_ID_ENV, modelAliases } from "../models.ts";
import type { ToolState } from "../toolState.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 { type AgentDiagnostic, formatAgentHangBody } from "../utils/agentHangReport.ts";
import { formatJsonValue, log } from "../utils/cli.ts"; import { formatJsonValue, log } from "../utils/cli.ts";
import { installCodexAuth } from "../utils/codexHome.ts"; import { installCodexAuth } from "../utils/codexHome.ts";
@@ -651,6 +657,21 @@ async function runOpenCode(params: RunParams): Promise<AgentResult> {
return; 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 // when the orchestrator dispatches a subagent via the `task` tool, push
// a label for the upcoming child session so its events are attributable. // a label for the upcoming child session so its events are attributable.
// record BEFORE label lookup: this event's session is the parent (whose // record BEFORE label lookup: this event's session is the parent (whose
@@ -732,6 +753,7 @@ async function runOpenCode(params: RunParams): Promise<AgentResult> {
} }
}, },
tool_result: (event: OpenCodeToolResultEvent) => { tool_result: (event: OpenCodeToolResultEvent) => {
resumeActivity();
const toolId = event.part?.callID || event.tool_id; const toolId = event.part?.callID || event.tool_id;
const state = event.part?.state; const state = event.part?.state;
const status = state?.status ?? event.status ?? "unknown"; const status = state?.status ?? event.status ?? "unknown";
@@ -979,13 +1001,15 @@ async function runOpenCode(params: RunParams): Promise<AgentResult> {
// wrapper would grow unbounded for multi-lens Reviews and previously // wrapper would grow unbounded for multi-lens Reviews and previously
// crashed the wrapper with RangeError at ~1 GiB. see issue #680. // crashed the wrapper with RangeError at ~1 GiB. see issue #680.
retain: "none", retain: "none",
// NB: we used to pass `isPausedExternally: isSubagentInFlight` to suspend // suspend the spawn-level idle watchdog across MCP tool calls (issue
// the activity timer during subagent dispatches. unnecessary now that // #760). bracketed by suspendActivity()/resumeActivity() in the
// our injected plugin (action/agents/opencodePlugin.ts) re-emits // tool_use/tool_result handlers above, bounded by
// subagent `message.part.updated` events on opencode's stdout — those // MAX_TOOL_CALL_SUSPENSION_MS in activity.ts. the injected plugin
// arrive at child.stdout here, fire updateActivity(), and reset // (action/agents/opencodePlugin.ts) re-emits subagent
// lastActivityTime naturally. verified empirically in PR #634 // `message.part.updated` events on opencode's stdout, so subagent
// (~3.3 plugin events/sec during a typical subagent run). // 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) => { onStdout: async (chunk) => {
const text = chunk.toString(); const text = chunk.toString();
output.append(text); output.append(text);
+24
View File
@@ -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 output = $("git", [command, ...args], { log: false });
const lineCount = output.split("\n").length; const lineCount = output.split("\n").length;
if (lineCount > COLLAPSE_THRESHOLD) { if (lineCount > COLLAPSE_THRESHOLD) {
+58 -1
View File
@@ -1,4 +1,5 @@
import { performance } from "node:perf_hooks"; import { performance } from "node:perf_hooks";
import { log } from "./log.ts";
function isMonitorDebugEnabled(): boolean { function isMonitorDebugEnabled(): boolean {
return ( return (
@@ -79,6 +80,19 @@ type WriteFunction = {
// module-level activity tracking - allows agents to mark activity on any event // module-level activity tracking - allows agents to mark activity on any event
let _lastActivity = performance.now(); 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. * mark activity to reset the no-output timeout.
* call this whenever the agent emits any event, even if it isn't logged to stdout. * 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 { export function getIdleMs(): number {
if (_suspendedAt !== null) return 0;
return Math.round(performance.now() - _lastActivity); 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 { function wrapWrite(original: WriteFunction, onActivity: () => void): WriteFunction {
const wrapped: WriteFunction = ( const wrapped: WriteFunction = (
chunk: string | Uint8Array, chunk: string | Uint8Array,
+23 -3
View File
@@ -379,10 +379,30 @@ export async function acquireNewToken(opts?: AcquireTokenOptions): Promise<strin
); );
}, },
}); });
} else {
// local development via GitHub App
return await acquireTokenViaGitHubApp(opts);
} }
// running inside GitHub Actions but the OIDC env vars are absent — the
// workflow is missing `permissions: id-token: write`. surface an
// actionable, customer-facing message; the GitHub-App branch below is
// local-dev only. see #739.
if (process.env.GITHUB_ACTIONS === "true") {
throw new Error(
"missing `permissions: id-token: write` on the Pullfrog workflow job.\n" +
"\n" +
"Pullfrog mints short-lived GitHub App installation tokens via OIDC and\n" +
"requires `id-token: write` to be granted at the job level. add the\n" +
"following to your workflow yaml:\n" +
"\n" +
" jobs:\n" +
" pullfrog:\n" +
" permissions:\n" +
" id-token: write # mint Pullfrog installation tokens via OIDC\n" +
" contents: read # for actions/checkout\n" +
"\n" +
"see https://docs.pullfrog.com/headless-action#required-permissions for the full template."
);
}
// local development via GitHub App
return await acquireTokenViaGitHubApp(opts);
} }
export interface RepoContext { export interface RepoContext {
+9 -1
View File
@@ -86,8 +86,16 @@ export function $(cmd: string, args: string[], options?: ShellOptions): string {
return stdout.trim(); return stdout.trim();
} }
// many git subcommands write context-bearing diagnostics to stdout, not
// stderr (merge conflicts, cherry-pick rejections, diff --exit-code,
// ls-files --error-unmatch). Falling back to "Unknown error" robbed the
// agent of any signal and forced an extra MCP round-trip. see #766.
const detail = [stderr, stdout]
.map((s) => s.trim())
.filter(Boolean)
.join("\n");
throw new Error( throw new Error(
`Command failed with exit code ${errorResult.status}: ${stderr || "Unknown error"}` `Command failed with exit code ${errorResult.status}: ${detail || "Unknown error"}`
); );
} }
+15
View File
@@ -125,6 +125,14 @@ export interface SpawnOptions {
// so that lingering SSE reconnects don't keep the outer activity timer // so that lingering SSE reconnects don't keep the outer activity timer
// alive after the subprocess is already dead. // alive after the subprocess is already dead.
onActivityTimeout?: (() => void) | undefined; 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; cwd?: string;
stdio?: ("pipe" | "ignore" | "inherit")[]; stdio?: ("pipe" | "ignore" | "inherit")[];
onStdout?: (chunk: string) => void; onStdout?: (chunk: string) => void;
@@ -276,6 +284,13 @@ export async function spawn(options: SpawnOptions): Promise<SpawnResult> {
`spawn activity timer: pid=${child.pid} cmd=${options.cmd} timeout=${activityTimeoutMs}ms` `spawn activity timer: pid=${child.pid} cmd=${options.cmd} timeout=${activityTimeoutMs}ms`
); );
activityCheckIntervalId = setInterval(() => { 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; const idleMs = performance.now() - lastActivityTime;
log.debug( log.debug(
`spawn activity check: pid=${child.pid} idle=${Math.round(idleMs)}ms / ${activityTimeoutMs}ms` `spawn activity check: pid=${child.pid} idle=${Math.round(idleMs)}ms / ${activityTimeoutMs}ms`