diff --git a/src/review/grounding-wire.ts b/src/review/grounding-wire.ts index 9dcc7fe611..79f18729d8 100644 --- a/src/review/grounding-wire.ts +++ b/src/review/grounding-wire.ts @@ -13,9 +13,10 @@ import { createInstallationToken } from "../github/app"; import { githubRateLimitAdmissionKeyForInstallation, timeoutFetch, type GitHubRateLimitAdmissionKey } from "../github/client"; -import { getCachedGroundingFileContent, putCachedGroundingFileContent } from "../db/repositories"; +import { getCachedGroundingFileContent, putCachedGroundingFileContent, recordAuditEvent } from "../db/repositories"; import type { CheckSummaryRecord, PullRequestFileRecord } from "../types"; import { repoParts } from "../utils/json"; +import { incr } from "../selfhost/metrics"; import { isConvergenceRepoAllowed } from "./cutover-gate"; import { buildGrounding, @@ -141,7 +142,27 @@ export async function makeGithubFileFetcher(env: Env, repoFullName: string, inst // network fetch below; only a genuinely successful fetch is ever written back (see the .catch-free write // after the try block), so a transient failure is never mistaken for a confirmed-permanent one. const cached = await getCachedGroundingFileContent(env, repoFullName, path, ref).catch(() => null); - if (cached !== null) return cached; + if (cached !== null) { + // #4448: mirrors repo-culture-profile's #4509 cache hit/miss instrumentation exactly -- one of the six + // AI-touching capabilities that had no reuse-rate signal at all before this. + incr("gittensory_grounding_cache_hit_total"); + await recordAuditEvent(env, { + eventType: "github_app.grounding_cache_hit", + targetKey: repoFullName, + outcome: "completed", + detail: "reused a cached grounding file blob instead of re-fetching from GitHub", + metadata: { repoFullName, path }, + }).catch(() => undefined); + return cached; + } + incr("gittensory_grounding_cache_miss_total"); + await recordAuditEvent(env, { + eventType: "github_app.grounding_cache_miss", + targetKey: repoFullName, + outcome: "completed", + detail: "no reusable cached grounding file blob; fetching fresh from GitHub", + metadata: { repoFullName, path }, + }).catch(() => undefined); try { const url = `https://api.github.com/repos/${encodeURIComponent(owner)}/${encodeURIComponent(name)}/contents/${path .split("/") diff --git a/src/review/review-memory-wire.ts b/src/review/review-memory-wire.ts index c83b9c3217..a3b5bb94e4 100644 --- a/src/review/review-memory-wire.ts +++ b/src/review/review-memory-wire.ts @@ -6,9 +6,10 @@ // review path at all (the caller guards on this flag before doing any D1 read or matching), so the review // stays byte-identical to today. -import { listReviewSuppressions } from "../db/repositories"; +import { listReviewSuppressions, recordAuditEvent } from "../db/repositories"; import { matchSuppressions, type ReviewMemoryFindingInput } from "./review-memory-match"; import type { AdvisoryFinding, ReviewSuppressionRecord } from "../types"; +import { incr } from "../selfhost/metrics"; /** True when repeat-false-positive suppression is enabled at the operator level. Flag-OFF (default) → the * caller takes no new branch, so no suppression-store read and no matcher call ever happens. Truthy follows @@ -43,7 +44,27 @@ const reviewSuppressionCache = new Map { const hit = reviewSuppressionCache.get(repoFullName); - if (hit && nowMs - hit.at < REVIEW_SUPPRESSION_CACHE_TTL_MS) return hit.signals; + if (hit && nowMs - hit.at < REVIEW_SUPPRESSION_CACHE_TTL_MS) { + // #4448: mirrors repo-culture-profile's #4509 cache hit/miss instrumentation exactly -- one of the six + // AI-touching capabilities that had no reuse-rate signal at all before this. + incr("gittensory_review_memory_cache_hit_total"); + await recordAuditEvent(env, { + eventType: "github_app.review_memory_cache_hit", + targetKey: repoFullName, + outcome: "completed", + detail: "reused the in-isolate cached suppression list instead of re-reading D1", + metadata: { repoFullName }, + }).catch(() => undefined); + return hit.signals; + } + incr("gittensory_review_memory_cache_miss_total"); + await recordAuditEvent(env, { + eventType: "github_app.review_memory_cache_miss", + targetKey: repoFullName, + outcome: "completed", + detail: "no fresh cached suppression list; reading fresh from D1", + metadata: { repoFullName }, + }).catch(() => undefined); const signals = await listReviewSuppressions(env, repoFullName); reviewSuppressionCache.set(repoFullName, { signals, at: nowMs }); return signals; diff --git a/test/unit/grounding-wiring.test.ts b/test/unit/grounding-wiring.test.ts index 6f18746b48..ad7b88e35e 100644 --- a/test/unit/grounding-wiring.test.ts +++ b/test/unit/grounding-wiring.test.ts @@ -1,4 +1,4 @@ -import { describe, expect, it, vi } from "vitest"; +import { afterEach, describe, expect, it, vi } from "vitest"; import { runGittensoryAiReview } from "../../src/services/ai-review"; import { runAiReviewForAdvisory } from "../../src/queue/processors"; import { @@ -9,8 +9,10 @@ import { makeGithubFileFetcher, } from "../../src/review/grounding-wire"; import { getCachedGroundingFileContent, putCachedGroundingFileContent, upsertCheckSummary, upsertRepositoryFromGitHub } from "../../src/db/repositories"; +import * as repositoriesModule from "../../src/db/repositories"; import * as githubApp from "../../src/github/app"; import { githubRateLimitAdmissionKeyForInstallation, latestGitHubRestRateLimitObservation } from "../../src/github/client"; +import { renderMetrics, resetMetrics } from "../../src/selfhost/metrics"; import type { Advisory, CheckSummaryRecord, JsonValue, PullRequestFileRecord, RepositorySettings } from "../../src/types"; import { createTestEnv } from "../helpers/d1"; @@ -398,6 +400,76 @@ describe("makeGithubFileFetcher (GitHub Contents-API-backed FileFetcher)", () => fetchSpy.mockRestore(); }); + describe("cache hit/miss telemetry (#4448)", () => { + afterEach(() => resetMetrics()); + + async function auditEvent(env: Env, eventType: string, repoFullName: string) { + return env.DB.prepare("SELECT outcome, target_key FROM audit_events WHERE event_type = ? AND target_key = ?") + .bind(eventType, repoFullName) + .first<{ outcome: string; target_key: string }>(); + } + + it("INVARIANT: a cache HIT fires exactly the hit counter/audit-event pair, and NOT the miss pair", async () => { + const env = createTestEnv({ GITHUB_PUBLIC_TOKEN: "ghp_test" }); + const fetchSpy = vi.spyOn(globalThis, "fetch").mockImplementation(async () => new Response("export const v = 1;", { status: 200 })); + await (await makeGithubFileFetcher(env, "acme/telemetry", null)).getFileContent("hit.ts", "sha7"); // first call: a miss + resetMetrics(); + await env.DB.prepare("DELETE FROM audit_events").run(); // isolate to the SECOND call's telemetry only + + const second = await (await makeGithubFileFetcher(env, "acme/telemetry", null)).getFileContent("hit.ts", "sha7"); // same (repo, path, ref) -- a hit + expect(second).toBe("export const v = 1;"); + + const rendered = await renderMetrics(); + expect(rendered).toContain("gittensory_grounding_cache_hit_total 1"); + expect(rendered).not.toContain("gittensory_grounding_cache_miss_total"); + const hitEvent = await auditEvent(env, "github_app.grounding_cache_hit", "acme/telemetry"); + expect(hitEvent?.outcome).toBe("completed"); + expect(await auditEvent(env, "github_app.grounding_cache_miss", "acme/telemetry")).toBeUndefined(); + fetchSpy.mockRestore(); + }); + + it("INVARIANT: a cache MISS fires exactly the miss counter/audit-event pair, and NOT the hit pair", async () => { + const env = createTestEnv({ GITHUB_PUBLIC_TOKEN: "ghp_test" }); + const fetchSpy = vi.spyOn(globalThis, "fetch").mockImplementation(async () => new Response("export const v = 1;", { status: 200 })); + + const first = await (await makeGithubFileFetcher(env, "acme/telemetry", null)).getFileContent("miss.ts", "sha7"); + expect(first).toBe("export const v = 1;"); + + const rendered = await renderMetrics(); + expect(rendered).toContain("gittensory_grounding_cache_miss_total 1"); + expect(rendered).not.toContain("gittensory_grounding_cache_hit_total"); + const missEvent = await auditEvent(env, "github_app.grounding_cache_miss", "acme/telemetry"); + expect(missEvent?.outcome).toBe("completed"); + expect(await auditEvent(env, "github_app.grounding_cache_hit", "acme/telemetry")).toBeUndefined(); + fetchSpy.mockRestore(); + }); + + it("swallows a failing cache-hit audit-event write without throwing, still returning the cached content", async () => { + const env = createTestEnv({ GITHUB_PUBLIC_TOKEN: "ghp_test" }); + const fetchSpy = vi.spyOn(globalThis, "fetch").mockImplementation(async () => new Response("export const v = 1;", { status: 200 })); + await (await makeGithubFileFetcher(env, "acme/telemetry", null)).getFileContent("swallow.ts", "sha7"); // populates the cache + + const writeSpy = vi.spyOn(repositoriesModule, "recordAuditEvent").mockRejectedValueOnce(new Error("D1 write error")); + const second = await (await makeGithubFileFetcher(env, "acme/telemetry", null)).getFileContent("swallow.ts", "sha7"); // a cache hit + writeSpy.mockRestore(); + + expect(second).toBe("export const v = 1;"); // the failed audit write never surfaces to the caller + fetchSpy.mockRestore(); + }); + + it("swallows a failing cache-MISS audit-event write without throwing, still returning the freshly-fetched content", async () => { + const env = createTestEnv({ GITHUB_PUBLIC_TOKEN: "ghp_test" }); + const fetchSpy = vi.spyOn(globalThis, "fetch").mockImplementation(async () => new Response("export const v = 1;", { status: 200 })); + + const writeSpy = vi.spyOn(repositoriesModule, "recordAuditEvent").mockRejectedValueOnce(new Error("D1 write error")); + const first = await (await makeGithubFileFetcher(env, "acme/telemetry", null)).getFileContent("miss-swallow.ts", "sha7"); // cold cache -- a miss + writeSpy.mockRestore(); + + expect(first).toBe("export const v = 1;"); // the failed audit write never surfaces to the caller, fetch still happens + fetchSpy.mockRestore(); + }); + }); + it("REGRESSION (#4499, grounding-refetch incident): repeated cooldown-driven calls on an unchanged head SHA only fetch once total, not once per call", async () => { const env = createTestEnv({ GITHUB_PUBLIC_TOKEN: "ghp_test" }); let fetchCount = 0; diff --git a/test/unit/review-memory-store.test.ts b/test/unit/review-memory-store.test.ts index 24f1010a67..3b3b292f17 100644 --- a/test/unit/review-memory-store.test.ts +++ b/test/unit/review-memory-store.test.ts @@ -1,7 +1,8 @@ -import { describe, expect, it, vi } from "vitest"; +import { afterEach, describe, expect, it, vi } from "vitest"; import { MAX_REVIEW_SUPPRESSIONS_PER_REPO, listReviewSuppressions, recordReviewSuppression } from "../../src/db/repositories"; import * as repositoriesModule from "../../src/db/repositories"; import { clearReviewSuppressionCacheForTest, getCachedReviewSuppressions, invalidateReviewSuppressionCache } from "../../src/review/review-memory-wire"; +import { renderMetrics, resetMetrics } from "../../src/selfhost/metrics"; import { createTestEnv } from "../helpers/d1"; // Review memory (#2178, data-model slice of #1964): insert/list repository accessors over the @@ -266,3 +267,87 @@ describe("getCachedReviewSuppressions / invalidateReviewSuppressionCache (#4508) expect(b).toHaveLength(0); }); }); + +describe("getCachedReviewSuppressions: cache hit/miss telemetry (#4448)", () => { + afterEach(() => resetMetrics()); + + async function auditEvent(env: Env, eventType: string, repoFullName: string) { + return env.DB.prepare("SELECT outcome, target_key FROM audit_events WHERE event_type = ? AND target_key = ?") + .bind(eventType, repoFullName) + .first<{ outcome: string; target_key: string }>(); + } + + it("INVARIANT: a cache HIT (within TTL) fires exactly the hit counter/audit-event pair, and NOT the miss pair", async () => { + clearReviewSuppressionCacheForTest(); + const env = createTestEnv(); + const t0 = 5_000_000; + await getCachedReviewSuppressions(env, "owner/telemetry-repo", t0); // first call: a miss (cold cache) + resetMetrics(); + await env.DB.prepare("DELETE FROM audit_events").run(); // isolate to the SECOND call's telemetry only + + const second = await getCachedReviewSuppressions(env, "owner/telemetry-repo", t0 + 30_000); // within the 60s TTL + expect(second).toEqual([]); + + const rendered = await renderMetrics(); + expect(rendered).toContain("gittensory_review_memory_cache_hit_total 1"); + expect(rendered).not.toContain("gittensory_review_memory_cache_miss_total"); + const hitEvent = await auditEvent(env, "github_app.review_memory_cache_hit", "owner/telemetry-repo"); + expect(hitEvent?.outcome).toBe("completed"); + expect(await auditEvent(env, "github_app.review_memory_cache_miss", "owner/telemetry-repo")).toBeUndefined(); + }); + + it("INVARIANT: a cache MISS (cold cache) fires exactly the miss counter/audit-event pair, and NOT the hit pair", async () => { + clearReviewSuppressionCacheForTest(); + const env = createTestEnv(); + const first = await getCachedReviewSuppressions(env, "owner/telemetry-repo-2", 6_000_000); + expect(first).toEqual([]); + + const rendered = await renderMetrics(); + expect(rendered).toContain("gittensory_review_memory_cache_miss_total 1"); + expect(rendered).not.toContain("gittensory_review_memory_cache_hit_total"); + const missEvent = await auditEvent(env, "github_app.review_memory_cache_miss", "owner/telemetry-repo-2"); + expect(missEvent?.outcome).toBe("completed"); + expect(await auditEvent(env, "github_app.review_memory_cache_hit", "owner/telemetry-repo-2")).toBeUndefined(); + }); + + it("REGRESSION: TTL expiry is correctly counted as a miss, not silently uninstrumented", async () => { + clearReviewSuppressionCacheForTest(); + const env = createTestEnv(); + const t0 = 7_000_000; + await getCachedReviewSuppressions(env, "owner/telemetry-repo-3", t0); // populates the cache + resetMetrics(); + await env.DB.prepare("DELETE FROM audit_events").run(); + + await getCachedReviewSuppressions(env, "owner/telemetry-repo-3", t0 + 60_001); // past the 60s TTL + + const rendered = await renderMetrics(); + expect(rendered).toContain("gittensory_review_memory_cache_miss_total 1"); + expect(rendered).not.toContain("gittensory_review_memory_cache_hit_total"); + }); + + it("swallows a failing cache-hit audit-event write without throwing, still returning the cached suppression list", async () => { + clearReviewSuppressionCacheForTest(); + const env = createTestEnv(); + const t0 = 8_000_000; + await recordReviewSuppression(env, { repoFullName: "owner/telemetry-repo-4", category: "ai_review_split", patternHash: "hash-swallow" }); + await getCachedReviewSuppressions(env, "owner/telemetry-repo-4", t0); // populates the cache + + const writeSpy = vi.spyOn(repositoriesModule, "recordAuditEvent").mockRejectedValueOnce(new Error("D1 write error")); + const second = await getCachedReviewSuppressions(env, "owner/telemetry-repo-4", t0 + 30_000); // a cache hit + writeSpy.mockRestore(); + + expect(second).toHaveLength(1); // the failed audit write never surfaces to the caller + }); + + it("swallows a failing cache-MISS audit-event write without throwing, still returning the freshly-read suppression list", async () => { + clearReviewSuppressionCacheForTest(); + const env = createTestEnv(); + await recordReviewSuppression(env, { repoFullName: "owner/telemetry-repo-5", category: "ai_review_split", patternHash: "hash-miss-swallow" }); + + const writeSpy = vi.spyOn(repositoriesModule, "recordAuditEvent").mockRejectedValueOnce(new Error("D1 write error")); + const first = await getCachedReviewSuppressions(env, "owner/telemetry-repo-5", 9_000_000); // cold cache -- a miss + writeSpy.mockRestore(); + + expect(first).toHaveLength(1); // the failed audit write never surfaces to the caller, D1 read still happens + }); +});