diff --git a/README.md b/README.md index 6a4f0cb..614bfcb 100644 --- a/README.md +++ b/README.md @@ -58,6 +58,39 @@ query { } ``` +## Observability + +Prometheus metrics are exposed on `GET /metrics` (public, no API key required). + +Alongside the ingestion and database metrics, Lens exports the three HTTP +signals needed to answer "is the API healthy": + +| Metric | Type | Labels | +|---|---|---| +| `http_requests_total` | Counter | `method`, `route`, `status_class` | +| `http_request_duration_seconds` | Histogram | `method`, `route` | + +`route` is the matched route **template** (`/price/:assetA/:assetB`), never the +resolved URL, so the number of time series stays bounded no matter how many +distinct assets are queried. `status_class` is `2xx`/`4xx`/`5xx` rather than the +exact code, for the same reason. + +```promql +# Request rate +sum(rate(http_requests_total[5m])) by (route) + +# Error rate +sum(rate(http_requests_total{status_class="5xx"}[5m])) + / sum(rate(http_requests_total[5m])) + +# p95 latency +histogram_quantile(0.95, + sum(rate(http_request_duration_seconds_bucket[5m])) by (le)) +``` + +See [`docs/http-metrics.md`](docs/http-metrics.md) for the full label reference, +the bucket rationale and suggested alerting rules. + ## Usage Examples Lens gates `/price`, `/pools`, and `/candles` behind x402 micropayments on Stellar (testnet by default). The `/status` endpoint is free. diff --git a/docs/http-metrics.md b/docs/http-metrics.md new file mode 100644 index 0000000..00a97f7 --- /dev/null +++ b/docs/http-metrics.md @@ -0,0 +1,142 @@ +# HTTP metrics + +Lens exports Prometheus metrics for the HTTP layer on the existing public +`/metrics` route, alongside the ingestion and database metrics defined in +[`src/metrics.ts`](../src/metrics.ts). + +These three signals — request rate, error rate and p95 latency — are what answer +"is the API healthy". The pre-existing `price_requests_total` counts price calls +specifically and cannot answer that question; it is unchanged and still means +what it always meant. + +## What is exported + +### `http_requests_total` + +Counter. Labels: `method`, `route`, `status_class`. + +| Label | Values | Notes | +| --- | --- | --- | +| `method` | `GET`, `POST`, … | The HTTP method. | +| `route` | `/price/:assetA/:assetB`, `/status`, … | The matched Fastify route **template**, never the resolved URL. Unrouted requests get the literal `unmatched`. | +| `status_class` | `2xx`, `3xx`, `4xx`, `5xx` | The status class, not the exact code. | + +### `http_request_duration_seconds` + +Histogram. Labels: `method`, `route`. + +Buckets: `0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10`. + +Observed for every request that produces a response, successful or not. + +## Why the labels look like this + +Cardinality is the whole design constraint. A histogram labelled by `req.url` +would mint a new time series for every asset pair, every address and every +cursor Lens is asked about — an unbounded set driven by callers, which +eventually degrades the Prometheus instance scraping it. + +So: + +- **`route` is the route template.** Fastify exposes the matched route on + `req.routeOptions.url`; that is what is used. 100 requests to 100 distinct + addresses produce **one** series, not 100 — asserted in + [`tests/httpMetrics.test.ts`](../tests/httpMetrics.test.ts). +- **Unmatched requests collapse to `unmatched`.** A 404 uses the literal string + rather than the raw path, so a scanner probing a thousand URLs cannot mint a + thousand series. +- **`status_class`, not `status`.** This bounds the series count at + `methods x routes x 5` rather than `methods x routes x ~60`. If a concrete + need for an exact code appears, add it then — it is easy to add a label and + painful to remove one dashboards depend on. + +## Bucket choice + +The prom-client defaults cluster below 1s and suit fast in-process handlers. +Lens handlers are not that: a request does a Redis cache lookup (single-digit +ms) or, on a miss, a Postgres aggregate query plus — for `/price` and `/route` — +Horizon/Soroswap network round-trips. + +The buckets therefore give resolution in two regions: + +- **5ms–50ms** — cache hits, the common fast path. Enough granularity to see the + Redis path regress before users notice. +- **100ms–2.5s** — DB aggregates and upstream venue calls. This is where p95 + actually lives and where an SLO would be set. + +The 5s and 10s buckets catch upstream stalls short of a timeout. Anything slower +lands in `+Inf` and surfaces as a saturated p99. + +## Registration order + +The hook is registered **first** in [`src/index.ts`](../src/index.ts) — ahead of +the network selector, API-key auth, the rate limiter and x402. + +This matters. All of those reject requests from an `onRequest` hook, and Fastify +runs `onRequest` hooks in registration order. Registering the metrics plugin +later would mean a request rejected by auth or x402 short-circuits before the +timer starts, losing exactly the 401/402/429 traffic an operator most wants to +see. + +`/metrics` itself is excluded from counting. It is scraped on a fixed interval, +so counting it would have the scraper continuously inflate the numbers it is +reading — request rate would never fall to zero on an idle service. + +## Queries + +```promql +# Request rate (per second, 5m window) +sum(rate(http_requests_total[5m])) by (route) + +# Error rate as a fraction of all requests +sum(rate(http_requests_total{status_class="5xx"}[5m])) + / sum(rate(http_requests_total[5m])) + +# p95 latency across the service +histogram_quantile(0.95, + sum(rate(http_request_duration_seconds_bucket[5m])) by (le)) + +# p95 latency per route — find which endpoint is slow +histogram_quantile(0.95, + sum(rate(http_request_duration_seconds_bucket[5m])) by (le, route)) +``` + +## Suggested alerts + +These are starting points; tune the thresholds against observed traffic before +paging anyone with them. + +```yaml +groups: + - name: lens-http + rules: + - alert: LensHighErrorRate + expr: | + sum(rate(http_requests_total{status_class="5xx"}[5m])) + / sum(rate(http_requests_total[5m])) > 0.05 + for: 10m + labels: { severity: critical } + annotations: + summary: "Lens is serving over 5% 5xx" + + - alert: LensHighLatencyP95 + expr: | + histogram_quantile(0.95, + sum(rate(http_request_duration_seconds_bucket[5m])) by (le)) > 2.5 + for: 15m + labels: { severity: warning } + annotations: + summary: "Lens p95 latency above 2.5s" + + - alert: LensNoTraffic + expr: sum(rate(http_requests_total[10m])) == 0 + for: 15m + labels: { severity: warning } + annotations: + summary: "Lens is serving no requests — check ingress or the scraper" +``` + +A note on `LensHighErrorRate`: the ratio is undefined when there is no traffic, +which is why `LensNoTraffic` exists separately rather than trying to make one +rule cover both. A service serving zero requests is a real problem that an error +*ratio* will never fire on. diff --git a/src/index.ts b/src/index.ts index 8e3e29c..e2c11c0 100644 --- a/src/index.ts +++ b/src/index.ts @@ -20,6 +20,7 @@ import { registerScreenerRoutes } from './routes/screener' import { registerHistoryRoutes } from './api/history' import { registerX402 } from './middleware/x402' import { registerNetworkSelector } from './middleware/network' +import { registerHttpMetrics } from './middleware/httpMetrics' import { registerWebSocket } from './api/websocket' import { registerApiKeyAuth } from './api/auth' import { registerAdminRoutes } from './api/admin' @@ -64,6 +65,12 @@ async function main() { await app.register(cors, { origin: true }) await app.register(compress) + // HTTP request/latency metrics. Registered FIRST, ahead of the network + // selector, API-key auth, the rate limiter and x402, so that requests those + // plugins reject (400/401/402/429) still have their timer started and are + // counted. See src/middleware/httpMetrics.ts. + await app.register(registerHttpMetrics) + // Resolves the per-request Stellar network (?network= query param / x-network // header) onto req.network, validating it (400 on an unrecognised value). // Runs in onRequest, ahead of API-key auth/rate-limiting/x402 and every route diff --git a/src/metrics.ts b/src/metrics.ts index f42c717..738f2a5 100644 --- a/src/metrics.ts +++ b/src/metrics.ts @@ -46,6 +46,38 @@ export const last_trade_timestamp = new Gauge({ registers: [register] }) +export const http_requests_total = new Counter({ + name: 'http_requests_total', + help: 'Total number of HTTP requests served, by method, route template and status class', + // `route` is the matched Fastify route TEMPLATE (e.g. /price/:assetA/:assetB), + // never the resolved URL — resolving it would mint a new time series per + // asset pair, address and cursor and eventually overwhelm Prometheus. + // `status_class` is 2xx/4xx/5xx rather than the exact code for the same + // reason; add an exact-status label only if a concrete need appears. + labelNames: ['method', 'route', 'status_class'], + registers: [register] +}) + +export const http_request_duration_seconds = new Histogram({ + name: 'http_request_duration_seconds', + help: 'Duration of HTTP requests in seconds, by method and route template', + labelNames: ['method', 'route'], + // Buckets are chosen for THIS service, not prom-client's defaults. The + // defaults top out at 10s and cluster below 1s, which suits fast in-process + // handlers; Lens handlers are not that. A typical request does a Redis cache + // lookup (single-digit ms) or, on a miss, a Postgres aggregate query plus — + // for /price and /route — Horizon/Soroswap network round-trips. So we want + // fine resolution across two regions: + // 5ms–50ms cache hits, the common fast path; enough granularity to see + // the Redis path regress before users notice. + // 100ms–2.5s DB aggregates and upstream venue calls, where p95 actually + // lives and where an SLO would be set. + // The 5s and 10s buckets exist to catch upstream stalls short of a timeout; + // anything slower falls in +Inf and shows up as a saturated p99. + buckets: [0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10], + registers: [register] +}) + export const db_query_duration_seconds = new Histogram({ name: 'db_query_duration_seconds', help: 'Duration of database queries in seconds', diff --git a/src/middleware/httpMetrics.ts b/src/middleware/httpMetrics.ts new file mode 100644 index 0000000..82ada90 --- /dev/null +++ b/src/middleware/httpMetrics.ts @@ -0,0 +1,91 @@ +import type { FastifyInstance, FastifyRequest, FastifyReply } from 'fastify' +import fp from 'fastify-plugin' +import { http_requests_total, http_request_duration_seconds } from '../metrics' + +/** Symbol key for the per-request start time, kept off the public request shape. */ +const START_TIME = Symbol('lens.httpMetrics.start') + +interface TimedRequest extends FastifyRequest { + [START_TIME]?: bigint +} + +/** + * Routes excluded from HTTP metrics. `/metrics` is scraped on a fixed interval, + * so counting it would have the scraper continuously inflate the very numbers + * it is reading — request rate would never fall to zero on an idle service. + */ +const EXCLUDED_ROUTES = new Set(['/metrics']) + +/** + * Bucket a status code into a class label. Keeping 2xx/4xx/5xx rather than the + * exact code bounds the series count at (methods x routes x 5) instead of + * (methods x routes x ~60). + */ +export function statusClass(statusCode: number): string { + if (statusCode >= 500) return '5xx' + if (statusCode >= 400) return '4xx' + if (statusCode >= 300) return '3xx' + if (statusCode >= 200) return '2xx' + return '1xx' +} + +/** + * The route-template label for a request. + * + * Fastify exposes the matched route on `req.routeOptions.url` — that is the + * TEMPLATE (`/price/:assetA/:assetB`), which is what we want. `req.url` is the + * resolved path and must never be used as a label: every distinct asset pair, + * address or cursor would become its own time series. + * + * When nothing matched (404, or a request rejected before routing resolved) we + * emit the literal `unmatched` rather than the raw path, so a scanner probing + * a thousand URLs produces one series, not a thousand. + */ +export function routeLabel(req: FastifyRequest): string { + return req.routeOptions?.url ?? 'unmatched' +} + +async function httpMetricsPlugin(app: FastifyInstance) { + // onRequest is the earliest hook in the lifecycle, so the timer starts before + // auth, rate limiting and x402 run — their rejections are real latency the + // caller experienced and belong in the histogram. + app.addHook('onRequest', async (req: TimedRequest) => { + req[START_TIME] = process.hrtime.bigint() + }) + + // onResponse fires for EVERY response that is sent, including ones produced + // by an error handler, by a `reply.send()` inside an onRequest hook (401 from + // auth, 402 from x402, 429 from the rate limiter) and by the default 404 + // handler. That is why the observation lives here and not in onSend or in a + // route wrapper — a 500 that escaped the counter is the exact case this + // exists to catch. + app.addHook('onResponse', async (req: TimedRequest, reply: FastifyReply) => { + const route = routeLabel(req) + if (EXCLUDED_ROUTES.has(route)) return + + const method = req.method + const code = reply.statusCode + + http_requests_total.inc({ method, route, status_class: statusClass(code) }) + + const start = req[START_TIME] + if (start !== undefined) { + const seconds = Number(process.hrtime.bigint() - start) / 1e9 + http_request_duration_seconds.observe({ method, route }, seconds) + } + }) +} + +/** + * Exports `http_requests_total` and `http_request_duration_seconds` on the + * shared Prometheus registry. + * + * Registration order matters: this plugin must be registered BEFORE the x402, + * auth and rate-limit plugins. All four attach `onRequest` hooks and Fastify + * runs them in registration order, so registering later would mean a request + * rejected by auth or x402 short-circuits before the timer starts and goes + * uncounted — losing exactly the 401/402/429 traffic an operator most wants to + * see. `onResponse` still fires for those rejections either way; it is the + * start timestamp that would be missing. + */ +export const registerHttpMetrics = fp(httpMetricsPlugin, { name: 'http-metrics' }) diff --git a/tests/httpMetrics.test.ts b/tests/httpMetrics.test.ts new file mode 100644 index 0000000..cb03014 --- /dev/null +++ b/tests/httpMetrics.test.ts @@ -0,0 +1,216 @@ +import { describe, it, expect, beforeEach } from 'vitest' +import Fastify, { type FastifyInstance } from 'fastify' +import { registerHttpMetrics, statusClass, routeLabel } from '../src/middleware/httpMetrics' +import { register, http_requests_total, http_request_duration_seconds } from '../src/metrics' + +/** Every `http_requests_total` sample currently in the registry. */ +async function requestSamples() { + const metric = await register.getSingleMetric('http_requests_total')!.get() + return metric.values +} + +/** Every `http_request_duration_seconds` sample currently in the registry. */ +async function durationSamples() { + const metric = await register.getSingleMetric('http_request_duration_seconds')!.get() + return metric.values +} + +/** The `_count` samples of the duration histogram — one per label combination. */ +async function durationCounts() { + return (await durationSamples()).filter(v => v.metricName === 'http_request_duration_seconds_count') +} + +/** + * Builds an app wired the way src/index.ts wires it: the metrics plugin is + * registered FIRST, ahead of the hooks that can reject a request, so the + * rejection paths are exercised by these tests the same way they are in + * production. + */ +async function buildApp(): Promise { + const app = Fastify() + await app.register(registerHttpMetrics) + + // Stands in for the API-key auth hook: rejects in onRequest, before routing + // completes, exactly as src/api/auth.ts does. + app.addHook('onRequest', async (req, reply) => { + if (req.headers['x-fail-auth']) { + return reply.status(401).send({ error: 'Unauthorized' }) + } + }) + + app.get('/price/:assetA/:assetB', async () => ({ ok: true })) + app.get('/status', async () => ({ ok: true })) + app.get('/boom', async () => { + throw new Error('intentional failure') + }) + app.get('/bad', async (_req, reply) => reply.status(400).send({ error: 'Bad Request' })) + app.get('/metrics', async () => 'metrics body') + + await app.ready() + return app +} + +let app: FastifyInstance + +beforeEach(async () => { + http_requests_total.reset() + http_request_duration_seconds.reset() + app = await buildApp() +}) + +describe('statusClass', () => { + it('buckets codes into classes rather than keeping the exact code', () => { + expect(statusClass(200)).toBe('2xx') + expect(statusClass(204)).toBe('2xx') + expect(statusClass(301)).toBe('3xx') + expect(statusClass(400)).toBe('4xx') + expect(statusClass(404)).toBe('4xx') + expect(statusClass(429)).toBe('4xx') + expect(statusClass(500)).toBe('5xx') + expect(statusClass(503)).toBe('5xx') + }) +}) + +describe('routeLabel', () => { + it('falls back to the literal "unmatched" when no route resolved', () => { + expect(routeLabel({ routeOptions: undefined } as never)).toBe('unmatched') + expect(routeLabel({ routeOptions: { url: undefined } } as never)).toBe('unmatched') + }) +}) + +describe('label cardinality', () => { + it('collapses 100 requests to distinct addresses into a single series', async () => { + for (let i = 0; i < 100; i++) { + await app.inject({ method: 'GET', url: `/price/XLM/GABC${i}DEADBEEF` }) + } + + const samples = await requestSamples() + expect(samples).toHaveLength(1) + expect(samples[0].labels).toEqual({ + method: 'GET', + route: '/price/:assetA/:assetB', + status_class: '2xx', + }) + expect(samples[0].value).toBe(100) + + // The resolved URL must never appear in a label. + const serialised = JSON.stringify(samples) + expect(serialised).not.toContain('DEADBEEF') + + const counts = await durationCounts() + expect(counts).toHaveLength(1) + expect(counts[0].value).toBe(100) + }) + + it('does not create a series per path for unmatched routes', async () => { + for (let i = 0; i < 25; i++) { + await app.inject({ method: 'GET', url: `/no/such/route/${i}` }) + } + + const samples = await requestSamples() + expect(samples).toHaveLength(1) + expect(samples[0].labels.route).toBe('unmatched') + expect(samples[0].labels.status_class).toBe('4xx') + expect(samples[0].value).toBe(25) + }) +}) + +describe('error accounting', () => { + it('counts a 5xx from a handler that throws', async () => { + const res = await app.inject({ method: 'GET', url: '/boom' }) + expect(res.statusCode).toBe(500) + + const samples = await requestSamples() + expect(samples).toHaveLength(1) + expect(samples[0].labels).toEqual({ method: 'GET', route: '/boom', status_class: '5xx' }) + expect(samples[0].value).toBe(1) + }) + + it('distinguishes 4xx from 5xx', async () => { + await app.inject({ method: 'GET', url: '/bad' }) + await app.inject({ method: 'GET', url: '/boom' }) + + const byClass = Object.fromEntries( + (await requestSamples()).map(s => [s.labels.status_class, s.value]) + ) + expect(byClass['4xx']).toBe(1) + expect(byClass['5xx']).toBe(1) + }) + + it('counts a request rejected by an auth hook before routing completes', async () => { + const res = await app.inject({ + method: 'GET', + url: '/price/XLM/USDC', + headers: { 'x-fail-auth': '1' }, + }) + expect(res.statusCode).toBe(401) + + const samples = await requestSamples() + expect(samples).toHaveLength(1) + expect(samples[0].labels.status_class).toBe('4xx') + expect(samples[0].value).toBe(1) + }) +}) + +describe('latency observation', () => { + it('observes duration for both successful and failed requests', async () => { + await app.inject({ method: 'GET', url: '/status' }) + await app.inject({ method: 'GET', url: '/boom' }) + + const byRoute = Object.fromEntries( + (await durationCounts()).map(s => [s.labels.route, s.value]) + ) + expect(byRoute['/status']).toBe(1) + expect(byRoute['/boom']).toBe(1) + }) + + it('records a non-negative, finite duration in the histogram sum', async () => { + await app.inject({ method: 'GET', url: '/status' }) + + const sum = (await durationSamples()).find( + v => v.metricName === 'http_request_duration_seconds_sum' + ) + expect(sum).toBeDefined() + expect(sum!.value).toBeGreaterThanOrEqual(0) + expect(Number.isFinite(sum!.value)).toBe(true) + }) +}) + +describe('scrape endpoint', () => { + it('does not count /metrics, so the scraper cannot inflate its own numbers', async () => { + await app.inject({ method: 'GET', url: '/metrics' }) + await app.inject({ method: 'GET', url: '/metrics' }) + + expect(await requestSamples()).toHaveLength(0) + expect(await durationCounts()).toHaveLength(0) + }) + + it('exposes both metric families on the shared registry', async () => { + await app.inject({ method: 'GET', url: '/status' }) + + const exported = await register.metrics() + expect(exported).toContain('http_requests_total') + expect(exported).toContain('http_request_duration_seconds') + }) +}) + +describe('method label', () => { + it('separates methods on the same route template', async () => { + const methodApp = Fastify() + await methodApp.register(registerHttpMetrics) + methodApp.get('/thing', async () => ({ ok: true })) + methodApp.post('/thing', async () => ({ ok: true })) + await methodApp.ready() + + await methodApp.inject({ method: 'GET', url: '/thing' }) + await methodApp.inject({ method: 'POST', url: '/thing' }) + + const byMethod = Object.fromEntries( + (await requestSamples()).map(s => [s.labels.method, s.value]) + ) + expect(byMethod['GET']).toBe(1) + expect(byMethod['POST']).toBe(1) + + await methodApp.close() + }) +})