diff --git a/package-lock.json b/package-lock.json index 117fd225a..84e3b92cf 100644 --- a/package-lock.json +++ b/package-lock.json @@ -21,10 +21,12 @@ "@hookform/resolvers": "^5.4.0", "@logtail/pino": "^0.5.8", "@next/bundle-analyzer": "^16.2.9", + "@opentelemetry/api": "^1.9.0", "@opentelemetry/auto-instrumentations-node": "^0.77.0", "@opentelemetry/exporter-trace-otlp-http": "^0.219.0", "@opentelemetry/resources": "^2.8.0", "@opentelemetry/sdk-node": "^0.219.0", + "@opentelemetry/sdk-trace-base": "^2.8.0", "@opentelemetry/semantic-conventions": "^1.41.1", "@prisma/adapter-pg": "^7.8.0", "@prisma/client": "^7.8.0", @@ -19060,6 +19062,7 @@ "version": "2.3.2", "resolved": "https://registry.npmjs.org/fsevents/-/fsevents-2.3.2.tgz", "integrity": "sha512-xiqMQR4xAeHTuB9uWm+fFRcIOgKBMiOBP+eXiyT7jsgVCq1bkVygt00oASowB7EdtpOHaaPgKt812P9ab+DDKA==", + "dev": true, "hasInstallScript": true, "license": "MIT", "optional": true, diff --git a/package.json b/package.json index 95b047d50..cb60598a2 100644 --- a/package.json +++ b/package.json @@ -101,10 +101,12 @@ "@hookform/resolvers": "^5.4.0", "@logtail/pino": "^0.5.8", "@next/bundle-analyzer": "^16.2.9", + "@opentelemetry/api": "^1.9.0", "@opentelemetry/auto-instrumentations-node": "^0.77.0", "@opentelemetry/exporter-trace-otlp-http": "^0.219.0", "@opentelemetry/resources": "^2.8.0", "@opentelemetry/sdk-node": "^0.219.0", + "@opentelemetry/sdk-trace-base": "^2.8.0", "@opentelemetry/semantic-conventions": "^1.41.1", "@prisma/adapter-pg": "^7.8.0", "@prisma/client": "^7.8.0", diff --git a/src/instrumentation.ts b/src/instrumentation.ts index 35a24cb32..e94ac5b7e 100644 --- a/src/instrumentation.ts +++ b/src/instrumentation.ts @@ -64,16 +64,17 @@ export async function register() { const { scheduleConfigSync } = await import("./lib/interactor/agents/config-sync"); scheduleConfigSync(); + // NOTE: the tracing SDK starts UNCONDITIONALLY on the Node runtime — it is + // NOT gated on OTEL_EXPORTER_OTLP_ENDPOINT. The LatencySpanProcessor feeds a + // purely in-process store (backs the admin Prod Metrics "Request Latency" + // panel) and needs no remote collector. Gating the whole SDK on the OTLP + // endpoint (which .env.example ships empty) is what previously left that + // panel permanently empty. The OTLP exporter is attached only when an + // endpoint IS configured; the HTTP auto-instrumentation runs either way so + // every incoming request produces the SERVER span the processor reads. const otlpEndpoint = process.env.OTEL_EXPORTER_OTLP_ENDPOINT; - // Skip tracing if no sink is configured (keeps dev startup fast). - if (!otlpEndpoint) { - return; - } const { NodeSDK } = await import("@opentelemetry/sdk-node"); - const { OTLPTraceExporter } = await import( - "@opentelemetry/exporter-trace-otlp-http" - ); const { getNodeAutoInstrumentations } = await import( "@opentelemetry/auto-instrumentations-node" ); @@ -81,25 +82,44 @@ export async function register() { const { SEMRESATTRS_SERVICE_NAME } = await import( "@opentelemetry/semantic-conventions" ); + const { LatencySpanProcessor } = await import( + "./lib/observability/latency-span-processor" + ); + // NodeSDK uses `spanProcessors` verbatim when provided and ignores + // `traceExporter`, so we assemble the OTLP export path ourselves here. + const { tracing } = await import("@opentelemetry/sdk-node"); const serviceName = process.env.OTEL_SERVICE_NAME ?? "product-manager"; - // Parse optional header overrides (e.g. "Authorization=Bearer "). - const headersRaw = process.env.OTEL_EXPORTER_OTLP_HEADERS ?? ""; - const headers: Record = {}; - for (const pair of headersRaw.split(",").filter(Boolean)) { - const idx = pair.indexOf("="); - if (idx > 0) headers[pair.slice(0, idx).trim()] = pair.slice(idx + 1).trim(); - } + // In-process latency capture is always on; the OTLP exporter is optional. + const spanProcessors: import("@opentelemetry/sdk-node").tracing.SpanProcessor[] = [ + new LatencySpanProcessor(), + ]; - const exporterOptions = otlpEndpoint - ? { url: `${otlpEndpoint}/v1/traces`, headers } - : {}; + if (otlpEndpoint) { + const { OTLPTraceExporter } = await import( + "@opentelemetry/exporter-trace-otlp-http" + ); + + // Parse optional header overrides (e.g. "Authorization=Bearer "). + const headersRaw = process.env.OTEL_EXPORTER_OTLP_HEADERS ?? ""; + const headers: Record = {}; + for (const pair of headersRaw.split(",").filter(Boolean)) { + const idx = pair.indexOf("="); + if (idx > 0) headers[pair.slice(0, idx).trim()] = pair.slice(idx + 1).trim(); + } + + spanProcessors.push( + new tracing.BatchSpanProcessor( + new OTLPTraceExporter({ url: `${otlpEndpoint}/v1/traces`, headers }), + ), + ); + } const sdk = new NodeSDK({ resource: resourceFromAttributes({ [SEMRESATTRS_SERVICE_NAME]: serviceName }), - traceExporter: new OTLPTraceExporter(exporterOptions), + spanProcessors, instrumentations: [ getNodeAutoInstrumentations({ // Disable noisy fs instrumentation; keep HTTP, pg, and redis. diff --git a/src/lib/observability/latency-span-processor.test.ts b/src/lib/observability/latency-span-processor.test.ts new file mode 100644 index 000000000..889856582 --- /dev/null +++ b/src/lib/observability/latency-span-processor.test.ts @@ -0,0 +1,169 @@ +// Copyright (c) 2026 Interactor, Inc. +// SPDX-License-Identifier: AGPL-3.0-or-later + +import { SpanKind } from "@opentelemetry/api"; +import type { HrTime } from "@opentelemetry/api"; +import type { ReadableSpan } from "@opentelemetry/sdk-trace-base"; +import { + ATTR_HTTP_ROUTE, + ATTR_URL_PATH, + SEMATTRS_HTTP_TARGET, +} from "@opentelemetry/semantic-conventions"; +import { describe, expect, it } from "vitest"; + +import { + LatencySpanProcessor, + extractRoutePath, + latencySampleFromSpan, +} from "./latency-span-processor"; +import { getLatencySummary } from "./metrics"; + +/** Build a minimal ReadableSpan-shaped object for the fields the code reads. */ +function makeSpan(opts: { + kind?: SpanKind; + attributes?: Record; + durationMs?: number; +}): ReadableSpan { + const ms = opts.durationMs ?? 0; + const duration: HrTime = [Math.floor(ms / 1000), (ms % 1000) * 1e6]; + return { + kind: opts.kind ?? SpanKind.SERVER, + attributes: (opts.attributes ?? {}) as ReadableSpan["attributes"], + duration, + } as ReadableSpan; +} + +describe("extractRoutePath", () => { + it("prefers the matched route template over target/path", () => { + expect( + extractRoutePath({ + [ATTR_HTTP_ROUTE]: "/api/v1/projects/[id]", + [SEMATTRS_HTTP_TARGET]: "/api/v1/projects/abc123", + [ATTR_URL_PATH]: "/api/v1/projects/abc123", + } as ReadableSpan["attributes"]), + ).toBe("/api/v1/projects/[id]"); + }); + + it("falls back to http.target, then url.path", () => { + expect( + extractRoutePath({ + [SEMATTRS_HTTP_TARGET]: "/dashboard", + } as ReadableSpan["attributes"]), + ).toBe("/dashboard"); + expect( + extractRoutePath({ + [ATTR_URL_PATH]: "/settings", + } as ReadableSpan["attributes"]), + ).toBe("/settings"); + }); + + it("strips query strings and fragments", () => { + expect( + extractRoutePath({ + [SEMATTRS_HTTP_TARGET]: "/api/search?q=hello#frag", + } as ReadableSpan["attributes"]), + ).toBe("/api/search"); + }); + + it("returns undefined when no path attribute is present", () => { + expect(extractRoutePath({} as ReadableSpan["attributes"])).toBeUndefined(); + }); +}); + +describe("latencySampleFromSpan", () => { + it("records a normalized route + rounded ms for a server HTTP span", () => { + const sample = latencySampleFromSpan( + makeSpan({ + kind: SpanKind.SERVER, + attributes: { [SEMATTRS_HTTP_TARGET]: "/o/acme/p/web/dashboard" }, + durationMs: 42, + }), + ); + expect(sample).toEqual({ + route: "/o/[orgSlug]/p/[projectSlug]/dashboard", + ms: 42, + }); + }); + + it("collapses dynamic id segments to bound cardinality", () => { + const sample = latencySampleFromSpan( + makeSpan({ + attributes: { + [ATTR_URL_PATH]: + "/api/v1/projects/550e8400-e29b-41d4-a716-446655440000/tasks", + }, + durationMs: 12, + }), + ); + expect(sample?.route).toBe("/api/v1/projects/[id]/tasks"); + }); + + it("ignores non-SERVER spans (outbound client calls)", () => { + expect( + latencySampleFromSpan( + makeSpan({ + kind: SpanKind.CLIENT, + attributes: { [SEMATTRS_HTTP_TARGET]: "/api/whatever" }, + durationMs: 5, + }), + ), + ).toBeNull(); + }); + + it("excludes Next.js static assets", () => { + for (const path of [ + "/_next/static/chunks/main.js", + "/_next/image?url=%2Flogo.png", + "/favicon.ico", + "/assets/logo.svg", + "/styles/app.css", + ]) { + expect( + latencySampleFromSpan( + makeSpan({ attributes: { [SEMATTRS_HTTP_TARGET]: path }, durationMs: 3 }), + ), + ).toBeNull(); + } + }); + + it("returns null when the span carries no path", () => { + expect(latencySampleFromSpan(makeSpan({ durationMs: 9 }))).toBeNull(); + }); +}); + +describe("LatencySpanProcessor.onEnd", () => { + it("feeds the in-process latency store", () => { + const proc = new LatencySpanProcessor(); + const route = "/api/test/processor-onend"; + for (let i = 0; i < 5; i++) { + proc.onEnd( + makeSpan({ + kind: SpanKind.SERVER, + attributes: { [ATTR_HTTP_ROUTE]: route }, + durationMs: 20, + }), + ); + } + const summary = getLatencySummary()[route]; + expect(summary).toBeDefined(); + expect(summary.count).toBe(5); + expect(summary.p50).toBe(20); + }); + + it("does not record excluded spans", () => { + const proc = new LatencySpanProcessor(); + proc.onEnd( + makeSpan({ + kind: SpanKind.CLIENT, + attributes: { [ATTR_HTTP_ROUTE]: "/api/test/should-not-record" }, + durationMs: 20, + }), + ); + expect(getLatencySummary()["/api/test/should-not-record"]).toBeUndefined(); + }); + + it("never throws even on a malformed span", () => { + const proc = new LatencySpanProcessor(); + expect(() => proc.onEnd({} as ReadableSpan)).not.toThrow(); + }); +}); diff --git a/src/lib/observability/latency-span-processor.ts b/src/lib/observability/latency-span-processor.ts new file mode 100644 index 000000000..8c1078468 --- /dev/null +++ b/src/lib/observability/latency-span-processor.ts @@ -0,0 +1,112 @@ +// Copyright (c) 2026 Interactor, Inc. +// SPDX-License-Identifier: AGPL-3.0-or-later + +/** + * OpenTelemetry SpanProcessor that feeds the in-process latency store + * (`recordLatency`) so the admin Prod Metrics "Request Latency" section + * populates from real traffic. + * + * Why a span processor (not per-handler wrappers, not middleware): + * - The OTel HTTP auto-instrumentation already emits one SERVER span per + * incoming request, so `onEnd()` captures EVERY route uniformly with no + * per-handler edits. + * - `src/middleware.ts` runs on the Edge runtime and cannot reach the + * Node-only ioredis-backed store in `metrics.ts` — capture must happen in + * the Node server process, which is exactly where span processors run. + * + * CRITICAL: this processor must be registered on the NodeSDK regardless of + * whether an OTLP export endpoint is configured (see instrumentation.ts). + * The store is a local in-memory buffer; it does not need a remote collector. + */ + +import { SpanKind, type Context } from "@opentelemetry/api"; +import type { + ReadableSpan, + Span, + SpanProcessor, +} from "@opentelemetry/sdk-trace-base"; +import { + ATTR_HTTP_ROUTE, + ATTR_URL_PATH, + SEMATTRS_HTTP_TARGET, +} from "@opentelemetry/semantic-conventions"; + +import { normalizeRoute } from "@/lib/telemetry/normalize-route"; +import { recordLatency } from "./metrics"; + +// Path prefixes for Next.js static assets we never want in the latency table. +const STATIC_PREFIXES = ["/_next/static", "/_next/image", "/favicon"]; + +// Static asset file extensions (fonts, images, scripts, styles, source maps). +const STATIC_EXT_RE = + /\.(?:js|mjs|css|map|json|txt|xml|ico|png|jpe?g|gif|svg|webp|avif|woff2?|ttf|otf|eot)$/i; + +function isStaticAsset(path: string): boolean { + if (STATIC_PREFIXES.some((prefix) => path.startsWith(prefix))) return true; + return STATIC_EXT_RE.test(path); +} + +/** + * Pull the request path from a server span's attributes, preferring the + * matched route template (`http.route`) over the raw target/path so keys stay + * low-cardinality even before normalization. Query/fragment are stripped. + * Exported for unit testing. + */ +export function extractRoutePath(attributes: ReadableSpan["attributes"]): string | undefined { + const raw = + attributes[ATTR_HTTP_ROUTE] ?? + attributes[SEMATTRS_HTTP_TARGET] ?? + attributes[ATTR_URL_PATH]; + if (typeof raw !== "string" || raw.length === 0) return undefined; + return raw.split("?")[0].split("#")[0]; +} + +/** Convert an OTel HrTime `[seconds, nanos]` duration to whole milliseconds. */ +function durationToMs(duration: ReadableSpan["duration"]): number { + const [seconds, nanos] = duration; + return Math.round(seconds * 1e3 + nanos / 1e6); +} + +/** + * Decide whether a finished span should be recorded, and return the normalized + * route key + latency in ms. Returns `null` when the span is not an eligible + * incoming HTTP request (wrong kind, no path, or a static asset). Exported so + * the routing/exclusion logic can be unit-tested without a live SDK. + */ +export function latencySampleFromSpan( + span: ReadableSpan, +): { route: string; ms: number } | null { + if (span.kind !== SpanKind.SERVER) return null; + const path = extractRoutePath(span.attributes); + if (!path) return null; + if (isStaticAsset(path)) return null; + return { route: normalizeRoute(path), ms: durationToMs(span.duration) }; +} + +/** + * SpanProcessor implementation. `onEnd` is the only hook that does work; the + * rest are no-ops required by the interface. All logic is guarded so a bad span + * can never take down request handling. + */ +export class LatencySpanProcessor implements SpanProcessor { + onStart(_span: Span, _parentContext: Context): void { + // no-op — latency is derived from the completed span in onEnd. + } + + onEnd(span: ReadableSpan): void { + try { + const sample = latencySampleFromSpan(span); + if (sample) recordLatency(sample.route, sample.ms); + } catch { + // Instrumentation must never throw into the request path. + } + } + + forceFlush(): Promise { + return Promise.resolve(); + } + + shutdown(): Promise { + return Promise.resolve(); + } +} diff --git a/src/lib/observability/metrics.test.ts b/src/lib/observability/metrics.test.ts new file mode 100644 index 000000000..2761c70bc --- /dev/null +++ b/src/lib/observability/metrics.test.ts @@ -0,0 +1,65 @@ +// Copyright (c) 2026 Interactor, Inc. +// SPDX-License-Identifier: AGPL-3.0-or-later + +import { describe, expect, it } from "vitest"; + +import { + getLatencySummary, + percentile, + recordLatency, +} from "./metrics"; + +describe("percentile", () => { + it("returns 0 for an empty sample set", () => { + expect(percentile([], 50)).toBe(0); + expect(percentile([], 99)).toBe(0); + }); + + it("computes nearest-rank percentiles on a sorted array", () => { + const sorted = [1, 2, 3, 4, 5, 6, 7, 8, 9, 10]; + expect(percentile(sorted, 50)).toBe(5); + expect(percentile(sorted, 95)).toBe(10); + expect(percentile(sorted, 99)).toBe(10); + }); + + it("clamps the index to the first element for tiny percentiles", () => { + expect(percentile([3, 6, 9], 1)).toBe(3); + }); + + it("rounds fractional samples", () => { + expect(percentile([1.2, 1.6, 2.4], 50)).toBe(2); + }); +}); + +describe("recordLatency + getLatencySummary", () => { + it("aggregates recorded samples into p50/p95/p99 with a count", () => { + // Unique route key so the shared in-process store doesn't collide with + // other tests appending to the same map. + const route = "/api/test/aggregate"; + for (let ms = 1; ms <= 100; ms++) recordLatency(route, ms); + + const summary = getLatencySummary()[route]; + expect(summary).toBeDefined(); + expect(summary.count).toBe(100); + expect(summary.p50).toBe(50); + expect(summary.p95).toBe(95); + expect(summary.p99).toBe(99); + }); + + it("bounds each route buffer to the rolling 500-sample window", () => { + const route = "/api/test/window"; + // Push 600 samples; only the last 500 (values 101..600) should survive. + for (let ms = 1; ms <= 600; ms++) recordLatency(route, ms); + + const summary = getLatencySummary()[route]; + expect(summary.count).toBe(500); + // p50 of 101..600 is the 250th value ⇒ 350. + expect(summary.p50).toBe(350); + // Nearest-rank p99 = ceil(0.99*500)-1 = index 494 ⇒ 595. + expect(summary.p99).toBe(595); + }); + + it("omits routes that never received a sample", () => { + expect(getLatencySummary()["/api/test/never-recorded"]).toBeUndefined(); + }); +});