From 5d86799344f2c5d280043460d839575f4fdff798 Mon Sep 17 00:00:00 2001 From: Pro-builder Date: Sat, 17 Oct 2026 13:53:20 +0100 Subject: [PATCH] feat: add request tracing and logging, enforce api versions, fix etag matching --- backend/__tests__/server.test.ts | 71 +++++++++ backend/server.ts | 45 +++++- backend/server/createApiServer.ts | 15 ++ .../shared/__tests__/apiVersioning.test.ts | 16 +- .../shared/__tests__/compression.test.ts | 15 ++ backend/services/shared/apiVersioning.ts | 29 ++-- backend/services/shared/compression.ts | 13 +- .../__tests__/requestObservability.test.ts | 137 +++++++++++++++++ backend/shared/middleware/index.ts | 7 + .../shared/middleware/requestObservability.ts | 141 ++++++++++++++++++ docs/api-logging.md | 37 +++++ docs/api-versioning.md | 51 ++++++- docs/distributed-tracing.md | 53 ++++--- docs/etag-caching.md | 24 ++- 14 files changed, 597 insertions(+), 57 deletions(-) create mode 100644 backend/shared/middleware/__tests__/requestObservability.test.ts create mode 100644 backend/shared/middleware/requestObservability.ts diff --git a/backend/__tests__/server.test.ts b/backend/__tests__/server.test.ts index ecd9ebde..dc0fc525 100644 --- a/backend/__tests__/server.test.ts +++ b/backend/__tests__/server.test.ts @@ -12,6 +12,7 @@ import type { RedisClient } from '../shared/cache/types'; import { setPlanCacheService } from '../subscription/planCacheRegistry'; import { buildMetricsService } from '../services/shared/buildMetricsService'; import { rateLimitingService } from '../services/shared/rateLimitingService'; +import { InMemorySpanExporter, Sampler, Tracer } from '../services/shared/tracing'; class FakeRedis implements RedisClient { private store = new Map(); @@ -515,3 +516,73 @@ describe('backend server', () => { }); }); }); + +describe('backend server: conditional requests, versioning and request tracing', () => { + let running: Awaited>; + let port: number; + const exporter = new InMemorySpanExporter(); + + beforeEach(async () => { + exporter.reset(); + const tracer = new Tracer({ + serviceName: 'subtrackr-backend', + exporter, + sampler: new Sampler({ defaultRatio: 1, alwaysSampleErrors: true }), + }); + running = await startServer({ + pool: makeMockPool(), + planBootstrap: makeBootstrap(), + listen: false, + tracer, + }); + port = await listenEphemeral(running.server); + jest.spyOn(console, 'log').mockImplementation(() => undefined); + }); + + afterEach(async () => { + jest.restoreAllMocks(); + await running.shutdown(); + setPlanCacheService(null); + }); + + it('emits an ETag and answers 304 to a matching If-None-Match (issue #1788)', async () => { + const first = await request(port, '/plans/plan-1'); + const etag = first.headers['etag']; + expect(first.status).toBe(200); + expect(etag).toMatch(/^"[^"]+"$/); + + const exact = await request(port, '/plans/plan-1', 'GET', undefined, { 'If-None-Match': etag }); + expect(exact.status).toBe(304); + expect(exact.body).toBe(''); + + const list = await request(port, '/plans/plan-1', 'GET', undefined, { + 'If-None-Match': `"stale", W/${etag}`, + }); + expect(list.status).toBe(304); + + const stale = await request(port, '/plans/plan-1', 'GET', undefined, { 'If-None-Match': '"stale"' }); + expect(stale.status).toBe(200); + }); + + it('labels responses with the API version and rejects unknown versions (issue #1789)', async () => { + const ok = await request(port, '/health'); + expect(ok.headers['api-version']).toBe('v1'); + expect(ok.headers['deprecation']).toBeUndefined(); + + const unknown = await request(port, '/health', 'GET', undefined, { 'api-version': 'v9' }); + expect(unknown.status).toBe(400); + expect(JSON.parse(unknown.body).error.code).toBe('VERSION_NOT_FOUND'); + }); + + it('echoes the request id and exports a server span for it (issues #1790, #1791)', async () => { + const traceId = '4bf92f3577b34da6a3ce929d0e0e4736'; + const res = await request(port, '/plans/plan-1', 'GET', undefined, { + 'X-Request-Id': 'req-server-1', + traceparent: `00-${traceId}-00f067aa0ba902b7-01`, + }); + + expect(res.headers['x-request-id']).toBe('req-server-1'); + const span = exporter.getFinishedSpans().find((s) => s.attributes['request.id'] === 'req-server-1'); + expect(span).toMatchObject({ traceId, kind: 'server', name: 'GET /plans/plan-1' }); + }); +}); diff --git a/backend/server.ts b/backend/server.ts index 591c8b20..e7c3e9ca 100644 --- a/backend/server.ts +++ b/backend/server.ts @@ -54,6 +54,10 @@ import { } from './services/shared/ipWhitelistService'; import { serverSessionService } from './services/auth/serverSessionService'; import { buildMetricsService } from './services/shared/buildMetricsService'; +import { createVersionMiddleware, versionRegistry } from './services/shared/apiVersioning'; +import { createLoggerFor } from './services/shared/logging'; +import { createTracerFromEnv, type Tracer } from './services/shared/tracing'; +import { createRequestObservability } from './shared/middleware/requestObservability'; export interface StartServerOptions { port?: number; @@ -63,6 +67,8 @@ export interface StartServerOptions { planBootstrap?: PlanCacheBootstrap; /** When true, binds to port (default). Set false in tests. */ listen?: boolean; + /** Tracer for request spans. Defaults to one configured from OTEL_* env vars. */ + tracer?: Tracer; } export interface RunningServer { @@ -433,7 +439,13 @@ export async function startServer(options: StartServerOptions = {}): Promise { + const observeRequest = createRequestObservability({ + tracer: options.tracer ?? createTracerFromEnv('subtrackr-backend'), + logger: createLoggerFor('http'), + }); + const versionMiddleware = createVersionMiddleware(versionRegistry); + + const handleRequest = async ( + req: http.IncomingMessage, + res: http.ServerResponse, + ): Promise => { const url = new URL(req.url ?? '/', `http://${req.headers.host ?? 'localhost'}`); const { pathname } = url; const method = req.method ?? 'GET'; @@ -490,6 +511,20 @@ export async function startServer(options: StartServerOptions = {}): Promise { + versionAccepted = true; + }, + ); + if (!versionAccepted) return; + // ----------------------------------------------------------------- // IP Whitelist gate (issue #1158) — applied before all auth/rate-limit // ----------------------------------------------------------------- @@ -1738,7 +1773,11 @@ export async function startServer(options: StartServerOptions = {}): Promise + observeRequest(req, res, () => handleRequest(req, res)), + ); const port = options.port ?? Number(process.env.PORT ?? 3001); const host = options.host ?? process.env.HOST ?? '0.0.0.0'; diff --git a/backend/server/createApiServer.ts b/backend/server/createApiServer.ts index 79e090e3..0647b49c 100644 --- a/backend/server/createApiServer.ts +++ b/backend/server/createApiServer.ts @@ -25,6 +25,10 @@ import { createThemeRouter, } from '../subscription/router'; import { API_VERSION_HEADER, API_VERSION_VALUE } from '../services/shared/apiResponse'; +import { createVersionMiddleware, versionRegistry } from '../services/shared/apiVersioning'; +import { createLoggerFor } from '../services/shared/logging'; +import { createTracerFromEnv } from '../services/shared/tracing'; +import { createRequestObservability } from '../shared/middleware/requestObservability'; import { createApiKeyRevocationRouter, createPasskeyRouter } from '../services/auth/router/authRouter'; // ── Zapier integration ──────────────────────────────────────────────────────── @@ -156,6 +160,14 @@ export function createApiServer(options: CreateApiServerOptions = {}): Express { app.disable('x-powered-by'); + // Request id, structured access log and server span for every request. + app.use( + createRequestObservability({ + tracer: createTracerFromEnv('subtrackr-api'), + logger: createLoggerFor('http'), + }), + ); + // Provider webhooks are signed over the exact bytes that were sent, and // `express.json()` consumes the request stream. `express.raw` is therefore // registered for the webhook paths *before* the JSON parser, so @@ -193,6 +205,9 @@ export function createApiServer(options: CreateApiServerOptions = {}): Express { res.setHeader(API_VERSION_HEADER, API_VERSION_VALUE); next(); }); + // Resolves the version from /api/vN, the `api-version` header or `?version=`; + // adds deprecation headers and rejects unknown or sunset versions. + app.use(createVersionMiddleware(versionRegistry) as unknown as express.RequestHandler); // ── CDN-cached public routes ─────────────────────────────────────────────── app.use(cacheHeadersMiddleware()); diff --git a/backend/services/shared/__tests__/apiVersioning.test.ts b/backend/services/shared/__tests__/apiVersioning.test.ts index 71f95a3e..fec0d841 100644 --- a/backend/services/shared/__tests__/apiVersioning.test.ts +++ b/backend/services/shared/__tests__/apiVersioning.test.ts @@ -750,21 +750,17 @@ describe('createVersionMiddleware — version resolution order', () => { // ─── Singleton versionRegistry ──────────────────────────────────────────────── describe('versionRegistry singleton', () => { - it('is exported and has v1 and v2 registered', () => { + it('registers v1, the version every route is served under', () => { expect(versionRegistry.has('v1')).toBe(true); - expect(versionRegistry.has('v2')).toBe(true); }); - it('default version is v2', () => { - expect(versionRegistry.getDefault()).toBe('v2'); + it('defaults to v1', () => { + expect(versionRegistry.getDefault()).toBe('v1'); }); - it('v1 is deprecated', () => { - expect(versionRegistry.get('v1')?.lifecycle).toBe('deprecated'); - }); - - it('v2 is active', () => { - expect(versionRegistry.get('v2')?.lifecycle).toBe('active'); + it('keeps v1 active so clients get no deprecation headers', () => { + expect(versionRegistry.get('v1')?.lifecycle).toBe('active'); + expect(versionRegistry.getDeprecationWarning('v1')).toBeNull(); }); }); diff --git a/backend/services/shared/__tests__/compression.test.ts b/backend/services/shared/__tests__/compression.test.ts index 4ddb85f3..9ed94a38 100644 --- a/backend/services/shared/__tests__/compression.test.ts +++ b/backend/services/shared/__tests__/compression.test.ts @@ -174,6 +174,21 @@ describe('isETagMatch', () => { const req = mockReq({ headers: {} }); expect(isETagMatch(req, '"abc"')).toBe(false); }); + + it('matches any tag in a comma-separated list', () => { + const req = mockReq({ headers: { 'if-none-match': '"old", "abc123" , "other"' } }); + expect(isETagMatch(req, '"abc123"')).toBe(true); + }); + + it('uses weak comparison so a W/ prefix still matches', () => { + const req = mockReq({ headers: { 'if-none-match': 'W/"abc123"' } }); + expect(isETagMatch(req, '"abc123"')).toBe(true); + }); + + it('does not match a tag that only shares a prefix', () => { + const req = mockReq({ headers: { 'if-none-match': '"abc"' } }); + expect(isETagMatch(req, '"abc123"')).toBe(false); + }); }); // ─── applyCompression — core behaviour ─────────────────────────────────────── diff --git a/backend/services/shared/apiVersioning.ts b/backend/services/shared/apiVersioning.ts index 729b59bf..0af6e395 100644 --- a/backend/services/shared/apiVersioning.ts +++ b/backend/services/shared/apiVersioning.ts @@ -376,6 +376,10 @@ export function resolveVersion( options: VersionExtractionOptions = {}, ): VersionResolution | null { const defaultVersion = registry.getDefault(); + // An explicitly requested version that is not registered is rejected rather + // than silently served as the default, so clients notice a typo or a + // version that never existed. + let requestedUnknown = false; // 1. Path if (opts.path && options.fromPath !== false) { @@ -383,6 +387,7 @@ export function resolveVersion( if (v && registry.has(v)) { return { version: v, source: 'path', config: registry.get(v)! }; } + if (v) requestedUnknown = true; } // 2. Header @@ -391,6 +396,7 @@ export function resolveVersion( if (v && registry.has(v)) { return { version: v, source: 'header', config: registry.get(v)! }; } + if (v) requestedUnknown = true; } // 3. Query param @@ -399,8 +405,11 @@ export function resolveVersion( if (v && registry.has(v)) { return { version: v, source: 'query', config: registry.get(v)! }; } + if (v) requestedUnknown = true; } + if (requestedUnknown) return null; + // 4. Default if (defaultVersion && registry.has(defaultVersion)) { return { version: defaultVersion, source: 'default', config: registry.get(defaultVersion)! }; @@ -586,26 +595,18 @@ export function createVersionMiddleware( // ─── Singleton registry ─────────────────────────────────────────────────────── /** - * Application-wide version registry. - * Pre-configured with SubTrackr's version history. + * Application-wide version registry. Mirrors what is actually served: every + * route is v1 (`/api/v1/*`, `X-API-Version: 1`). Register v2 here as `draft` + * when its first breaking change lands; see docs/api-versioning.md for the + * deprecation policy. */ export const versionRegistry = new ApiVersionRegistry(); versionRegistry .register({ version: 'v1', - lifecycle: 'deprecated', - releasedAt: '2024-01-01T00:00:00Z', - deprecatedAt: '2025-01-01T00:00:00Z', - sunsetAt: '2026-06-01T00:00:00Z', - successorVersion: 'v2', - migrationUrl: 'https://docs.subtrackr.io/migration/v1-to-v2', - description: 'Initial release. Deprecated in favour of v2.', - }) - .register({ - version: 'v2', lifecycle: 'active', - releasedAt: '2025-01-01T00:00:00Z', + releasedAt: '2024-01-01T00:00:00Z', description: 'Current stable API version.', }) - .setDefault('v2'); + .setDefault('v1'); diff --git a/backend/services/shared/compression.ts b/backend/services/shared/compression.ts index 4c3989ae..2d42d32b 100644 --- a/backend/services/shared/compression.ts +++ b/backend/services/shared/compression.ts @@ -131,10 +131,19 @@ export function generateETag(body: Buffer): string { return `"${hash.slice(0, 27)}"`; } +/** + * If-None-Match uses the weak comparison (RFC 9110 §13.1.2): the header may + * list several tags, and a `W/` prefix on either side is ignored. + */ export function isETagMatch(req: IncomingMessage, etag: string): boolean { - const ifNoneMatch = req.headers['if-none-match']; + const raw = req.headers['if-none-match']; + const ifNoneMatch = Array.isArray(raw) ? raw.join(',') : raw; if (!ifNoneMatch) return false; - return ifNoneMatch === etag || ifNoneMatch === '*'; + if (ifNoneMatch.trim() === '*') return true; + + const opaque = (tag: string) => tag.trim().replace(/^W\//, ''); + const target = opaque(etag); + return ifNoneMatch.split(',').some((candidate) => opaque(candidate) === target); } // ─── Compression ───────────────────────────────────────────────────────────── diff --git a/backend/shared/middleware/__tests__/requestObservability.test.ts b/backend/shared/middleware/__tests__/requestObservability.test.ts new file mode 100644 index 00000000..74f4b248 --- /dev/null +++ b/backend/shared/middleware/__tests__/requestObservability.test.ts @@ -0,0 +1,137 @@ +import http from 'node:http'; +import type { AddressInfo } from 'node:net'; + +import { + createRequestObservability, + resolveRequestId, + sanitizePath, +} from '../requestObservability'; +import { clearLogBuffer, createLoggerFor, logger as rootLogger, queryLogs } from '../../../services/shared/logging'; +import { InMemorySpanExporter, Sampler, Tracer } from '../../../services/shared/tracing'; + +const exporter = new InMemorySpanExporter(); +const tracer = new Tracer({ + serviceName: 'test-api', + exporter, + sampler: new Sampler({ defaultRatio: 1, alwaysSampleErrors: true }), +}); +const observe = createRequestObservability({ tracer, logger: createLoggerFor('http') }); + +let server: http.Server; +let baseUrl: string; + +beforeAll(async () => { + server = http.createServer((req, res) => + observe(req, res, () => { + // A log written by the handler must carry the request's correlation id. + rootLogger.info('handler ran'); + const status = req.url?.startsWith('/boom') ? 500 : 200; + res.writeHead(status, { 'Content-Type': 'application/json' }); + res.end(JSON.stringify({ ok: status === 200 })); + }), + ); + await new Promise((resolve) => server.listen(0, '127.0.0.1', resolve)); + baseUrl = `http://127.0.0.1:${(server.address() as AddressInfo).port}`; +}); + +afterAll(async () => { + await new Promise((resolve) => server.close(() => resolve())); +}); + +beforeEach(() => { + exporter.reset(); + clearLogBuffer(); + jest.spyOn(console, 'log').mockImplementation(() => undefined); + jest.spyOn(console, 'error').mockImplementation(() => undefined); +}); + +afterEach(() => { + jest.restoreAllMocks(); +}); + +const requestLogs = () => queryLogs({ text: 'http.request' }).filter((e) => e.message === 'http.request'); + +describe('resolveRequestId', () => { + it('keeps a well-formed caller id', () => { + expect(resolveRequestId('req-123_abc')).toBe('req-123_abc'); + }); + + it('replaces missing, oversized or unsafe ids with a uuid', () => { + const uuid = /^[0-9a-f-]{36}$/; + expect(resolveRequestId(undefined)).toMatch(uuid); + expect(resolveRequestId('a'.repeat(200))).toMatch(uuid); + expect(resolveRequestId('bad id\nwith newline')).toMatch(uuid); + }); +}); + +describe('sanitizePath', () => { + it('drops the query string and masks email and long number segments', () => { + expect(sanitizePath('/users/jane%40example.com/cards/4111111111111111?token=abc')).toBe( + '/users/:redacted/cards/:redacted', + ); + }); + + it('leaves ordinary ids alone', () => { + expect(sanitizePath('/plans/basic/42')).toBe('/plans/basic/42'); + }); +}); + +describe('request observability middleware', () => { + it('generates a request id, echoes it and uses it as the log correlation id', async () => { + const res = await fetch(`${baseUrl}/plans`); + const requestId = res.headers.get('x-request-id'); + + expect(requestId).toBeTruthy(); + const handlerLog = queryLogs({ text: 'handler ran' })[0]; + expect(handlerLog?.correlationId).toBe(requestId); + + const [log] = requestLogs(); + expect(log.correlationId).toBe(requestId); + expect(log.meta).toMatchObject({ requestId, method: 'GET', path: '/plans', status: 200 }); + }); + + it('propagates a caller-supplied request id', async () => { + const res = await fetch(`${baseUrl}/plans`, { headers: { 'X-Request-Id': 'client-abc-1' } }); + + expect(res.headers.get('x-request-id')).toBe('client-abc-1'); + expect(requestLogs()[0].correlationId).toBe('client-abc-1'); + }); + + it('exports a server span that continues the caller trace and matches the log', async () => { + const traceId = '4bf92f3577b34da6a3ce929d0e0e4736'; + const parentSpanId = '00f067aa0ba902b7'; + await fetch(`${baseUrl}/plans`, { + headers: { traceparent: `00-${traceId}-${parentSpanId}-01`, 'X-Request-Id': 'trace-1' }, + }); + + const [span] = exporter.getFinishedSpans(); + expect(span).toMatchObject({ + traceId, + parentSpanId, + kind: 'server', + name: 'GET /plans', + status: { code: 'ok' }, + }); + expect(span.attributes).toMatchObject({ 'request.id': 'trace-1', 'http.status_code': 200 }); + + const [log] = requestLogs(); + expect(log.meta).toMatchObject({ traceId, spanId: span.spanId }); + }); + + it('marks 5xx responses as errors on the span and the log', async () => { + await fetch(`${baseUrl}/boom`); + + expect(exporter.getFinishedSpans()[0].status.code).toBe('error'); + expect(requestLogs()[0].level).toBe('error'); + }); + + it('never logs query strings, headers or client addresses', async () => { + await fetch(`${baseUrl}/users/jane%40example.com?email=jane%40example.com&token=secret`, { + headers: { Authorization: 'Bearer secret-token', Cookie: 'sid=secret-cookie' }, + }); + + const serialized = JSON.stringify(requestLogs()) + JSON.stringify(exporter.getFinishedSpans()); + expect(serialized).not.toMatch(/jane|secret|token=|127\.0\.0\.1|authorization|cookie/i); + expect(requestLogs()[0].meta).toMatchObject({ path: '/users/:redacted' }); + }); +}); diff --git a/backend/shared/middleware/index.ts b/backend/shared/middleware/index.ts index 985a0615..200a77b8 100644 --- a/backend/shared/middleware/index.ts +++ b/backend/shared/middleware/index.ts @@ -42,3 +42,10 @@ export { applySecurityHeadersToResponse, } from './securityHeaders'; export type { SecurityHeadersOptions } from './securityHeaders'; +export { + REQUEST_ID_HEADER, + createRequestObservability, + resolveRequestId, + sanitizePath, +} from './requestObservability'; +export type { RequestObservabilityOptions } from './requestObservability'; diff --git a/backend/shared/middleware/requestObservability.ts b/backend/shared/middleware/requestObservability.ts new file mode 100644 index 00000000..91044b4b --- /dev/null +++ b/backend/shared/middleware/requestObservability.ts @@ -0,0 +1,141 @@ +/** + * Request observability middleware: request ids, structured access logs and a + * server span per request, all sharing the same identifiers so a log line can + * be found from a trace and the other way round. + * + * - `X-Request-Id` is taken from the caller when well formed, otherwise + * generated, and echoed on the response. + * - The handler runs inside the logger's correlation context, so every log + * written while serving the request carries `correlationId = requestId`. + * - A `server` span continues the caller's W3C `traceparent` (or starts a new + * trace) and is exported through the tracer when the response finishes. + * - One `http.request` log line is written per request with the request id, + * trace id and span id. + * + * No PII: query strings, headers, bodies and client IPs are never logged or + * recorded on spans, and path segments that look like emails or long numbers + * are masked. + * + * Works as Express middleware and with a raw `http.Server` handler: + * http.createServer((req, res) => observe(req, res, () => handle(req, res))); + */ + +import { randomUUID } from 'node:crypto'; +import type { IncomingMessage, ServerResponse } from 'node:http'; + +import { runWithLogContext, type Logger } from '../../services/shared/logging'; +import { extractContext, type Tracer } from '../../services/shared/tracing'; + +export const REQUEST_ID_HEADER = 'X-Request-Id'; + +const REQUEST_ID_PATTERN = /^[A-Za-z0-9._:-]{1,128}$/; +const EMAIL_SEGMENT = /^[^/@\s]+@[^/@\s]+$/; +const LONG_NUMBER_SEGMENT = /^\+?\d{7,}$/; + +/** Accept a caller-supplied id only if it is short and safe to log. */ +export function resolveRequestId(header: string | string[] | undefined): string { + const value = Array.isArray(header) ? header[0] : header; + return value && REQUEST_ID_PATTERN.test(value) ? value : randomUUID(); +} + +/** Path without the query string, with PII-looking segments masked. */ +export function sanitizePath(url: string | undefined): string { + const path = (url ?? '/').split('?')[0] || '/'; + return path + .split('/') + .map((segment) => { + let decoded = segment; + try { + decoded = decodeURIComponent(segment); + } catch { + // keep the raw segment + } + return EMAIL_SEGMENT.test(decoded) || LONG_NUMBER_SEGMENT.test(decoded) + ? ':redacted' + : segment; + }) + .join('/'); +} + +export interface RequestObservabilityOptions { + tracer: Tracer; + logger: Logger; +} + +type Next = () => unknown; + +export function createRequestObservability({ tracer, logger }: RequestObservabilityOptions) { + return function requestObservability( + req: IncomingMessage, + res: ServerResponse, + next: Next, + ): void { + const requestId = resolveRequestId(req.headers['x-request-id']); + const method = (req.method ?? 'GET').toUpperCase(); + const path = sanitizePath(req.url); + const startedAt = Date.now(); + + const span = tracer.startSpan(`${method} ${path}`, { + kind: 'server', + parent: extractContext(req.headers), + endpoint: path, + attributes: { + 'http.method': method, + 'http.target': path, + 'request.id': requestId, + }, + }); + + res.setHeader(REQUEST_ID_HEADER, requestId); + + let finished = false; + const finish = (aborted: boolean): void => { + if (finished) return; + finished = true; + + const status = res.statusCode; + span.setAttribute('http.status_code', status); + if (aborted) { + span.setStatus('error', 'client closed request'); + } else if (span.data.status.code !== 'error') { + span.setStatus(status >= 500 ? 'error' : 'ok'); + } + span.end(); + + const entry = { + requestId, + traceId: span.context.traceId, + spanId: span.context.spanId, + method, + path, + status, + durationMs: Date.now() - startedAt, + ...(aborted ? { aborted: true } : {}), + }; + runWithLogContext(requestId, () => { + if (status >= 500) logger.error('http.request', entry); + else if (status >= 400 || aborted) logger.warn('http.request', entry); + else logger.info('http.request', entry); + }); + }; + + res.once('finish', () => finish(false)); + res.once('close', () => finish(!res.writableFinished)); + + runWithLogContext(requestId, () => { + try { + const result = next(); + if (result && typeof (result as Promise).catch === 'function') { + // Record and rethrow so the rejection still surfaces as before. + (result as Promise).catch((error: unknown) => { + span.recordException(error); + throw error; + }); + } + } catch (error) { + span.recordException(error); + throw error; + } + }); + }; +} diff --git a/docs/api-logging.md b/docs/api-logging.md index 8c1f045d..15201696 100644 --- a/docs/api-logging.md +++ b/docs/api-logging.md @@ -93,6 +93,43 @@ Avoid logging sensitive data (private keys, auth tokens) Use debug for internal state inspection only Keep logs structured (never plain strings only) +### HTTP Request Logs + +Both backend servers write one structured line per request through +`backend/shared/middleware/requestObservability.ts`: + +```json +{ + "timestamp": "2026-10-17T12:00:00.000Z", + "service": "subtrackr-backend", + "module": "http", + "level": "info", + "message": "http.request", + "correlationId": "5f0c…", + "meta": { + "requestId": "5f0c…", + "traceId": "4bf92f3577b34da6a3ce929d0e0e4736", + "spanId": "00f067aa0ba902b7", + "method": "GET", + "path": "/plans/plan-1", + "status": 200, + "durationMs": 12 + } +} +``` + +- **Request id:** a caller's `X-Request-Id` is kept when it is 1 to 128 + characters of `A-Z a-z 0-9 . _ : -`; anything else is replaced with a UUID. + The id is echoed on the response and is the `correlationId` of every log + written while the request is served. +- **Level:** `info` for 2xx/3xx, `warn` for 4xx and aborted requests, `error` + for 5xx. +- **No PII:** query strings, headers, request and response bodies and client + IPs are never logged. Path segments that look like an email address or a long + number (7+ digits, e.g. a card or phone number) are replaced with `:redacted`. +- **Trace link:** `traceId` and `spanId` point at the request's server span + (see [distributed-tracing.md](distributed-tracing.md)). + ### Log Aggregation The backend supports forwarding structured events to a centralized endpoint using `LOG_REMOTE_ENDPOINT`. Set `BACKEND_LOG_LEVEL` and `BACKEND_LOG_LEVELS` to tune verbosity globally or per module. diff --git a/docs/api-versioning.md b/docs/api-versioning.md index 074acb2d..2bade90c 100644 --- a/docs/api-versioning.md +++ b/docs/api-versioning.md @@ -12,6 +12,49 @@ Deprecated versions continue to serve requests but receive RFC 8594 headers (`De --- +## Current state + +| Version | Lifecycle | Served at | +|---|---|---| +| `v1` | active (default) | every route in `backend/server.ts` and `/api/v1/*` in `backend/server/createApiServer.ts` | + +Both servers run `createVersionMiddleware(versionRegistry)` on every request. +Responses carry `api-version: v1` (the Express app also keeps the older +`X-API-Version: 1`). A request that names a version the registry does not know, +for example `api-version: v9` or `/v9/plans`, is rejected with +`400 VERSION_NOT_FOUND` instead of being served as v1. + +## Strategy + +- **Major versions only.** A new version (`v2`, `v3`, …) is created only for a + breaking change: removing or renaming a field, endpoint or enum value, + changing a type or a default, or making an optional input required. +- **Additive changes stay in the current version.** New endpoints, new optional + fields and new enum values for output are not breaking. Clients must ignore + unknown response fields. +- **One codebase.** Old and new versions are served side by side; handlers + branch on the resolved version instead of forking the code. +- **New versions start as `draft`**, are exercised internally, then + `registry.activate()` makes them public and, once stable, `setDefault()` + moves unversioned requests over. + +## Deprecation policy + +1. A version can be deprecated only after its successor is `active`. +2. Deprecation is announced in `CHANGELOG.md` and the developer portal with the + sunset date and a migration guide (`migrationUrl`). +3. From the deprecation date every response on that version carries + `Deprecation`, `Sunset`, `Link: <…>; rel="successor-version"` and `Warning` + headers. +4. The sunset date is at least **6 months** after the deprecation date. +5. Usage is watched through `registry.getStats()` and the deprecation report + (`backend/services/shared/apiDeprecationReport.ts`); remaining heavy users + are contacted before sunset. +6. On the sunset date `registry.sunset()` is called and the version answers + `410 Gone` with `VERSION_SUNSET`. + +--- + ## Quick start ```ts @@ -40,6 +83,10 @@ For every request the middleware checks in priority order: 3. **`version` query param** — `?version=v2` 4. **Default** — whatever `registry.setDefault()` was called with +If any of steps 1 to 3 names a version that is not registered, resolution stops +and the middleware answers `400 VERSION_NOT_FOUND`. The default only applies +when the request does not name a version at all. + --- ## Version lifecycle @@ -196,9 +243,11 @@ The pre-configured registry (`versionRegistry`) is exported for application-wide ```ts import { versionRegistry } from '../services/shared/apiVersioning'; -// v1: deprecated (sunsets 2026-06-01), v2: active (default) +// v1: active (default) ``` +Register the next version here as `draft` when its first breaking change lands. + --- ## Running tests diff --git a/docs/distributed-tracing.md b/docs/distributed-tracing.md index 9d4c788c..3d42a7a9 100644 --- a/docs/distributed-tracing.md +++ b/docs/distributed-tracing.md @@ -32,27 +32,40 @@ trace id is shared and parent/child span linkage is preserved. ## Per-language usage -### Backend (TypeScript) — `backend/services/shared` +### Backend (TypeScript) — `backend/shared/middleware/requestObservability.ts` -```ts -import { startServerSpan, traceDbQuery, traceExternalCall } from './shared/monitoring'; - -async function handleCharge(req) { - const { span, downstreamHeaders } = startServerSpan('POST /v1/charges', req.headers); - try { - const sub = await traceDbQuery('select subscription', span.context, () => db.query(...)); - await traceExternalCall('ml-service', span.context, (_s, headers) => - fetch(ML_URL, { headers }) // headers already carry traceparent - ); - span.setStatus('ok'); - } catch (e) { - span.recordException(e); - throw e; - } finally { - span.end(); - } -} -``` +Both backend HTTP servers (`backend/server.ts` and the Express app in +`backend/server/createApiServer.ts`) run every request through +`createRequestObservability`. It: + +- continues the caller's `traceparent` (or starts a new trace) with a `server` + span named ` `; +- records `http.method`, `http.target` (path only), `http.status_code` and + `request.id`; 5xx responses and aborted requests get status `error`; +- exports the span through the tracer built by `createTracerFromEnv` + (`backend/services/shared/tracing.ts`): OTLP/HTTP to + `$OTEL_EXPORTER_OTLP_ENDPOINT/v1/traces` when set, otherwise an in-memory + buffer. + +Service names: `subtrackr-backend` (`server.ts`) and `subtrackr-api` +(`createApiServer.ts`). + +To propagate a context to a downstream call, add the headers from +`injectContext(span.context)` to the outgoing request. + +### Correlating traces and logs + +The middleware also sets `X-Request-Id` (kept from the caller when it is a safe +token, otherwise a UUID) and runs the handler in the logger's correlation +context. So: + +- every log written while serving the request has `correlationId` = request id; +- the `http.request` access log line carries `requestId`, `traceId` and + `spanId`; +- the server span carries the `request.id` attribute. + +From a log line, search Tempo by `traceId`; from a trace, filter logs by +`correlationId` = the span's `request.id`. See [api-logging.md](api-logging.md). ### Mobile (TypeScript) — `src/services/network/apiClient.ts` diff --git a/docs/etag-caching.md b/docs/etag-caching.md index 5ae7bb00..bd61b4a2 100644 --- a/docs/etag-caching.md +++ b/docs/etag-caching.md @@ -23,7 +23,8 @@ Client Server |---|---| | `backend/shared/middleware/etagMiddleware.ts` | Core ETag logic, 304 handling, Cache-Control | | `backend/shared/middleware/index.ts` | Barrel export | -| `backend/server.ts` | `applyETagToRawHandler` wired into raw HTTP server | +| `backend/services/shared/compression.ts` | ETag + `If-None-Match` handling used by `backend/server.ts` (`sendJson` → `applyCompression`) | +| `backend/server/createApiServer.ts` | Express app; uses Express's built-in ETag and `304` handling | ## ETag Generation @@ -98,15 +99,24 @@ applyETagToRawHandler(req, res, { bypassForAuth: false }); ### Raw HTTP server (default in `backend/server.ts`) -```ts -import { applyETagToRawHandler } from './shared/middleware/etagMiddleware'; +Every `200` JSON response from `backend/server.ts` goes through `sendJson` → +`applyCompression`, which computes the ETag from the uncompressed body (so it +is the same for gzip, brotli and identity) and answers `304 Not Modified` when +`If-None-Match` matches. Matching uses the weak comparison from RFC 9110: the +header may list several tags and a `W/` prefix is ignored, so a CDN that +weakens the tag still gets a `304`. -const server = http.createServer(async (req, res) => { - applyETagToRawHandler(req, res); - // … handler logic … -}); +```bash +curl -i http://localhost:3001/plans/plan-1 # 200 + ETag: "…" +curl -i -H 'If-None-Match: "…"' http://localhost:3001/plans/plan-1 # 304, empty body ``` +For a new raw handler that does not use `sendJson`, call +`applyETagToRawHandler(req, res)` before writing the response. + +Covered by `backend/__tests__/server.test.ts` and +`backend/services/shared/__tests__/compression.test.ts`. + ### Express ```ts