diff --git a/review-enrichment/src/brief.ts b/review-enrichment/src/brief.ts index 03a4dce560..0fe9c9e348 100644 --- a/review-enrichment/src/brief.ts +++ b/review-enrichment/src/brief.ts @@ -24,6 +24,7 @@ import { type AnalysisContext, } from "./analysis-context.js"; import { ANALYZERS } from "./analyzers/registry.js"; +import { incr, observe } from "./metrics.js"; import { renderBrief } from "./render.js"; import { COST_ORDER, @@ -199,6 +200,13 @@ function captureDegradation( }); } +/** Records one analyzer's outcome for the run. `elapsedMs` is omitted for a skip/cap that never actually + * invoked the analyzer function (scheduling overhead isn't real analyzer execution time). */ +function recordAnalyzerOutcome(name: string, status: AnalyzerStatus, elapsedMs?: number): void { + incr("rees_analyzer_runs_total", { analyzer: name, status }); + if (elapsedMs !== undefined) observe("rees_analyzer_duration_seconds", elapsedMs / 1000, { analyzer: name }); +} + function attachAnalysisMetrics( diagnostics: AnalyzerDiagnostics, analysis: AnalysisContext, @@ -242,6 +250,7 @@ export async function buildBrief( costClass: item.descriptor.cost, skipReason: item.skipReason, }; + recordAnalyzerOutcome(item.name, "skipped"); } async function runAnalyzer(item: AnalyzerPlanItem): Promise { @@ -263,6 +272,7 @@ export async function buildBrief( }; partial = true; analysis.metrics.recordCappedWork("analyzer_budget", 1); + recordAnalyzerOutcome(name, "capped"); // #2541: budget exhaustion, not a dependency-health signal -- if this call had claimed the circuit // breaker's half-open probe (isAnalyzerCircuitOpen), free it so a later request can still probe rather // than leaving the slot claimed forever with no outcome ever recorded. @@ -288,6 +298,7 @@ export async function buildBrief( }; partial = true; analysis.metrics.recordCappedWork(`analyzer_${item.descriptor.cost}`, 1); + recordAnalyzerOutcome(name, "capped"); // #2541: same as above -- release a claimed half-open probe without recording an outcome. releaseAnalyzerCircuitProbe(name, req); return; @@ -319,15 +330,17 @@ export async function buildBrief( status === "capped" ? "analyzer_capped" : "analyzer_partial", ); analyzerStatus[name] = status; + const elapsedMs = Date.now() - analyzerStartedAt; analyzerTelemetry[name] = { status, - elapsedMs: Date.now() - analyzerStartedAt, + elapsedMs, timeoutMs, costClass: item.descriptor.cost, partialStatus: "partial", partialReason, capped: status === "capped" || diagnostics.capped, }; + recordAnalyzerOutcome(name, status, elapsedMs); partial = true; diagnostics.partialStatus = "partial"; diagnostics.partialReason = partialReason; @@ -349,13 +362,15 @@ export async function buildBrief( } } else { analyzerStatus[name] = "ok"; + const elapsedMs = Date.now() - analyzerStartedAt; analyzerTelemetry[name] = { status: "ok", - elapsedMs: Date.now() - analyzerStartedAt, + elapsedMs, timeoutMs, costClass: item.descriptor.cost, partialStatus: diagnostics.partialStatus, }; + recordAnalyzerOutcome(name, "ok", elapsedMs); } } catch (error) { // #2541: a THROWN failure (including the analyzer_timeout rejection from runWithTimeout) is the signal @@ -365,15 +380,17 @@ export async function buildBrief( const status = timeoutStatus(error, diagnostics); const partialReason = publicPartialReason(diagnostics.partialReason, "analyzer_error"); analyzerStatus[name] = status; + const elapsedMs = Date.now() - analyzerStartedAt; analyzerTelemetry[name] = { status, - elapsedMs: Date.now() - analyzerStartedAt, + elapsedMs, timeoutMs, costClass: item.descriptor.cost, partialStatus: "partial", partialReason, capped: status === "capped" || diagnostics.capped, }; + recordAnalyzerOutcome(name, status, elapsedMs); partial = true; diagnostics.partialStatus = "partial"; diagnostics.partialReason = partialReason; @@ -424,6 +441,7 @@ export async function buildBrief( elapsedMs: 0, skipReason: "not_requested", }; + recordAnalyzerOutcome(name, "skipped"); } const { promptSection, systemSuffix } = renderBrief( diff --git a/review-enrichment/src/metrics.ts b/review-enrichment/src/metrics.ts new file mode 100644 index 0000000000..039a8e3d84 --- /dev/null +++ b/review-enrichment/src/metrics.ts @@ -0,0 +1,121 @@ +// Minimal Prometheus text-format metrics for REES (#5367 observability). A tiny in-process registry — +// counters (monotonic, incremented at the call site) and histograms (latency distributions observed at the +// call site) — rendered at GET /metrics. Deliberately smaller than the main app's src/selfhost/metrics.ts: +// REES is a separate deployable (own package, own build, sometimes deployed standalone on Railway) and has no +// gauges, dynamic label-set gauges, or per-repo redaction needs today, so those pieces aren't duplicated here. +type Labels = Record; +type MetricType = "counter" | "histogram"; + +export type MetricMeta = { + help: string; + type: MetricType; +}; + +interface HistogramState { + name: string; + labels: Labels | undefined; + buckets: number[]; // upper bounds (le), ascending + counts: number[]; // cumulative count of observations <= buckets[i] + sum: number; + count: number; +} + +const counters = new Map(); +const histograms = new Map(); + +export const DEFAULT_METRIC_META: readonly (readonly [string, MetricMeta])[] = [ + ["rees_enrich_requests_total", { help: "REES /v1/enrich call outcomes, by status (ok/unauthorized/service_not_configured/bad_request/error).", type: "counter" }], + ["rees_enrich_request_duration_seconds", { help: "REES /v1/enrich request handling duration in seconds.", type: "histogram" }], + ["rees_analyzer_runs_total", { help: "REES analyzer run outcomes, by analyzer name and status (ok/degraded/timeout/capped/skipped).", type: "counter" }], + ["rees_analyzer_duration_seconds", { help: "REES per-analyzer execution duration in seconds, for analyzers that actually ran (ok/degraded/timeout).", type: "histogram" }], +]; +const metricMeta = new Map(DEFAULT_METRIC_META); + +// Request-latency buckets in seconds (Prometheus convention). Covers sub-ms analyzer checks through a +// multi-second full /v1/enrich pass under the "deep" profile. +export const DEFAULT_BUCKETS = [0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10]; + +function seriesKey(name: string, labels?: Labels): string { + if (!labels || Object.keys(labels).length === 0) return name; + const inner = Object.entries(labels) + .sort(([a], [b]) => a.localeCompare(b)) + .map(([k, v]) => `${k}="${String(v).replace(/"/g, '\\"')}"`) + .join(","); + return `${name}{${inner}}`; +} + +function metricNameFromSeriesKey(key: string): string { + const labelsStart = key.indexOf("{"); + return labelsStart === -1 ? key : key.slice(0, labelsStart); +} + +function escapeHelpText(help: string): string { + return help.replace(/\\/g, "\\\\").replace(/\n/g, "\\n"); +} + +function pushMetricMeta(lines: string[], emitted: Set, name: string): void { + if (emitted.has(name)) return; + const meta = metricMeta.get(name); + if (!meta) return; + lines.push(`# HELP ${name} ${escapeHelpText(meta.help)}`); + lines.push(`# TYPE ${name} ${meta.type}`); + emitted.add(name); +} + +/** Increment a monotonic counter (created on first use). */ +export function incr(name: string, labels?: Labels, by = 1): void { + const k = seriesKey(name, labels); + counters.set(k, (counters.get(k) ?? 0) + by); +} + +/** Read a counter's current value (0 when the series has never been incremented). Test/introspection only. */ +export function counterValue(name: string, labels?: Labels): number { + const k = seriesKey(name, labels); + const value = counters.get(k); + return typeof value === "number" && Number.isFinite(value) ? value : 0; +} + +/** Observe a value into a histogram (created on first use). `buckets` must be ascending upper bounds. */ +export function observe(name: string, value: number, labels?: Labels, buckets: number[] = DEFAULT_BUCKETS): void { + const k = seriesKey(name, labels); + let h = histograms.get(k); + if (!h) { + h = { name, labels, buckets, counts: new Array(buckets.length).fill(0), sum: 0, count: 0 }; + histograms.set(k, h); + } + // Cumulative bucketing: bump every bucket whose upper bound is >= the value. + for (let i = 0; i < h.buckets.length; i++) { + if (value <= h.buckets[i]!) h.counts[i]!++; + } + h.sum += value; + h.count += 1; +} + +/** Render the registry in Prometheus text exposition format. */ +export function renderMetrics(): string { + const lines: string[] = []; + const emittedMeta = new Set(); + for (const [k, v] of counters) { + pushMetricMeta(lines, emittedMeta, metricNameFromSeriesKey(k)); + lines.push(`${k} ${v}`); + } + for (const h of histograms.values()) { + pushMetricMeta(lines, emittedMeta, h.name); + for (let i = 0; i < h.buckets.length; i++) { + lines.push(`${seriesKey(`${h.name}_bucket`, { ...h.labels, le: String(h.buckets[i]) })} ${h.counts[i]}`); + } + // The +Inf bucket equals the total observation count (Prometheus requires it). + lines.push(`${seriesKey(`${h.name}_bucket`, { ...h.labels, le: "+Inf" })} ${h.count}`); + lines.push(`${seriesKey(`${h.name}_sum`, h.labels)} ${h.sum}`); + lines.push(`${seriesKey(`${h.name}_count`, h.labels)} ${h.count}`); + } + return `${lines.join("\n")}\n`; +} + +/** Test-only: clear all series and restore built-in metric metadata. */ +export function resetMetrics(): void { + counters.clear(); + histograms.clear(); + metricMeta.clear(); + for (const [name, meta] of DEFAULT_METRIC_META) metricMeta.set(name, meta); +} diff --git a/review-enrichment/src/server.ts b/review-enrichment/src/server.ts index 6cbb9c1146..a05996871d 100644 --- a/review-enrichment/src/server.ts +++ b/review-enrichment/src/server.ts @@ -11,6 +11,7 @@ import { serve } from "@hono/node-server"; import { Hono } from "hono"; import { normalizeSharedSecret, verifyBearer } from "./auth.js"; import { buildBrief } from "./brief.js"; +import { incr, observe, renderMetrics } from "./metrics.js"; import { parseEnrichRequestBody, readEnrichRequestText, @@ -45,6 +46,12 @@ app.get("/health", (c) => c.json({ status: "ok", service: "review-enrichment" }), ); app.get("/ready", (c) => c.json({ ready: true })); +app.get("/metrics", (c) => c.text(renderMetrics())); + +function recordEnrichOutcome(status: string, startedAtMs: number): void { + incr("rees_enrich_requests_total", { status }); + observe("rees_enrich_request_duration_seconds", (Date.now() - startedAtMs) / 1000); +} app.onError((error, c) => { captureRouteError(error, { method: c.req.method, route: c.req.path }); @@ -62,23 +69,43 @@ app.post("/v1/ping", (c) => { }); app.post("/v1/enrich", async (c) => { - const secret = normalizeSharedSecret(process.env.REES_SHARED_SECRET); - // No secret configured ⇒ the service is not ready to authenticate anything; fail closed. - if (!secret) return c.json({ error: "service_not_configured" }, 503); - if (!verifyBearer(c.req.header("authorization"), secret)) - return c.json({ error: "unauthorized" }, 401); + const startedAtMs = Date.now(); + try { + const secret = normalizeSharedSecret(process.env.REES_SHARED_SECRET); + // No secret configured ⇒ the service is not ready to authenticate anything; fail closed. + if (!secret) { + recordEnrichOutcome("service_not_configured", startedAtMs); + return c.json({ error: "service_not_configured" }, 503); + } + if (!verifyBearer(c.req.header("authorization"), secret)) { + recordEnrichOutcome("unauthorized", startedAtMs); + return c.json({ error: "unauthorized" }, 401); + } - const body = await readEnrichRequestText(c.req.raw); - if (!body.ok) return c.json({ error: body.error }, body.status); + const body = await readEnrichRequestText(c.req.raw); + if (!body.ok) { + recordEnrichOutcome("bad_request", startedAtMs); + return c.json({ error: body.error }, body.status); + } - const parsed = parseEnrichRequestBody(body.raw); - if (!parsed.ok) return c.json({ error: parsed.error }, parsed.status); + const parsed = parseEnrichRequestBody(body.raw); + if (!parsed.ok) { + recordEnrichOutcome("bad_request", startedAtMs); + return c.json({ error: parsed.error }, parsed.status); + } - const brief = await buildBrief(parsed.payload, undefined, { - requestId: c.req.header("x-gittensory-request-id") ?? c.req.header("x-request-id"), - traceId: traceIdFromTraceparent(c.req.header("traceparent")), - }); - return c.json(brief); + const brief = await buildBrief(parsed.payload, undefined, { + requestId: c.req.header("x-gittensory-request-id") ?? c.req.header("x-request-id"), + traceId: traceIdFromTraceparent(c.req.header("traceparent")), + }); + recordEnrichOutcome("ok", startedAtMs); + return c.json(brief); + } catch (error) { + // Rethrow to app.onError below, which still owns the 500 response + Sentry capture -- this catch exists + // only to record the outcome with the duration/startedAtMs this route handler has and onError doesn't. + recordEnrichOutcome("error", startedAtMs); + throw error; + } }); const port = Number(process.env.PORT ?? "8080"); diff --git a/review-enrichment/test/brief-metrics.test.ts b/review-enrichment/test/brief-metrics.test.ts new file mode 100644 index 0000000000..5f4f252a02 --- /dev/null +++ b/review-enrichment/test/brief-metrics.test.ts @@ -0,0 +1,72 @@ +import assert from "node:assert/strict"; +import { beforeEach, test } from "node:test"; + +import { buildBrief } from "../dist/brief.js"; +import { counterValue, resetMetrics } from "../dist/metrics.js"; + +const baseReq = { + repoFullName: "o/r", + prNumber: 1, + diff: "@@ -1 +1 @@", + files: [{ path: "a.ts", patch: "@@ -1 +1 @@" }], +}; + +beforeEach(() => { + resetMetrics(); +}); + +test("records an 'ok' outcome + a duration observation for an analyzer that resolves cleanly", async () => { + await buildBrief( + { ...baseReq, analyzers: ["todoMarker"] }, + { todoMarker: async () => [] }, + ); + assert.equal(counterValue("rees_analyzer_runs_total", { analyzer: "todoMarker", status: "ok" }), 1); + assert.equal(counterValue("rees_analyzer_runs_total", { analyzer: "todoMarker", status: "degraded" }), 0); +}); + +test("records a 'degraded' outcome when the analyzer's result reports partial:true", async () => { + await buildBrief( + { ...baseReq, analyzers: ["todoMarker"] }, + { todoMarker: async () => [{ partial: true }] }, + ); + assert.equal(counterValue("rees_analyzer_runs_total", { analyzer: "todoMarker", status: "degraded" }), 1); +}); + +test("records a 'timeout' outcome when the analyzer never resolves within its budget", async () => { + // No explicit budget override: the default "balanced" profile gives a "local"-cost analyzer a 750ms + // per-analyzer timeout (see scheduler.ts's PROFILE_CONFIG), comfortably below this test's own timeout. + await buildBrief( + { ...baseReq, analyzers: ["todoMarker"] }, + { todoMarker: () => new Promise(() => {}) }, // never resolves + ); + assert.equal(counterValue("rees_analyzer_runs_total", { analyzer: "todoMarker", status: "timeout" }), 1); +}); + +test("records a degraded/error outcome when the analyzer throws synchronously", async () => { + await buildBrief( + { ...baseReq, analyzers: ["todoMarker"] }, + { + todoMarker: async () => { + throw new Error("boom"); + }, + }, + ); + // A thrown (non-timeout) failure resolves to "degraded" via timeoutStatus's statusFromDiagnostics fallback. + assert.equal(counterValue("rees_analyzer_runs_total", { analyzer: "todoMarker", status: "degraded" }), 1); +}); + +test("records a 'skipped' outcome for every analyzer not in an explicit request list, with no duration series", async () => { + await buildBrief( + { ...baseReq, analyzers: ["todoMarker"] }, + { todoMarker: async () => [], conflictMarker: async () => [] }, + ); + assert.equal(counterValue("rees_analyzer_runs_total", { analyzer: "conflictMarker", status: "skipped" }), 1); +}); + +test("records a 'skipped' outcome for an analyzer the scheduler pre-filters (missing a hard requirement)", async () => { + await buildBrief( + { ...baseReq, files: [], analyzers: ["todoMarker"] }, // todoMarker requires files; none provided + { todoMarker: async () => [] }, + ); + assert.equal(counterValue("rees_analyzer_runs_total", { analyzer: "todoMarker", status: "skipped" }), 1); +}); diff --git a/review-enrichment/test/metrics.test.ts b/review-enrichment/test/metrics.test.ts new file mode 100644 index 0000000000..4b10640efb --- /dev/null +++ b/review-enrichment/test/metrics.test.ts @@ -0,0 +1,61 @@ +import assert from "node:assert/strict"; +import { beforeEach, test } from "node:test"; + +import { counterValue, incr, observe, renderMetrics, resetMetrics } from "../dist/metrics.js"; + +beforeEach(() => { + resetMetrics(); +}); + +test("incr creates a counter on first use and accumulates on repeat calls", () => { + assert.equal(counterValue("rees_enrich_requests_total", { status: "ok" }), 0); + incr("rees_enrich_requests_total", { status: "ok" }); + incr("rees_enrich_requests_total", { status: "ok" }); + incr("rees_enrich_requests_total", { status: "unauthorized" }); + assert.equal(counterValue("rees_enrich_requests_total", { status: "ok" }), 2); + assert.equal(counterValue("rees_enrich_requests_total", { status: "unauthorized" }), 1); +}); + +test("incr supports a custom increment amount", () => { + incr("rees_analyzer_runs_total", { analyzer: "secret", status: "ok" }, 5); + assert.equal(counterValue("rees_analyzer_runs_total", { analyzer: "secret", status: "ok" }), 5); +}); + +test("renderMetrics emits HELP/TYPE once per metric name, then one line per counter series", () => { + incr("rees_enrich_requests_total", { status: "ok" }); + incr("rees_enrich_requests_total", { status: "http_error" }); + const text = renderMetrics(); + assert.equal(text.match(/# HELP rees_enrich_requests_total/g)?.length, 1); + assert.equal(text.match(/# TYPE rees_enrich_requests_total counter/g)?.length, 1); + assert.match(text, /rees_enrich_requests_total\{status="ok"\} 1/); + assert.match(text, /rees_enrich_requests_total\{status="http_error"\} 1/); +}); + +test("observe accumulates a histogram's bucket counts, sum, and count, with a correct +Inf bucket", () => { + observe("rees_analyzer_duration_seconds", 0.02, { analyzer: "redos" }); + observe("rees_analyzer_duration_seconds", 3, { analyzer: "redos" }); + const text = renderMetrics(); + assert.match(text, /rees_analyzer_duration_seconds_bucket\{analyzer="redos",le="0.025"\} 1/); + assert.match(text, /rees_analyzer_duration_seconds_bucket\{analyzer="redos",le="5"\} 2/); + assert.match(text, /rees_analyzer_duration_seconds_bucket\{analyzer="redos",le="\+Inf"\} 2/); + assert.match(text, /rees_analyzer_duration_seconds_sum\{analyzer="redos"\} 3\.02/); + assert.match(text, /rees_analyzer_duration_seconds_count\{analyzer="redos"\} 2/); +}); + +test("a metric name with no registered meta is still rendered, just without HELP/TYPE lines", () => { + incr("rees_unregistered_metric_total"); + const text = renderMetrics(); + assert.doesNotMatch(text, /# HELP rees_unregistered_metric_total/); + assert.match(text, /^rees_unregistered_metric_total 1$/m); +}); + +test("resetMetrics clears every series and restores the built-in metric metadata", () => { + incr("rees_enrich_requests_total", { status: "ok" }); + observe("rees_analyzer_duration_seconds", 1, { analyzer: "secret" }); + resetMetrics(); + assert.equal(counterValue("rees_enrich_requests_total", { status: "ok" }), 0); + incr("rees_enrich_requests_total", { status: "ok" }); + const text = renderMetrics(); + assert.equal(text.match(/# HELP rees_enrich_requests_total/g)?.length, 1); + assert.doesNotMatch(text, /rees_analyzer_duration_seconds/); +}); diff --git a/src/review/enrichment-wire.ts b/src/review/enrichment-wire.ts index 0de1e833f7..f76c969a6f 100644 --- a/src/review/enrichment-wire.ts +++ b/src/review/enrichment-wire.ts @@ -8,10 +8,21 @@ // network / parse error, or an empty brief, returns undefined and the review proceeds on diff + grounding + RAG. import { extractLinkedIssueNumbers, getIssue } from "../db/repositories"; import { sanitizePublicComment } from "../queue-intelligence"; +import { incr, observe } from "../selfhost/metrics"; import { neutralizePromptInjection } from "./prompt-injection"; import { REES_ANALYZER_NAMES, REES_ANALYZER_NAME_SET, type ReesAnalyzerName } from "./enrichment-analyzer-names"; import type { PullRequestFileRecord } from "../types"; +const REES_ENRICH_REQUESTS_TOTAL = "gittensory_rees_enrich_requests_total"; +const REES_ENRICH_REQUEST_DURATION_SECONDS = "gittensory_rees_enrich_request_duration_seconds"; + +/** Records the client-observable outcome of one /v1/enrich attempt. `elapsedMs` is omitted for the + * skipped-before-any-network-attempt case (the auth-rejected circuit breaker), since no call was timed. */ +function recordReesEnrichOutcome(status: string, startedAtMs?: number): void { + incr(REES_ENRICH_REQUESTS_TOTAL, { status }); + if (startedAtMs !== undefined) observe(REES_ENRICH_REQUEST_DURATION_SECONDS, (Date.now() - startedAtMs) / 1000); +} + export { REES_ANALYZER_NAMES, type ReesAnalyzerName } from "./enrichment-analyzer-names"; interface EnrichmentEnv { @@ -417,6 +428,7 @@ export async function buildReviewEnrichment( }), ); } + recordReesEnrichOutcome("skipped_auth_rejected"); return undefined; } const sharedSecret = normalizeSharedSecret(cfg.REES_SHARED_SECRET); @@ -430,6 +442,7 @@ export async function buildReviewEnrichment( const analyzers = resolveEnrichmentAnalyzerSelection(resolveReesAnalyzers(env), input.enrichmentAnalyzers); const profile = resolveReesProfile(env); const requestId = newReesRequestId(); + const requestStartedAtMs = Date.now(); try { const response = await fetch(`${base.replace(/\/+$/, "")}/v1/enrich`, { method: "POST", @@ -501,6 +514,7 @@ export async function buildReviewEnrichment( : `REES /v1/enrich returned ${response.status}`, }), ); + recordReesEnrichOutcome("http_error", requestStartedAtMs); return undefined; } const brief = (await response.json()) as { @@ -511,7 +525,11 @@ export async function buildReviewEnrichment( elapsedMs?: number; }; const promptSection = sanitizeEnrichmentPromptSection(brief.promptSection); - if (!promptSection) return undefined; // no findings / unsafe brief ⇒ byte-identical prompt + if (!promptSection) { + recordReesEnrichOutcome("empty", requestStartedAtMs); // no findings / unsafe brief ⇒ byte-identical prompt + return undefined; + } + recordReesEnrichOutcome("ok", requestStartedAtMs); return { promptSection, // Never splice REES-provided instructions into the SYSTEM prompt. A fixed local suffix preserves the @@ -522,6 +540,9 @@ export async function buildReviewEnrichment( : "", }; } catch (error) { + // AbortSignal.timeout rejects with a TimeoutError; everything else is a network/parse exception. + const isTimeout = (error as { name?: string } | null)?.name === "TimeoutError"; + recordReesEnrichOutcome(isTimeout ? "timeout" : "exception", requestStartedAtMs); // Surface the failure (#5 review observability): the REES enrichment call can fail (timeout / network / parse) // and the review then silently proceeds without the brief. ERROR level so the central Sentry forwarder captures // a broken/slow REES backend instead of it degrading invisibly. diff --git a/src/selfhost/metrics.ts b/src/selfhost/metrics.ts index 5cca89c77b..b5d48dd17d 100644 --- a/src/selfhost/metrics.ts +++ b/src/selfhost/metrics.ts @@ -166,6 +166,8 @@ export const DEFAULT_METRIC_META: readonly (readonly [string, MetricMeta])[] = [ ["gittensory_review_memory_cache_hit_total", { help: "Review-memory cache hits.", type: "counter" }], ["gittensory_review_memory_cache_miss_total", { help: "Review-memory cache misses.", type: "counter" }], ["gittensory_review_memory_suppressed_total", { help: "Review-memory entries suppressed from surfacing, by repo.", type: "counter" }], + ["gittensory_rees_enrich_requests_total", { help: "REES /v1/enrich call outcomes, by status (ok/empty/http_error/timeout/exception/skipped_auth_rejected).", type: "counter" }], + ["gittensory_rees_enrich_request_duration_seconds", { help: "REES /v1/enrich call duration in seconds, for calls that were actually attempted (excludes the auth-rejected circuit-breaker skip).", type: "histogram" }], ]; const metricMeta = new Map(DEFAULT_METRIC_META); diff --git a/test/unit/enrichment-wire.test.ts b/test/unit/enrichment-wire.test.ts index 36cc381c49..be62961a7e 100644 --- a/test/unit/enrichment-wire.test.ts +++ b/test/unit/enrichment-wire.test.ts @@ -14,6 +14,7 @@ import { } from "../../src/review/enrichment-wire"; import { createTestEnv } from "../helpers/d1"; import { upsertIssueFromGitHub, upsertRepositoryFromGitHub } from "../../src/db/repositories"; +import { renderMetrics, resetMetrics } from "../../src/selfhost/metrics"; const env = (o: Record) => o as unknown as Env; const input = { @@ -665,6 +666,98 @@ describe("buildReviewEnrichment", () => { }); }); +describe("buildReviewEnrichment metrics recording (#5367)", () => { + let realFetch: typeof fetch; + beforeEach(() => { + realFetch = globalThis.fetch; + resetMetrics(); + }); + afterEach(() => { + globalThis.fetch = realFetch; + resetReesAuthRejectedForTests(); + }); + + it('records status="ok" with a duration observation on a usable brief', async () => { + globalThis.fetch = vi.fn( + async () => ({ ok: true, json: async () => ({ promptSection: "brief" }) }) as Response, + ) as unknown as typeof fetch; + await buildReviewEnrichment(env({ REES_URL: "https://r" }), input); + const metrics = await renderMetrics(); + expect(metrics).toContain('gittensory_rees_enrich_requests_total{status="ok"} 1'); + expect(metrics).toContain("gittensory_rees_enrich_request_duration_seconds_count 1"); + }); + + it('records status="empty" when the response is 2xx but the brief has no usable promptSection', async () => { + globalThis.fetch = vi.fn( + async () => ({ ok: true, json: async () => ({ promptSection: "" }) }) as Response, + ) as unknown as typeof fetch; + await buildReviewEnrichment(env({ REES_URL: "https://r" }), input); + const metrics = await renderMetrics(); + expect(metrics).toContain('gittensory_rees_enrich_requests_total{status="empty"} 1'); + expect(metrics).toContain("gittensory_rees_enrich_request_duration_seconds_count 1"); + }); + + it('records status="http_error" on a non-2xx response', async () => { + const errSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + globalThis.fetch = vi.fn( + async () => ({ ok: false, status: 502, statusText: "Bad Gateway", text: async () => "" }) as Response, + ) as unknown as typeof fetch; + await buildReviewEnrichment(env({ REES_URL: "https://r" }), input); + const metrics = await renderMetrics(); + expect(metrics).toContain('gittensory_rees_enrich_requests_total{status="http_error"} 1'); + expect(metrics).toContain("gittensory_rees_enrich_request_duration_seconds_count 1"); + errSpy.mockRestore(); + }); + + it('records status="timeout" when the fetch rejects with a TimeoutError (AbortSignal.timeout)', async () => { + const errSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + globalThis.fetch = vi.fn(async () => { + throw Object.assign(new Error("The operation was aborted due to timeout"), { name: "TimeoutError" }); + }) as unknown as typeof fetch; + await buildReviewEnrichment(env({ REES_URL: "https://r" }), input); + const metrics = await renderMetrics(); + expect(metrics).toContain('gittensory_rees_enrich_requests_total{status="timeout"} 1'); + expect(metrics).not.toContain('status="exception"'); + errSpy.mockRestore(); + }); + + it('records status="exception" for a non-timeout fetch throw (network/parse error)', async () => { + const errSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + globalThis.fetch = vi.fn(async () => { + throw new Error("network down"); + }) as unknown as typeof fetch; + await buildReviewEnrichment(env({ REES_URL: "https://r" }), input); + const metrics = await renderMetrics(); + expect(metrics).toContain('gittensory_rees_enrich_requests_total{status="exception"} 1'); + expect(metrics).not.toContain('status="timeout"'); + errSpy.mockRestore(); + }); + + it('records status="skipped_auth_rejected" WITHOUT a duration observation once the circuit breaker trips', async () => { + globalThis.fetch = vi.fn(async () => ({ ok: false, status: 401 }) as Response) as unknown as typeof fetch; + const warnSpy = vi.spyOn(console, "warn").mockImplementation(() => {}); + const errSpy = vi.spyOn(console, "error").mockImplementation(() => {}); + probeReesSecretAtStartup(env({ REES_URL: "https://rees.example", REES_SHARED_SECRET: "s3cret" })); + await new Promise((resolve) => setTimeout(resolve, 0)); + resetMetrics(); // the startup probe itself doesn't call buildReviewEnrichment; isolate what follows + + await buildReviewEnrichment(env({ REES_URL: "https://rees.example", REES_SHARED_SECRET: "s3cret" }), input); + const metrics = await renderMetrics(); + expect(metrics).toContain('gittensory_rees_enrich_requests_total{status="skipped_auth_rejected"} 1'); + // No network attempt was made, so no duration sample -- the histogram must not appear at all. + expect(metrics).not.toContain("gittensory_rees_enrich_request_duration_seconds"); + warnSpy.mockRestore(); + errSpy.mockRestore(); + }); + + it("never records any outcome when REES_URL is unset (not a real attempt)", async () => { + await buildReviewEnrichment(env({}), input); + const metrics = await renderMetrics(); + expect(metrics).not.toContain("gittensory_rees_enrich_requests_total"); + expect(metrics).not.toContain("gittensory_rees_enrich_request_duration_seconds"); + }); +}); + describe("REGRESSION (#3738): REES auth-rejected circuit breaker", () => { let realFetch: typeof fetch; beforeEach(() => {