diff --git a/docs/observability-slos.md b/docs/observability-slos.md index 2dc48c74a..925dac59e 100644 --- a/docs/observability-slos.md +++ b/docs/observability-slos.md @@ -168,13 +168,57 @@ Operational notes: `workflow_dispatch` run and confirm it goes green before trusting the nightly cadence (repo gate for this workflow). -## 4. Gaps / next steps (not in this change) +## 4. Degradation counters on `/api/health` (shipped) + +The §2 reliability SQL is now also a scrape. An **authorized deep probe** — +`GET /api/health?deep=1` with the `x-health-deep-token: $HEALTH_DEEP_PROBE_SECRET` +header (same operator gate as the Supabase probe) — returns two counter blocks: + +- **`slo`** — `answerSloSnapshot` (`src/lib/observability/answer-slo.ts`) counts + `rag_queries` over the trailing `windowMinutes` (60) and reports + `hybridRpcErrorQueries` / `hybridRpcErrorRate` (the §2 silent-RPC-death guard) + and `degradedQueries` / `degradedRate` (the source-only/fallback guard). These + are windowed rates straight from the persisted telemetry. + +- **`cache`** — `cacheMetricsSnapshot` (`src/lib/observability/cache-metrics.ts`) + reports `{ lookups, hits, misses, hitRate }` for the retrieval search cache, + incremented in-process at the two-layer cache orchestration in + `searchChunksWithTelemetry` (`src/lib/rag.ts`). A request served by **either** + the process-local or the shared (`rag_response_cache`) layer counts as a hit, + so a cold process falling through to a warm shared cache is not miscounted as a + miss; disabled/skipped lookups are recorded as neither. These are **cumulative + since process start** (Prometheus-style): a scraper derives a windowed hit-rate + from the delta between two polls. Measuring at the lookup site — not from + `rag_queries` — also captures coalesced and fully cache-served requests that + never write a telemetry row. `hitRate` is a convenience for eyeballing a single + probe. + +```jsonc +// GET /api/health?deep=1 (authorized, live) +"slo": { "windowMinutes": 60, "totalQueries": 412, + "hybridRpcErrorQueries": 0, "hybridRpcErrorRate": 0.0, + "degradedQueries": 26, "degradedRate": 0.063 }, +"cache": { "lookups": 1873, "hits": 1402, "misses": 471, "hitRate": 0.748 } +``` -- Host-level metrics (CPU, memory, restart count) and log drains once the +**The counter _values_ never flip liveness.** A bad SLO rate or a cold cache +stays visible without changing readiness — degradation is made _visible_, not +_fatal_, which is the failure mode this doc guards against. Liveness is driven +only by the reachability `checks`: a failing `probeSupabaseHealth()` still sets +`checks.supabase = "error"` and returns `503`, whereas an `answerSloSnapshot()` +query failure merely omits the `slo` block (never a false-healthy zero). The +cache counter is always present for a token-authorized probe (in-process, works +in demo mode). Both blocks are wired through `src/lib/health-response.ts` and are +**withheld from the unauthenticated `/api/health/ready` endpoint** (Railway's +readiness target, which exposes no diagnostic details). The §2 warn/page +thresholds map directly onto these fields. + +## 5. Gaps / next steps + +- **Wire the warn/page thresholds into an actual alerting channel.** The §4 + counters are now scrapeable; the remaining work is routing them past their §2 + thresholds (and the 3 h-sustained hybrid escalation) into a real channel — a + host-native alerter polling `/api/health?deep=1`, or a scheduled workflow + evaluating the §2 SQL. +- **Host-level metrics** (CPU, memory, restart count) and log drains once the container host exists (`docs/deployment-architecture.md` §2). -- A lightweight `/api/health` extension exposing cache hit-rate and - `hybrid_rpc_errors`-in-last-hour counters for host-native alerting, so the - SQL above can become a scrape instead of a manual query. (Touches app code — - deliberately excluded from this change.) -- Wire the warn/page thresholds into an actual alerting channel (Supabase log - drain → host alerts, or a scheduled workflow evaluating the SQL above). diff --git a/src/app/api/health/ready/route.ts b/src/app/api/health/ready/route.ts index 8cc8cd7bd..9e7c6a463 100644 --- a/src/app/api/health/ready/route.ts +++ b/src/app/api/health/ready/route.ts @@ -6,5 +6,10 @@ export const dynamic = "force-dynamic"; // Railway cannot attach the authenticated deep-probe header. This endpoint is // intentionally limited to readiness state and exposes no diagnostic details. export async function GET(request: Request) { - return healthResponse(request, { forceDeep: true, allowUnauthenticatedDeep: true, includeSlo: false }); + return healthResponse(request, { + forceDeep: true, + allowUnauthenticatedDeep: true, + includeSlo: false, + includeCache: false, + }); } diff --git a/src/lib/health-response.ts b/src/lib/health-response.ts index 01ec52f4e..628f1773a 100644 --- a/src/lib/health-response.ts +++ b/src/lib/health-response.ts @@ -2,11 +2,13 @@ import { NextResponse } from "next/server"; import { allowDeepHealthProbe } from "@/lib/deep-probe-auth"; import { env, isDemoMode } from "@/lib/env"; import type { AnswerSloSnapshot } from "@/lib/observability/answer-slo"; +import { cacheMetricsSnapshot, type CacheMetricsSnapshot } from "@/lib/observability/cache-metrics"; type HealthResponseOptions = { forceDeep?: boolean; allowUnauthenticatedDeep?: boolean; includeSlo?: boolean; + includeCache?: boolean; }; export async function healthResponse(request: Request, options: HealthResponseOptions = {}) { @@ -17,32 +19,46 @@ export async function healthResponse(request: Request, options: HealthResponseOp openaiConfig: env.OPENAI_API_KEY ? "ok" : "missing", }; let slo: AnswerSloSnapshot | null = null; + let cache: CacheMetricsSnapshot | null = null; if (deep) { - if (!options.allowUnauthenticatedDeep && !allowDeepHealthProbe(request)) { + const tokenAuthorized = allowDeepHealthProbe(request); + if (!options.allowUnauthenticatedDeep && !tokenAuthorized) { checks.supabase = "unauthorized"; - } else if (supabaseConfigured && !isDemoMode()) { - try { - const [{ createAdminClient }, { probeSupabaseHealth }, { answerSloSnapshot }] = await Promise.all([ - import("@/lib/supabase/admin"), - import("@/lib/supabase/health"), - import("@/lib/observability/answer-slo"), - ]); - const admin = createAdminClient(); - const health = await probeSupabaseHealth(admin); - checks.supabase = health.ok ? "ok" : "error"; - if (health.ok && options.includeSlo !== false) { - try { - slo = await answerSloSnapshot(admin); - } catch { - slo = null; + } else { + // Cache hit-rate is operator-gated internal telemetry (the in-process + // hot-path half of the silent-degradation counters). Expose it only to a + // genuinely token-authorized deep probe — never the unauthenticated + // readiness endpoint, which exposes no diagnostic details — and only when + // not explicitly suppressed. Reads a cumulative counter (no DB), so it is + // available even in demo mode. Like `slo`, it never flips liveness. + if (tokenAuthorized && options.includeCache !== false) { + cache = cacheMetricsSnapshot(); + } + + if (supabaseConfigured && !isDemoMode()) { + try { + const [{ createAdminClient }, { probeSupabaseHealth }, { answerSloSnapshot }] = await Promise.all([ + import("@/lib/supabase/admin"), + import("@/lib/supabase/health"), + import("@/lib/observability/answer-slo"), + ]); + const admin = createAdminClient(); + const health = await probeSupabaseHealth(admin); + checks.supabase = health.ok ? "ok" : "error"; + if (health.ok && options.includeSlo !== false) { + try { + slo = await answerSloSnapshot(admin); + } catch { + slo = null; + } } + } catch { + checks.supabase = "error"; } - } catch { - checks.supabase = "error"; + } else { + checks.supabase = "skipped"; } - } else { - checks.supabase = "skipped"; } } @@ -58,6 +74,7 @@ export async function healthResponse(request: Request, options: HealthResponseOp uptimeSeconds: Math.round(process.uptime()), checks, ...(slo ? { slo } : {}), + ...(cache ? { cache } : {}), }, { status: ready ? 200 : 503, headers: { "Cache-Control": "no-store" } }, ); diff --git a/src/lib/observability/cache-metrics.ts b/src/lib/observability/cache-metrics.ts new file mode 100644 index 000000000..bc8a28371 --- /dev/null +++ b/src/lib/observability/cache-metrics.ts @@ -0,0 +1,65 @@ +// In-process cache-lookup counters for the retrieval hot path. +// +// The cache hit-rate half of the /api/health silent-degradation counters (see +// docs/observability-slos.md). Its sibling `answer-slo.ts` aggregates +// `rag_queries` over a trailing window; cache effectiveness instead has to be +// measured where the lookups actually happen (the search-cache orchestration in +// searchChunksWithTelemetry) so it also covers requests that never write a +// rag_queries row — coalesced or fully cache-served. +// +// Counters are cumulative since process start (Prometheus-style): a host-native +// scraper derives a windowed hit-rate from the delta between two polls, which is +// exactly what a counter is for. `hitRate` is a convenience for eyeballing a +// single probe. Only cache-enabled lookups are recorded — a request that skips +// the cache (skipCache / TTL or size 0) is neither a hit nor a miss. + +let lookups = 0; +let hits = 0; + +/** Record one retrieval-cache lookup with its outcome. Cheap; safe on the hot path. */ +export function recordCacheLookup(hit: boolean): void { + lookups += 1; + if (hit) hits += 1; +} + +export type CacheMetricsSnapshot = { + lookups: number; + hits: number; + misses: number; + // 0..1; 0 when there have been no lookups yet (avoid divide-by-zero noise). + hitRate: number; +}; + +export function cacheMetricsSnapshot(): CacheMetricsSnapshot { + const misses = lookups - hits; + return { lookups, hits, misses, hitRate: lookups > 0 ? hits / lookups : 0 }; +} + +/** Test-only: reset the counters between cases. */ +export function resetCacheMetrics(): void { + lookups = 0; + hits = 0; +} + +/** + * Classify the outcome of the two-layer search-cache lookup so the counter + * reflects real cache effectiveness. Retrieval consults the process-local cache + * first and the shared (`rag_response_cache`) cache second; a request served by + * *either* layer is a hit, so a cold process falling through to a warm shared + * cache is not miscounted as a miss. When the search cache is disabled for this + * request (`cacheEnabled` false — skipCache, or TTL/size 0) the lookup is + * `"skip"` and recorded as neither; this is gated up front because the shared + * lookup only short-circuits on skipCache/TTL, so a size-0 deployment would + * otherwise record disabled lookups as misses and read as false degradation. + * Pure, so the orchestration stays trivial and this stays unit-tested. + */ +export function classifySearchCacheOutcome( + cacheEnabled: boolean, + localHit: boolean, + sharedResult: { kind: "hit" | "miss" } | null | undefined, +): "hit" | "miss" | "skip" { + if (!cacheEnabled) return "skip"; + if (localHit || sharedResult?.kind === "hit") return "hit"; + if (sharedResult?.kind === "miss") return "miss"; + return "skip"; +} diff --git a/src/lib/rag-cache.ts b/src/lib/rag-cache.ts index b9fce6b59..6b70349d2 100644 --- a/src/lib/rag-cache.ts +++ b/src/lib/rag-cache.ts @@ -179,12 +179,20 @@ function normalizeCacheStorageTelemetry(telemetry: SearchTelemetry): SearchTelem }; } +// Single source of truth for whether the process-local search cache is active +// for a request. Shared with the observability counter so a size-0 (or TTL-0 / +// skipCache) deployment records the lookup as neither hit nor miss rather than a +// false miss (the shared-cache lookup does not itself short-circuit on size). +export function isSearchCacheEnabled(args: Pick): boolean { + return !args.skipCache && env.RAG_SEARCH_CACHE_TTL_MS > 0 && env.RAG_SEARCH_CACHE_SIZE > 0; +} + export async function getCachedSearch( args: SearchChunksArgs, queryClass?: RagQueryClass, queryVariants: string[] = [], ): Promise<{ results: SearchResult[]; telemetry: SearchTelemetry } | null> { - if (args.skipCache || env.RAG_SEARCH_CACHE_TTL_MS <= 0 || env.RAG_SEARCH_CACHE_SIZE <= 0) return null; + if (!isSearchCacheEnabled(args)) return null; const key = scopedSearchCacheKey(args, queryClass, queryVariants); const cached = searchCache.get(key); diff --git a/src/lib/rag.ts b/src/lib/rag.ts index 1e23815af..bc0cf5cb1 100644 --- a/src/lib/rag.ts +++ b/src/lib/rag.ts @@ -73,6 +73,7 @@ import { getCachedSearch, getSharedCachedAnswer, getSharedCachedSearch, + isSearchCacheEnabled, packAdjacentSourceContext, packedContextCacheKey, scopedAnswerCacheKey, @@ -85,6 +86,7 @@ export { packedContextCacheKey, retrievalPlanCacheQuery, } from "@/lib/rag-cache"; +import { classifySearchCacheOutcome, recordCacheLookup } from "@/lib/observability/cache-metrics"; import { buildRagSourceBlock, compactContextText, neutralizeIdentityField } from "@/lib/rag-source-block"; export { buildRagSourceBlock, truncateForModel } from "@/lib/rag-source-block"; import { @@ -3015,8 +3017,16 @@ export async function searchChunksWithTelemetry(args: SearchChunksArgs) { const queryVariants = buildRetrievalQueryVariants(retrievalQuery, queryAnalysis, ragAliases); telemetry.retrieval_query_variant_count = queryVariants.length; const cached = await getCachedSearch(args, queryClassification.queryClass, queryVariants); + // Only consult the shared cache when the process-local cache missed (preserves + // the original short-circuit), then record the hit-rate counter ONCE with full + // knowledge of both layers: a request served by either cache is a hit, so a + // cold process that falls through to a warm shared cache is not miscounted as a + // miss (deep /api/health cache hit-rate — docs/observability-slos.md §4). + const sharedCached = cached ? null : await getSharedCachedSearch(args, queryClassification.queryClass, queryVariants); + const cacheOutcome = classifySearchCacheOutcome(isSearchCacheEnabled(args), Boolean(cached), sharedCached); + if (cacheOutcome !== "skip") recordCacheLookup(cacheOutcome === "hit"); + if (cached) return cached; - const sharedCached = await getSharedCachedSearch(args, queryClassification.queryClass, queryVariants); if (sharedCached?.kind === "hit") { await setCachedSearch(args, sharedCached.results, sharedCached.telemetry, queryVariants); return { results: sharedCached.results, telemetry: sharedCached.telemetry }; diff --git a/tests/cache-metrics.test.ts b/tests/cache-metrics.test.ts new file mode 100644 index 000000000..b782285da --- /dev/null +++ b/tests/cache-metrics.test.ts @@ -0,0 +1,69 @@ +import { afterEach, describe, expect, it } from "vitest"; + +import { + cacheMetricsSnapshot, + classifySearchCacheOutcome, + recordCacheLookup, + resetCacheMetrics, +} from "@/lib/observability/cache-metrics"; + +afterEach(() => { + resetCacheMetrics(); +}); + +describe("cache metrics counter", () => { + it("reports a zero hit-rate (not NaN) before any lookups", () => { + expect(cacheMetricsSnapshot()).toEqual({ lookups: 0, hits: 0, misses: 0, hitRate: 0 }); + }); + + it("accumulates hits and misses and derives the hit-rate", () => { + recordCacheLookup(true); + recordCacheLookup(true); + recordCacheLookup(true); + recordCacheLookup(false); + + expect(cacheMetricsSnapshot()).toEqual({ lookups: 4, hits: 3, misses: 1, hitRate: 0.75 }); + }); + + it("is cumulative across calls until reset", () => { + recordCacheLookup(false); + expect(cacheMetricsSnapshot()).toMatchObject({ lookups: 1, hits: 0, misses: 1, hitRate: 0 }); + + recordCacheLookup(true); + expect(cacheMetricsSnapshot()).toMatchObject({ lookups: 2, hits: 1, misses: 1, hitRate: 0.5 }); + + resetCacheMetrics(); + expect(cacheMetricsSnapshot()).toEqual({ lookups: 0, hits: 0, misses: 0, hitRate: 0 }); + }); +}); + +describe("classifySearchCacheOutcome", () => { + it("counts a process-local cache hit as a hit", () => { + expect(classifySearchCacheOutcome(true, true, null)).toBe("hit"); + expect(classifySearchCacheOutcome(true, true, { kind: "miss" })).toBe("hit"); + }); + + it("counts a shared-cache hit after a local miss as a hit (not a miss)", () => { + // Regression: a cold process serving fully from the shared cache must not + // deflate the hit-rate into false-degradation territory. + expect(classifySearchCacheOutcome(true, false, { kind: "hit" })).toBe("hit"); + }); + + it("counts a miss only when both layers were consulted and missed", () => { + expect(classifySearchCacheOutcome(true, false, { kind: "miss" })).toBe("miss"); + }); + + it("skips the disabled search cache even when the shared lookup still ran", () => { + // Regression: getSharedCachedSearch does not short-circuit on size, so a + // size-0 (or TTL-0 / skipCache) deployment would otherwise record disabled + // lookups as false misses and report a 0% hit-rate. + expect(classifySearchCacheOutcome(false, false, { kind: "miss" })).toBe("skip"); + expect(classifySearchCacheOutcome(false, false, { kind: "hit" })).toBe("skip"); + expect(classifySearchCacheOutcome(false, false, null)).toBe("skip"); + }); + + it("skips when enabled but no cache layer was consulted", () => { + expect(classifySearchCacheOutcome(true, false, null)).toBe("skip"); + expect(classifySearchCacheOutcome(true, false, undefined)).toBe("skip"); + }); +}); diff --git a/tests/health-route.test.ts b/tests/health-route.test.ts index db5fe7d8a..45a1de270 100644 --- a/tests/health-route.test.ts +++ b/tests/health-route.test.ts @@ -1,19 +1,22 @@ import { afterEach, describe, expect, it, vi } from "vitest"; -function mockEnv(options: { configured: boolean; demoMode?: boolean }) { +const DEEP_TOKEN = "deep-probe-secret"; + +function mockEnv(options: { configured: boolean; demoMode?: boolean; deepSecret?: boolean }) { vi.resetModules(); vi.doMock("@/lib/env", () => ({ env: { NEXT_PUBLIC_SUPABASE_URL: options.configured ? "https://sjrfecxgysukkwxsowpy.supabase.co" : undefined, SUPABASE_SERVICE_ROLE_KEY: options.configured ? "service-role-key" : undefined, OPENAI_API_KEY: options.configured ? "openai-key" : undefined, + HEALTH_DEEP_PROBE_SECRET: options.deepSecret ? DEEP_TOKEN : undefined, }, isDemoMode: () => Boolean(options.demoMode), })); } -function healthRequest(query = "") { - return new Request(`http://localhost/api/health${query}`); +function healthRequest(query = "", headers?: HeadersInit) { + return new Request(`http://localhost/api/health${query}`, headers ? { headers } : undefined); } async function payload(response: Response) { @@ -52,8 +55,8 @@ describe("GET /api/health", () => { expect(body.checks).toMatchObject({ supabaseConfig: "missing", openaiConfig: "missing" }); }); - it("gates the deep probe without a token and omits the slo snapshot", async () => { - mockEnv({ configured: true }); + it("gates the deep probe without a token and omits the slo/cache snapshots", async () => { + mockEnv({ configured: true, deepSecret: true }); const { GET } = await import("../src/app/api/health/route"); const response = await GET(healthRequest("?deep=1")); @@ -62,6 +65,27 @@ describe("GET /api/health", () => { expect(response.status).toBe(503); expect(body.checks).toMatchObject({ supabase: "unauthorized" }); expect(body.slo).toBeUndefined(); + expect(body.cache).toBeUndefined(); + }); + + it("exposes the in-process cache hit-rate counter on an authorized deep probe", async () => { + // Demo mode skips the Supabase-backed slo query, so no admin mock is needed; + // the cache counter is in-process and must still be reported. + mockEnv({ configured: true, demoMode: true, deepSecret: true }); + const { GET } = await import("../src/app/api/health/route"); + + const response = await GET(healthRequest("?deep=1", { "x-health-deep-token": DEEP_TOKEN })); + const body = await payload(response); + + expect(response.status).toBe(200); + const cache = body.cache as Record; + // Counters are process-cumulative, so assert shape/invariants, not exact counts. + expect(typeof cache.lookups).toBe("number"); + expect(typeof cache.hits).toBe("number"); + expect(cache.misses).toBe(cache.lookups - cache.hits); + expect(cache.hitRate).toBeGreaterThanOrEqual(0); + expect(cache.hitRate).toBeLessThanOrEqual(1); + expect(body.slo).toBeUndefined(); }); it("does not leak secret values in the payload", async () => { @@ -87,4 +111,17 @@ describe("GET /api/health/ready", () => { expect(response.status).toBe(200); expect(body.checks).toMatchObject({ supabaseConfig: "ok", openaiConfig: "ok", supabase: "skipped" }); }); + + it("exposes no diagnostic details (slo/cache) even to a token-bearing caller", async () => { + mockEnv({ configured: true, demoMode: true, deepSecret: true }); + const { GET } = await import("../src/app/api/health/ready/route"); + + const response = await GET( + new Request("http://localhost/api/health/ready", { headers: { "x-health-deep-token": DEEP_TOKEN } }), + ); + const body = await payload(response); + + expect(body.slo).toBeUndefined(); + expect(body.cache).toBeUndefined(); + }); });