diff --git a/src/db/repositories.ts b/src/db/repositories.ts index 871997fa81..05599f4700 100644 --- a/src/db/repositories.ts +++ b/src/db/repositories.ts @@ -5298,6 +5298,22 @@ export async function hasActiveReviewForHeadSha(env: Env, repoFullName: string, return row !== undefined && row.status === "active" && row.headSha === headSha; } +// Review turnaround-time tracking (#4446): reuses the SAME startedAt startActiveReviewTracking already records +// for review-evasion protection -- reads it (for the exact headSha this pass is publishing) rather than +// duplicating a second "when did this review start" clock. Not gated on status === "active": the publish site +// this feeds reads it BEFORE terminalizeActiveReviewTracking runs later in the same pass (see processors.ts), +// but staying permissive here means a future reordering degrades to "no duration" rather than a silent wrong +// number. A DIFFERENT headSha (a newer pass already raced in) or no row at all correctly returns null -- the +// caller's duration computation is skipped entirely rather than measuring the wrong pass's window. +export async function getActiveReviewStartedAt(env: Env, repoFullName: string, pullNumber: number, headSha: string): Promise { + const row = await getDb(env.DB) + .select({ headSha: activeReviewTracking.headSha, startedAt: activeReviewTracking.startedAt }) + .from(activeReviewTracking) + .where(and(eq(activeReviewTracking.repoFullName, boundedString(repoFullName, 200)), eq(activeReviewTracking.pullNumber, pullNumber))) + .get(); + return row !== undefined && row.headSha === headSha ? row.startedAt : null; +} + // Review-evasion protection: guarded status transition -- terminalize the active-review row for // repoFullName#pullNumber ONLY if it is still 'active' (and, when given, still pinned to headSha), the same // CAS shape as claimPendingAgentActionDecision, so a stale/already-terminalized row is never double-processed. diff --git a/src/queue/processors.ts b/src/queue/processors.ts index 464b580757..81b148b481 100644 --- a/src/queue/processors.ts +++ b/src/queue/processors.ts @@ -72,6 +72,7 @@ import { recordGateBlockOutcome, getGateBlockOutcome, hasActiveReviewForHeadSha, + getActiveReviewStartedAt, isDbFrozenForRepo, markGateOutcomeOverridden, markPullRequestLinkedIssueHardRuleViolated, @@ -8654,6 +8655,15 @@ async function resolveManifestPassedValidationCount( return liveCi.ciState === "passed" ? 1 : 0; } +// review turnaround-time (#4446): elapsed ms between startedAt and "now", clamped to a sane non-negative +// finite value -- a clock-skew or malformed-timestamp edge case (a future startedAt, or an unparseable one) +// degrades to undefined rather than ever letting a negative or NaN duration reach the public payload. +export function reviewDurationMsSince(startedAt: string | null, nowMs: number): number | undefined { + if (!startedAt) return undefined; + const ms = nowMs - Date.parse(startedAt); + return Number.isFinite(ms) && ms >= 0 ? ms : undefined; +} + async function maybePublishPrPublicSurface( env: Env, installationId: number, @@ -9246,6 +9256,17 @@ async function maybePublishPrPublicSurface( ) .then((effort) => effort.minutes) .catch(() => undefined); + // review turnaround-time (#4446): reuses the SAME startedAt startActiveReviewTracking already records for + // review-evasion protection -- persisted onto this SAME published event, mirroring reviewEffortMinutes' + // exact precedent above (a raw per-PR number in audit metadata; the daily rollup job aggregates it later). + // Read before terminalizeActiveReviewTracking runs later in this same pass, matched to the EXACT headSha + // being published so a race with a newer pass degrades to "no duration" (undefined), never a wrong number. + // Fail-safe: a lookup error must never block the publish audit itself. + const reviewDurationMsForStats = pr.headSha + ? await getActiveReviewStartedAt(env, repoFullName, pr.number, pr.headSha) + .then((startedAt) => reviewDurationMsSince(startedAt, Date.now())) + .catch(() => undefined) + : undefined; await recordAuditEvent(env, { eventType: "github_app.pr_public_surface_published", actor: author, @@ -9263,6 +9284,7 @@ async function maybePublishPrPublicSurface( failedOutputs, gateCheckFinalized: gateFinalized, ...(reviewEffortMinutesForStats !== undefined ? { reviewEffortMinutes: reviewEffortMinutesForStats } : {}), + ...(reviewDurationMsForStats !== undefined ? { reviewDurationMs: reviewDurationMsForStats } : {}), }, }); await recordGithubProductUsage(env, "pr_public_surface_published", { diff --git a/test/unit/db-persistence.test.ts b/test/unit/db-persistence.test.ts index 423b47f006..63af43147d 100644 --- a/test/unit/db-persistence.test.ts +++ b/test/unit/db-persistence.test.ts @@ -1,5 +1,6 @@ import { describe, expect, it } from "vitest"; import { + getActiveReviewStartedAt, getContributorScoringProfile, getOpenUpstreamDriftReportByFingerprint, hasActiveReviewForHeadSha, @@ -397,4 +398,38 @@ describe("active-review tracking (#review-evasion-protection)", () => { const row = await rawRow(env, "owner/repo", 1); expect(row?.author_login).toBeNull(); }); + + describe("getActiveReviewStartedAt (#4446)", () => { + it("returns null when no row exists at all", async () => { + const env = createTestEnv(); + expect(await getActiveReviewStartedAt(env, "owner/repo", 1, "sha1")).toBeNull(); + }); + + it("returns the row's startedAt for the exact matching headSha", async () => { + const env = createTestEnv(); + await startActiveReviewTracking(env, { repoFullName: "owner/repo", pullNumber: 1, headSha: "sha1", deliveryId: "delivery-1" }); + const row = await rawRow(env, "owner/repo", 1); + expect(await getActiveReviewStartedAt(env, "owner/repo", 1, "sha1")).toBe(row?.started_at); + }); + + it("REGRESSION: returns null for a DIFFERENT headSha than the tracked row -- never measures the wrong pass's window", async () => { + const env = createTestEnv(); + await startActiveReviewTracking(env, { repoFullName: "owner/repo", pullNumber: 1, headSha: "sha1", deliveryId: "delivery-1" }); + expect(await getActiveReviewStartedAt(env, "owner/repo", 1, "sha-different")).toBeNull(); + }); + + it("returns null for a different PR number, even under the same repo", async () => { + const env = createTestEnv(); + await startActiveReviewTracking(env, { repoFullName: "owner/repo", pullNumber: 1, headSha: "sha1", deliveryId: "delivery-1" }); + expect(await getActiveReviewStartedAt(env, "owner/repo", 2, "sha1")).toBeNull(); + }); + + it("still returns startedAt for a matching headSha AFTER the row has been terminalized -- not gated on status === 'active'", async () => { + const env = createTestEnv(); + await startActiveReviewTracking(env, { repoFullName: "owner/repo", pullNumber: 1, headSha: "sha1", deliveryId: "delivery-1" }); + const row = await rawRow(env, "owner/repo", 1); + await terminalizeActiveReviewTracking(env, "owner/repo", 1); + expect(await getActiveReviewStartedAt(env, "owner/repo", 1, "sha1")).toBe(row?.started_at); + }); + }); }); diff --git a/test/unit/queue.test.ts b/test/unit/queue.test.ts index 1ad4fd3873..88895fab64 100644 --- a/test/unit/queue.test.ts +++ b/test/unit/queue.test.ts @@ -57,7 +57,7 @@ import { listReviewSuppressions, setGlobalAgentFrozen, } from "../../src/db/repositories"; -import { agentMaintenanceHeadMatchesGate, changedPathsForGuardrail, claimAiReviewLock, claimPrActuationLock, contributorEvidenceBatchSize, enrichOpenPullRequestsWithChangedFiles, processJob, reconcileLiveDuplicateSiblings, releaseAiReviewLock, releasePrActuationLock, SWEEP_FANOUT_RESOLUTION_CONCURRENCY } from "../../src/queue/processors"; +import { agentMaintenanceHeadMatchesGate, changedPathsForGuardrail, claimAiReviewLock, claimPrActuationLock, contributorEvidenceBatchSize, enrichOpenPullRequestsWithChangedFiles, processJob, reconcileLiveDuplicateSiblings, releaseAiReviewLock, releasePrActuationLock, reviewDurationMsSince, SWEEP_FANOUT_RESOLUTION_CONCURRENCY } from "../../src/queue/processors"; import type { PullRequestRecord } from "../../src/types"; import { aiReviewCacheInputFingerprint } from "../../src/review/ai-review-cache-input"; import { fingerprint as reviewMemoryFingerprint } from "../../src/review/review-memory-match"; @@ -4028,6 +4028,136 @@ describe("queue processors", () => { expect(reputationPrepares).toHaveLength(3); // submitter_stats + review_targets quality scan + cadence scan, ONCE }); + it("INVARIANT (#4446): a real agent-regate-pr pass with AI review persists a non-negative reviewDurationMs onto the publish audit event", async () => { + const env = createTestEnv({ + GITHUB_APP_PRIVATE_KEY: await generatePrivateKeyPem(), + AI: { run: async () => ({ response: JSON.stringify({ assessment: "Looks fine.", blockers: [], nits: [], suggestions: [] }) }) } as unknown as Ai, + AI_SUMMARIES_ENABLED: "true", + AI_PUBLIC_COMMENTS_ENABLED: "true", + AI_DAILY_NEURON_BUDGET: "100000", + }); + await seedRegateChurnRepo(env); + await upsertPullRequestFromGitHub(env, "JSONbored/gittensory", { number: 63, title: "Turnaround PR", state: "open", user: { login: "contributor" }, head: { sha: "a63" }, labels: [], body: "Closes #1" }); + await upsertPullRequestDetailSyncState(env, { repoFullName: "JSONbored/gittensory", pullNumber: 63, status: "complete", reviewsSyncedAt: new Date().toISOString() }); + vi.stubGlobal("fetch", async (input: RequestInfo | URL, init?: RequestInit) => { + const url = input.toString(); + const method = init?.method ?? "GET"; + if (url.includes("/access_tokens")) return Response.json({ token: "fake-installation-token" }); + if (url.includes("/pulls/63/files")) return Response.json([{ filename: "src/a.ts", status: "modified", additions: 1, deletions: 0, changes: 1, patch: "@@\n+export const ok = true;" }]); + if (url.endsWith("/pulls/63")) return Response.json({ number: 63, title: "Turnaround PR", state: "open", user: { login: "contributor" }, head: { sha: "a63" }, labels: [], body: "Closes #1", mergeable_state: "clean" }); + if (url.includes("/commits/a63/check-runs")) return Response.json({ total_count: 0, check_runs: [] }); + if (url.includes("/commits/a63/status")) return Response.json({ state: "success", statuses: [] }); + if (url.includes("/issues/63/comments")) return method === "POST" ? Response.json({ id: 63 }, { status: 201 }) : Response.json([]); + if (url.includes("/issues/1")) return Response.json({ number: 1, title: "Issue", state: "open", labels: [], user: { login: "reporter" } }); + if (url.includes("/branches/")) return Response.json({ protected: false, protection: { required_status_checks: { contexts: [] } } }); + return Response.json({}); + }); + + await processJob(env, { type: "agent-regate-pr", deliveryId: "turnaround-capture", repoFullName: "JSONbored/gittensory", prNumber: 63, installationId: 123 }); + + const published = await env.DB.prepare("select metadata_json from audit_events where event_type = ? and target_key = ?") + .bind("github_app.pr_public_surface_published", "JSONbored/gittensory#63") + .first<{ metadata_json: string }>(); + const metadata = JSON.parse(published?.metadata_json ?? "{}"); + expect(typeof metadata.reviewDurationMs).toBe("number"); + expect(metadata.reviewDurationMs).toBeGreaterThanOrEqual(0); + }); + + it("REGRESSION (#4446): reviewDurationMs is correctly ABSENT (not a bogus 0) when no active-review-tracking row exists for this exact headSha", async () => { + const env = createTestEnv({ + GITHUB_APP_PRIVATE_KEY: await generatePrivateKeyPem(), + AI: { run: async () => ({ response: JSON.stringify({ assessment: "Looks fine.", blockers: [], nits: [], suggestions: [] }) }) } as unknown as Ai, + AI_SUMMARIES_ENABLED: "true", + AI_PUBLIC_COMMENTS_ENABLED: "true", + AI_DAILY_NEURON_BUDGET: "100000", + }); + await seedRegateChurnRepo(env, { aiReviewMode: "off" }); // AI review never runs -> startActiveReviewTracking never fires + await upsertPullRequestFromGitHub(env, "JSONbored/gittensory", { number: 64, title: "No AI review PR", state: "open", user: { login: "contributor" }, head: { sha: "a64" }, labels: [], body: "Closes #1" }); + await upsertPullRequestDetailSyncState(env, { repoFullName: "JSONbored/gittensory", pullNumber: 64, status: "complete", reviewsSyncedAt: new Date().toISOString() }); + vi.stubGlobal("fetch", async (input: RequestInfo | URL, init?: RequestInit) => { + const url = input.toString(); + const method = init?.method ?? "GET"; + if (url.includes("/access_tokens")) return Response.json({ token: "fake-installation-token" }); + if (url.includes("/pulls/64/files")) return Response.json([{ filename: "src/a.ts", status: "modified", additions: 1, deletions: 0, changes: 1, patch: "@@\n+export const ok = true;" }]); + if (url.endsWith("/pulls/64")) return Response.json({ number: 64, title: "No AI review PR", state: "open", user: { login: "contributor" }, head: { sha: "a64" }, labels: [], body: "Closes #1", mergeable_state: "clean" }); + if (url.includes("/commits/a64/check-runs")) return Response.json({ total_count: 0, check_runs: [] }); + if (url.includes("/commits/a64/status")) return Response.json({ state: "success", statuses: [] }); + if (url.includes("/issues/64/comments")) return method === "POST" ? Response.json({ id: 64 }, { status: 201 }) : Response.json([]); + if (url.includes("/issues/1")) return Response.json({ number: 1, title: "Issue", state: "open", labels: [], user: { login: "reporter" } }); + if (url.includes("/branches/")) return Response.json({ protected: false, protection: { required_status_checks: { contexts: [] } } }); + return Response.json({}); + }); + + await processJob(env, { type: "agent-regate-pr", deliveryId: "turnaround-absent", repoFullName: "JSONbored/gittensory", prNumber: 64, installationId: 123 }); + + const published = await env.DB.prepare("select metadata_json from audit_events where event_type = ? and target_key = ?") + .bind("github_app.pr_public_surface_published", "JSONbored/gittensory#64") + .first<{ metadata_json: string }>(); + const metadata = JSON.parse(published?.metadata_json ?? "{}"); + expect(metadata.reviewDurationMs).toBeUndefined(); + }); + + it("swallows a failing getActiveReviewStartedAt lookup without throwing, publishing with no reviewDurationMs (#4446)", async () => { + const env = createTestEnv({ + GITHUB_APP_PRIVATE_KEY: await generatePrivateKeyPem(), + AI: { run: async () => ({ response: JSON.stringify({ assessment: "Looks fine.", blockers: [], nits: [], suggestions: [] }) }) } as unknown as Ai, + AI_SUMMARIES_ENABLED: "true", + AI_PUBLIC_COMMENTS_ENABLED: "true", + AI_DAILY_NEURON_BUDGET: "100000", + }); + await seedRegateChurnRepo(env); + await upsertPullRequestFromGitHub(env, "JSONbored/gittensory", { number: 65, title: "Lookup failure PR", state: "open", user: { login: "contributor" }, head: { sha: "a65" }, labels: [], body: "Closes #1" }); + await upsertPullRequestDetailSyncState(env, { repoFullName: "JSONbored/gittensory", pullNumber: 65, status: "complete", reviewsSyncedAt: new Date().toISOString() }); + vi.stubGlobal("fetch", async (input: RequestInfo | URL, init?: RequestInit) => { + const url = input.toString(); + const method = init?.method ?? "GET"; + if (url.includes("/access_tokens")) return Response.json({ token: "fake-installation-token" }); + if (url.includes("/pulls/65/files")) return Response.json([{ filename: "src/a.ts", status: "modified", additions: 1, deletions: 0, changes: 1, patch: "@@\n+export const ok = true;" }]); + if (url.endsWith("/pulls/65")) return Response.json({ number: 65, title: "Lookup failure PR", state: "open", user: { login: "contributor" }, head: { sha: "a65" }, labels: [], body: "Closes #1", mergeable_state: "clean" }); + if (url.includes("/commits/a65/check-runs")) return Response.json({ total_count: 0, check_runs: [] }); + if (url.includes("/commits/a65/status")) return Response.json({ state: "success", statuses: [] }); + if (url.includes("/issues/65/comments")) return method === "POST" ? Response.json({ id: 65 }, { status: 201 }) : Response.json([]); + if (url.includes("/issues/1")) return Response.json({ number: 1, title: "Issue", state: "open", labels: [], user: { login: "reporter" } }); + if (url.includes("/branches/")) return Response.json({ protected: false, protection: { required_status_checks: { contexts: [] } } }); + return Response.json({}); + }); + const lookupSpy = vi.spyOn(repositoriesModule, "getActiveReviewStartedAt").mockRejectedValueOnce(new Error("D1 read error")); + + await expect( + processJob(env, { type: "agent-regate-pr", deliveryId: "turnaround-lookup-fail", repoFullName: "JSONbored/gittensory", prNumber: 65, installationId: 123 }), + ).resolves.toBeUndefined(); // the publish still completes — a lookup failure is best-effort, never fatal + lookupSpy.mockRestore(); + + const published = await env.DB.prepare("select metadata_json from audit_events where event_type = ? and target_key = ?") + .bind("github_app.pr_public_surface_published", "JSONbored/gittensory#65") + .first<{ metadata_json: string }>(); + const metadata = JSON.parse(published?.metadata_json ?? "{}"); + expect(metadata.reviewDurationMs).toBeUndefined(); + }); + + describe("reviewDurationMsSince (#4446, pure)", () => { + it("returns undefined for a null startedAt (no active-review-tracking row)", () => { + expect(reviewDurationMsSince(null, 1_000_000)).toBeUndefined(); + }); + + it("returns the elapsed ms for a valid past startedAt", () => { + expect(reviewDurationMsSince(new Date(1_000_000).toISOString(), 1_005_000)).toBe(5_000); + }); + + it("returns 0 for a startedAt exactly equal to now", () => { + const now = new Date(1_000_000).toISOString(); + expect(reviewDurationMsSince(now, 1_000_000)).toBe(0); + }); + + it("REGRESSION: returns undefined (not a negative number) for a startedAt in the FUTURE relative to now (clock skew)", () => { + expect(reviewDurationMsSince(new Date(2_000_000).toISOString(), 1_000_000)).toBeUndefined(); + }); + + it("REGRESSION: returns undefined (not NaN) for an unparseable startedAt string", () => { + expect(reviewDurationMsSince("not-a-real-timestamp", 1_000_000)).toBeUndefined(); + }); + }); + it("swallows a failing hit/skip audit write without throwing (cache-hit path)", async () => { const env = createTestEnv({ GITHUB_APP_PRIVATE_KEY: await generatePrivateKeyPem(),