feat(observability): instrument REES + its main-app client with real Prometheus metrics

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<void> {
@@ -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(

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<string, string>;
+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<string, number>();
+const histograms = new Map<string, HistogramState>();
+
+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<string, MetricMeta>(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<string>, 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<string>();
+  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);
+}

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");

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);
+});