diff --git a/src/review/repo-culture-profile.ts b/src/review/repo-culture-profile.ts index 87e686cfcc..044e2a0ba7 100644 --- a/src/review/repo-culture-profile.ts +++ b/src/review/repo-culture-profile.ts @@ -23,8 +23,9 @@ // explicit `{ present: false, reason }` branch, never a partial/misleading guess -- callers must treat that as // "no grounding to add", never a signal in itself, and NEVER a gate/scoring input (this is advisory prompt // context only, per the issue's explicit "no new scored gate dimension" requirement). -import { listSignalSnapshots, persistSignalSnapshot } from "../db/repositories"; +import { listSignalSnapshots, persistSignalSnapshot, recordAuditEvent } from "../db/repositories"; import { countRecentMergedPullRequests, listRecentMergedPullRequests } from "../db/repositories"; +import { incr } from "../selfhost/metrics"; import type { RecentMergedPullRequestRecord } from "../types"; import { nowIso } from "../utils/json"; @@ -280,8 +281,31 @@ export async function extractRepoCultureProfile(env: Env, repoFullName: string, const maxAgeMs = options.maxAgeMs ?? REPO_CULTURE_PROFILE_MAX_AGE_MS; if (!options.refresh) { const cached = await readCachedCultureProfile(env, repoFullName, maxAgeMs); - if (cached) return cached; + if (cached) { + // #4509: mirrors the ai_review cache's hit/miss instrumentation (processors.ts) exactly -- this cache + // works correctly (unlike the #4481 linked_issue_satisfaction bug class) but previously had zero + // hit/miss telemetry, one of the six capability gaps #4448 identified. readCachedCultureProfile's null + // return covers EVERY invalidation reason uniformly (no snapshot, TTL expiry, drift, malformed row), so + // this single hit/miss branch point correctly counts the merged-PR-count drift path as a miss too. + incr("gittensory_repo_culture_profile_cache_hit_total"); + await recordAuditEvent(env, { + eventType: "github_app.repo_culture_profile_cache_hit", + targetKey: repoFullName, + outcome: "completed", + detail: "reused a cached repo-culture profile instead of re-deriving from merged-PR history", + metadata: { repoFullName }, + }).catch(() => undefined); + return cached; + } } + incr("gittensory_repo_culture_profile_cache_miss_total"); + await recordAuditEvent(env, { + eventType: "github_app.repo_culture_profile_cache_miss", + targetKey: repoFullName, + outcome: "completed", + detail: "no reusable cached repo-culture profile; deriving fresh from merged-PR history", + metadata: { repoFullName }, + }).catch(() => undefined); try { const prs = await listRecentMergedPullRequests(env, repoFullName); const sampleCountAtGeneration = await countRecentMergedPullRequests(env, repoFullName); diff --git a/test/unit/repo-culture-profile.test.ts b/test/unit/repo-culture-profile.test.ts index 379c3a8fdd..393762a287 100644 --- a/test/unit/repo-culture-profile.test.ts +++ b/test/unit/repo-culture-profile.test.ts @@ -1,5 +1,6 @@ -import { describe, expect, it, vi } from "vitest"; +import { afterEach, describe, expect, it, vi } from "vitest"; import { upsertRecentMergedPullRequest } from "../../src/db/repositories"; +import * as repositoriesModule from "../../src/db/repositories"; import { deriveRepoCultureProfile, extractRepoCultureProfile, @@ -7,6 +8,7 @@ import { prSizeBand, REPO_CULTURE_PROFILE_SCHEMA_VERSION, } from "../../src/review/repo-culture-profile"; +import { renderMetrics, resetMetrics } from "../../src/selfhost/metrics"; import type { RecentMergedPullRequestRecord } from "../../src/types"; import { createTestEnv } from "../helpers/d1"; @@ -436,3 +438,87 @@ describe("extractRepoCultureProfile: cache + invalidation", () => { expect(profile.commonLabels).toEqual([{ label: "", frequency: 0 }]); }); }); + +// ── cache hit/miss telemetry (#4509) ──────────────────────────────────────────────────────────── + +describe("extractRepoCultureProfile: cache hit/miss telemetry (#4509)", () => { + afterEach(() => resetMetrics()); + + async function auditEvent(env: ReturnType, eventType: string) { + return env.DB.prepare("SELECT outcome, target_key FROM audit_events WHERE event_type = ? AND target_key = ?") + .bind(eventType, REPO) + .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({}); + for (let i = 1; i <= MIN_SAMPLE_PULL_REQUESTS; i++) await seedMergedPr(env, { number: i }); + await extractRepoCultureProfile(env, REPO, { now: "2026-07-05T00:00:00.000Z" }); // 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 extractRepoCultureProfile(env, REPO, { now: "2026-07-05T00:30:00.000Z" }); // within TTL, no drift + expect(second.present).toBe(true); + + const rendered = await renderMetrics(); + expect(rendered).toContain("gittensory_repo_culture_profile_cache_hit_total 1"); + expect(rendered).not.toContain("gittensory_repo_culture_profile_cache_miss_total"); + const hitEvent = await auditEvent(env, "github_app.repo_culture_profile_cache_hit"); + expect(hitEvent?.outcome).toBe("completed"); + expect(await auditEvent(env, "github_app.repo_culture_profile_cache_miss")).toBeUndefined(); + }); + + it("swallows a failing cache-hit audit-event write without throwing, still returning the cached profile", async () => { + const env = createTestEnv({}); + for (let i = 1; i <= MIN_SAMPLE_PULL_REQUESTS; i++) await seedMergedPr(env, { number: i }); + await extractRepoCultureProfile(env, REPO, { now: "2026-07-05T00:00:00.000Z" }); // populates the cache + + const writeSpy = vi.spyOn(repositoriesModule, "recordAuditEvent").mockRejectedValueOnce(new Error("D1 write error")); + const second = await extractRepoCultureProfile(env, REPO, { now: "2026-07-05T00:30:00.000Z" }); // a cache hit + writeSpy.mockRestore(); + + expect(second.present).toBe(true); // the failed audit write never surfaces to the caller + }); + + it("INVARIANT: a cache MISS (TTL expired) fires exactly the miss counter/audit-event pair, and NOT the hit pair", async () => { + const env = createTestEnv({}); + for (let i = 1; i <= MIN_SAMPLE_PULL_REQUESTS; i++) await seedMergedPr(env, { number: i }); + await extractRepoCultureProfile(env, REPO, { now: "2026-07-05T00:00:00.000Z" }); // first call populates the cache + resetMetrics(); + await env.DB.prepare("DELETE FROM audit_events").run(); + + // maxAgeMs: -1 makes the freshly-written snapshot immediately stale, forcing a miss/re-derive. + const second = await extractRepoCultureProfile(env, REPO, { now: "2026-07-05T00:00:00.000Z", maxAgeMs: -1 }); + expect(second.present).toBe(true); + + const rendered = await renderMetrics(); + expect(rendered).toContain("gittensory_repo_culture_profile_cache_miss_total 1"); + expect(rendered).not.toContain("gittensory_repo_culture_profile_cache_hit_total"); + const missEvent = await auditEvent(env, "github_app.repo_culture_profile_cache_miss"); + expect(missEvent?.outcome).toBe("completed"); + expect(await auditEvent(env, "github_app.repo_culture_profile_cache_hit")).toBeUndefined(); + }); + + it("REGRESSION: the merged-PR-count drift-invalidation path is correctly counted as a miss, not silently uninstrumented", async () => { + const env = createTestEnv({}); + for (let i = 1; i <= MIN_SAMPLE_PULL_REQUESTS; i++) await seedMergedPr(env, { number: i }); + const first = await extractRepoCultureProfile(env, REPO, { now: "2026-07-05T00:00:00.000Z" }); + expect(first.present).toBe(true); + + // A new merged PR lands — the cached snapshot's sampleCountAtGeneration no longer matches the live COUNT, + // even though the TTL (maxAgeMs: POSITIVE_INFINITY below) never expires. + await seedMergedPr(env, { number: MIN_SAMPLE_PULL_REQUESTS + 1 }); + resetMetrics(); + await env.DB.prepare("DELETE FROM audit_events").run(); + + const refreshed = await extractRepoCultureProfile(env, REPO, { now: "2026-07-05T01:00:00.000Z", maxAgeMs: Number.POSITIVE_INFINITY }); + expect(refreshed.present).toBe(true); + if (!refreshed.present) throw new Error("expected present profile"); + expect(refreshed.pullRequestNorms.sampleSize).toBe(MIN_SAMPLE_PULL_REQUESTS + 1); // confirms the drift path actually re-derived + + const rendered = await renderMetrics(); + expect(rendered).toContain("gittensory_repo_culture_profile_cache_miss_total 1"); + expect(rendered).not.toContain("gittensory_repo_culture_profile_cache_hit_total"); + expect((await auditEvent(env, "github_app.repo_culture_profile_cache_miss"))?.outcome).toBe("completed"); + }); +});