From 079d36790b0d5c56e57d07efed05a5f4f6c3abed Mon Sep 17 00:00:00 2001 From: JSONbored <49853598+JSONbored@users.noreply.github.com> Date: Sat, 11 Jul 2026 02:41:10 -0700 Subject: [PATCH] fix(review): rate-limit the ci_stuck_review_repeat_suppressed log (#4998) The log line that announces a repeat suppression fired as its own console.error on EVERY suppressed evaluation, not once per incident -- 649 events over 4 days. The underlying suppression (capping the finalize/review spend to once per head SHA) was correct; only the observability side never got the same treatment. Rate-limit the log to once per (repo, pr, headSha) per day via the existing self-host transient-cache helpers; the defer itself is untouched and still runs on every evaluation. --- src/queue/processors.ts | 50 ++++++++++++++++++++++------- test/unit/queue.test.ts | 70 +++++++++++++++++++++++++++++++++++++++++ 2 files changed, 109 insertions(+), 11 deletions(-) diff --git a/src/queue/processors.ts b/src/queue/processors.ts index 952c9f5a72..ba46d25b81 100644 --- a/src/queue/processors.ts +++ b/src/queue/processors.ts @@ -3393,17 +3393,21 @@ async function prReadyForReview( // stopped the wasteful re-review, so its OWN existence is the operator-visible signal (via the structured // log → Sentry forwarder, forwardStructuredLogToSentry) that a PR's CI has been permanently stuck long // enough to need a human — the same "surface an anomaly at error level" convention selfhost_ai_provider_ - // failed / selfhost_ai_providers_exhausted already use in src/selfhost/ai.ts. - console.error( - JSON.stringify({ - level: "error", - event: "ci_stuck_review_repeat_suppressed", - repo: repoFullName, - pullNumber: pr.number, - headSha: pr.headSha, - deliveryId, - }), - ); + // failed / selfhost_ai_providers_exhausted already use in src/selfhost/ai.ts. Rate-limited to once per + // (repo, pr, headSha) per day (#4998) — the defer above still runs on every evaluation; only the log is + // coalesced, so one permanently-stuck PR doesn't flood Sentry with hundreds of copies of the same signal. + if (!(await ciStuckRepeatLogCoalesced(env, repoFullName, pr.number, pr.headSha))) { + console.error( + JSON.stringify({ + level: "error", + event: "ci_stuck_review_repeat_suppressed", + repo: repoFullName, + pullNumber: pr.number, + headSha: pr.headSha, + deliveryId, + }), + ); + } return false; } await recordAuditEvent(env, { @@ -3432,6 +3436,13 @@ const CI_STUCK_FINALIZE_GUARD_EVENT_TYPE = "github_app.review_finalized_ci_stuck const CI_STUCK_FINALIZE_MAX_PER_SHA = 1; const CI_STUCK_FINALIZE_GUARD_LOOKBACK_MS = 7 * 24 * 60 * 60 * 1000; +// #4998: the ci_stuck_review_repeat_suppressed log below announces ONE thing (this PR has been stuck long enough +// that a human should look) -- but the guard it reports on re-fires on EVERY later evaluation of a PR still +// stuck on the same head SHA (a webhook re-trigger, a sweep pass), which flooded Sentry (650 events over 4 days +// for a single PR). Rate-limits the LOG only, once per (repo, pr, headSha) per day -- the underlying suppression +// (the guard immediately above the log call) is untouched and still runs every time. +const CI_STUCK_REPEAT_LOG_WINDOW_SECONDS = 24 * 60 * 60; + // A required check pending longer than this is treated as STUCK (orphaned / never-completing — e.g. a fork check // that will never report). Past it, prReadyForReview stops deferring and finalizes the gate so the PR surfaces // (held / needs-human) instead of deferring forever. Generous so a genuinely-slow CI is never cut off early. @@ -3468,6 +3479,23 @@ async function putTransientKey( } } +/** True when the ci_stuck_review_repeat_suppressed log for this exact (repo, pr, headSha) already fired within + * the window -- caller should skip logging (but still perform the actual defer). A missing/unavailable + * transient cache degrades to "never coalesced" (every call logs, matching the pre-#4998 behavior) rather than + * risk silently dropping the one operator-visible signal that a PR is stuck. */ +async function ciStuckRepeatLogCoalesced( + env: Env, + repoFullName: string, + prNumber: number, + headSha: string, +): Promise { + const key = `ci-stuck-repeat-log:${repoFullName.toLowerCase()}#${prNumber}:${headSha}`; + // getTransientKey/putTransientKey are already internally fail-safe (never throw), so no outer try/catch here. + if (await getTransientKey(env, key)) return true; + await putTransientKey(env, key, "1", CI_STUCK_REPEAT_LOG_WINDOW_SECONDS); + return false; +} + /** * True when CI for this PR+headSha has been pending past `capMs`. Stamps the first-seen time in a transient diff --git a/test/unit/queue.test.ts b/test/unit/queue.test.ts index f5bde33cad..b53b71786f 100644 --- a/test/unit/queue.test.ts +++ b/test/unit/queue.test.ts @@ -1831,6 +1831,76 @@ describe("queue processors", () => { } }); + it("REGRESSION (#4998): ci_stuck_review_repeat_suppressed rate-limits its log to once per (repo, pr, headSha) per day -- the defer still runs on every evaluation", async () => { + const env = createTestEnv({ GITHUB_APP_PRIVATE_KEY: await generatePrivateKeyPem() }); + await upsertInstallation(env, { action: "created", installation: { id: 9001, account: { login: "owner", id: 1, type: "Organization" }, target_type: "Organization", repository_selection: "selected", permissions: { pull_requests: "write", checks: "write" }, events: [] } }); + await upsertRepositoryFromGitHub(env, { name: "agent-repo", full_name: "owner/agent-repo", private: false, owner: { login: "owner" } }, 9001); + await upsertRepositorySettings(env, { repoFullName: "owner/agent-repo", autonomy: { merge: "auto", update_branch: "auto" }, aiReviewMode: "off", gatePack: "oss-anti-slop", gateCheckMode: "enabled", reviewCheckMode: "required", checkRunMode: "off", commentMode: "off", publicSurface: "off" }); + await upsertPullRequestFromGitHub(env, "owner/agent-repo", { number: 7, title: "Permanently stuck CI", state: "open", user: { login: "contributor" }, head: { sha: "a7" }, base: { ref: "main" }, labels: [], body: "Closes #1" }); + vi.setSystemTime(new Date("2026-05-28T02:00:00.000Z")); + await env.SELFHOST_TRANSIENT_CACHE?.set( + "ci-pending-first-seen:owner/agent-repo#7:a7", + String(Date.now() - 31 * 60 * 1000), + 7 * 24 * 3600, + ); + const requiredContextsSpy = vi.spyOn(backfillModule, "fetchRequiredStatusContexts").mockResolvedValue(new Set(["trusted-required-ci"])); + const liveCiSpy = vi.spyOn(backfillModule, "fetchLiveCiAggregatePreferGraphQl").mockResolvedValue({ + ciState: "passed", + hasPending: true, + hasVisiblePending: false, + hasMissingRequiredContext: false, + failingDetails: [], + nonRequiredFailingDetails: [], + ciCompletenessWarning: null, + }); + let liveHeadSha = "a7"; + vi.stubGlobal("fetch", async (input: RequestInfo | URL, init?: RequestInit) => { + const url = input.toString(); + const method = (init?.method ?? "GET").toUpperCase(); + if (url === "https://api.gittensor.io/miners") return Response.json([]); + if (url.includes("/access_tokens")) return Response.json({ token: "installation-token" }); + if (/\/pulls\/7(?:\?|$)/.test(url) && method === "GET") return Response.json({ number: 7, title: "Permanently stuck CI", state: "open", user: { login: "contributor" }, head: { sha: liveHeadSha }, mergeable_state: "clean", labels: [], body: "Closes #1" }); + if (url.includes("/pulls/7/files")) return Response.json([{ filename: "src/a.ts", status: "modified", additions: 1, deletions: 0, changes: 1, patch: "@@\n+export const ok = true;" }]); + if (url.includes("/check-runs") && (method === "POST" || method === "PATCH")) return Response.json({ id: 901 }, { status: method === "POST" ? 201 : 200 }); + return Response.json({}); + }); + const errors = vi.spyOn(console, "error").mockImplementation(() => undefined); + + try { + // 1st evaluation: finalizes for real (pays for one review). 2nd: guarded — defers AND logs (the ONE + // Sentry-visible signal). 3rd: guarded again — defers again, but the log is now within the 24h coalesce + // window, so it must NOT re-fire. + await processJob(env, { type: "agent-regate-pr", deliveryId: "stuck-ci-eval-1", repoFullName: "owner/agent-repo", prNumber: 7, installationId: 9001 }); + await processJob(env, { type: "agent-regate-pr", deliveryId: "stuck-ci-eval-2", repoFullName: "owner/agent-repo", prNumber: 7, installationId: 9001 }); + await processJob(env, { type: "agent-regate-pr", deliveryId: "stuck-ci-eval-3", repoFullName: "owner/agent-repo", prNumber: 7, installationId: 9001 }); + + const deferred = await env.DB.prepare("select count(*) as n from audit_events where event_type = ? and target_key = ?") + .bind("github_app.review_deferred_ci_pending", "owner/agent-repo#7") + .first<{ n: number }>(); + expect(deferred?.n).toBe(2); // both the 2nd AND 3rd evaluations deferred -- suppression itself is unchanged + const repeatSuppressedLogs = errors.mock.calls.filter(([line]) => typeof line === "string" && line.includes("ci_stuck_review_repeat_suppressed")); + expect(repeatSuppressedLogs).toHaveLength(1); // only the 2nd evaluation's log survives -- the 3rd is coalesced + + // A DIFFERENT head SHA (a new commit) is a fresh key -- its first guarded evaluation must log again, not + // inherit the previous SHA's coalesce window. + liveHeadSha = "b7"; + await upsertPullRequestFromGitHub(env, "owner/agent-repo", { number: 7, title: "Permanently stuck CI", state: "open", user: { login: "contributor" }, head: { sha: "b7" }, base: { ref: "main" }, labels: [], body: "Closes #1" }); + await env.SELFHOST_TRANSIENT_CACHE?.set( + "ci-pending-first-seen:owner/agent-repo#7:b7", + String(Date.now() - 31 * 60 * 1000), + 7 * 24 * 3600, + ); + await processJob(env, { type: "agent-regate-pr", deliveryId: "stuck-ci-eval-4", repoFullName: "owner/agent-repo", prNumber: 7, installationId: 9001 }); + await processJob(env, { type: "agent-regate-pr", deliveryId: "stuck-ci-eval-5", repoFullName: "owner/agent-repo", prNumber: 7, installationId: 9001 }); + const repeatSuppressedLogsAfterNewSha = errors.mock.calls.filter(([line]) => typeof line === "string" && line.includes("ci_stuck_review_repeat_suppressed")); + expect(repeatSuppressedLogsAfterNewSha).toHaveLength(2); // the new SHA's own guarded evaluation logged once + } finally { + errors.mockRestore(); + liveCiSpy.mockRestore(); + requiredContextsSpy.mockRestore(); + } + }); + it("REGRESSION (#orb-ci-stuck-repeat, fail-open): a failed guard-audit write does not stop the first stuck-CI finalize from running its review", async () => { const env = createTestEnv({ GITHUB_APP_PRIVATE_KEY: await generatePrivateKeyPem() }); await upsertInstallation(env, { action: "created", installation: { id: 9001, account: { login: "owner", id: 1, type: "Organization" }, target_type: "Organization", repository_selection: "selected", permissions: { pull_requests: "write", checks: "write" }, events: [] } });