From a69593eb727777fae2d5a900ca20a739eeeced77 Mon Sep 17 00:00:00 2001 From: Lilleman auf Larv Date: Sun, 8 Nov 2026 14:59:55 +0100 Subject: [PATCH] Put the caller, site and route on every request's span and log line --- CHANGELOG.md | 13 +++++++ README.md | 18 +++++++-- src/config.test.ts | 7 ++++ src/config.ts | 13 ++++++- src/function-limits.test.ts | 4 +- src/http/app-request-log.test.ts | 49 ++++++++++++++++++++++++ src/http/app.test.ts | 5 +-- src/http/app.ts | 48 ++++++----------------- src/http/request-fields.test.ts | 55 +++++++++++++++++++++++++++ src/http/request-fields.ts | 65 ++++++++++++++++++++++++++++++++ src/http/request-tracking.ts | 42 +++++++++++++++++++++ src/logger.ts | 5 ++- src/server.ts | 1 + todo.md | 18 --------- 14 files changed, 275 insertions(+), 68 deletions(-) create mode 100644 src/http/app-request-log.test.ts create mode 100644 src/http/request-fields.test.ts create mode 100644 src/http/request-fields.ts create mode 100644 src/http/request-tracking.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index d6b0595..05a8dff 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,19 @@ The host's contract version is now 0.5.0, so discovery refuses a plugin whose `a `0.4.x`. Change the literal in each plugin's manifest when you upgrade, and add `assetHref` to any `RequestContext` your tests build by hand: `assetHref: (href) => href`. +### Every request's span and `request` log line name the caller, the site and the route + +The `request` line and the request span now carry OpenTelemetry's HTTP attributes: +`http.request.method`, `url.path`, `http.response.status_code`, `http.route` (when a route matched), +`server.address` (the `Host`), `user_agent.original` and `client.address`. They replace `method`, +`path` and `status`; `ms` is gone, because the span's own duration is the latency. Plugins' own log +lines for a request carry them too. + +`client.address` is the socket's peer. Set `TRUSTED_PROXIES` (comma-separated IPs or CIDR ranges) +to the proxies in front of the host and the address `X-Forwarded-For` names is used instead. A bad +entry refuses the boot. The log now holds callers' IPs and user agents, which are personal data: +say so in your privacy policy. + ### `buildPaginationModel` builds the pagination partial's model Call `buildPaginationModel(page, hrefFor, { label?, pageSizes?, pageParam?, pageSizeParam? })` from diff --git a/README.md b/README.md index 3880909..030c100 100644 --- a/README.md +++ b/README.md @@ -1237,6 +1237,7 @@ The app is **environment-agnostic**: no `NODE_ENV`, every behaviour its own expl | `LOG_FORMAT` | `text` | log line format: `text` (human-readable, dev) or `json` (structured, prod) | | `SERVICE_NAME` | `plainpages` | OTLP `service.name` on every log + span — brand it as your own deployment | | `OTLP_ENDPOINT` | _unset_ | OpenTelemetry Collector HTTP base URI; set ⇒ export logs + traces (unset ⇒ console only) | +| `TRUSTED_PROXIES` | _unset_ | comma-separated IPs/CIDR ranges of the reverse proxies in front of the host; only a request from one lets `X-Forwarded-For` name the caller in logs and spans ([Observability](#observability)) | | `OTLP_PROTOCOL` | `http/json` | OTLP wire format: `http/json` or `http/protobuf` | | `KRATOS_PUBLIC_URL` / `KRATOS_ADMIN_URL` | `http://kratos:4433` / `:4434` | identity (self-service / admin) | | `KETO_READ_URL` / `KETO_WRITE_URL` | `http://keto:4466` / `:4467` | authorization check / write | @@ -1762,9 +1763,18 @@ Logging is **structured** and **OTLP-native**, on handler (an `AsyncLocalStorage`), so logs and traces correlate. Three explicit toggles: `LOG_LEVEL`, `LOG_FORMAT` (`text` dev / `json` prod) and `SERVICE_NAME`. -Every request emits one access line (`method`, `path` — the query is dropped, it can carry tokens — -`status`, `ms`, `requestId`); login/logout, admin writes and missing-permission/CSRF rejections log -at `info`/`warn`, the catch-all 500 and Ory-unreachable re-mint at `error`/`warn`. An inbound W3C +Every request emits one access line, and the same fields ride its span. They follow OpenTelemetry's +HTTP conventions: `http.request.method`, `url.path` (the query is dropped, it can carry tokens), +`http.response.status_code`, `http.route` (the matched pattern, absent on a 404), `server.address` +(the `Host`), `user_agent.original`, `client.address` and `requestId`; the span's duration is the +latency. **They are personal data** (an IP and a user agent identify a caller), so a deployment's +privacy policy must say the host logs them. `client.address` is the socket's peer; set +`TRUSTED_PROXIES` to the IPs or CIDR ranges of the proxies in front of the host and a request from +one takes the nearest address in `X-Forwarded-For` that is not itself a listed proxy. Never list a +range a caller can send from: the header is then theirs to write. + +Login/logout, admin writes and missing-permission/CSRF rejections log at `info`/`warn`, the +catch-all 500 and Ory-unreachable re-mint at `error`/`warn`. An inbound W3C `traceparent` is **adopted**, continuing a trace started upstream. **Distributed tracing covers every outbound call.** Because the request logger is ambient, all @@ -1850,7 +1860,7 @@ src/ The app — strict tsc, no build step. *.test.ts sit beside server.ts Entry point; config.ts env loader; logger.ts structured log + trace span + tracedFetch *.test.ts Guards with no source counterpart (compose/kratos/keto/hydra/postgres/ci-gate/function-limits) http/ Request pipeline: app.ts (createApp), builtin-route, context, body, cookie, - static, safe-url (safeUrl + localPath), security-headers + static, safe-url (safeUrl + localPath), security-headers, request-fields (span/log attributes) auth/ Identity + the session-JWT hot path: jwt · jwt-middleware · jwks · gen-jwks (CLI) · login · guards · csrf · denylist · flow-view · oauth-login · oauth-consent · routes · bootstrap, and the Ory REST clients (kratos-public/admin, keto, hydra, diff --git a/src/config.test.ts b/src/config.test.ts index 87a591a..e217319 100644 --- a/src/config.test.ts +++ b/src/config.test.ts @@ -97,6 +97,13 @@ test("SERVICE_NAME is overridable so an implementer brands their own logs/traces assert.equal(loadConfig({ SERVICE_NAME: "" }).serviceName, "plainpages"); // empty ⇒ default }); +test("TRUSTED_PROXIES: a comma-separated list of IPs/CIDRs, empty by default, a bad entry refuses the boot", () => { + assert.deepEqual(loadConfig({}).trustedProxies, []); // trust nobody's X-Forwarded-For unless told + assert.deepEqual(loadConfig({ TRUSTED_PROXIES: "" }).trustedProxies, []); // compose passes ${TRUSTED_PROXIES:-} + assert.deepEqual(loadConfig({ TRUSTED_PROXIES: "10.0.0.0/8, ::1" }).trustedProxies, ["10.0.0.0/8", "::1"]); + assert.throws(() => loadConfig({ TRUSTED_PROXIES: "10.0.0.1,proxy.internal" }), /TRUSTED_PROXIES/); +}); + test("LOG_LEVEL/LOG_FORMAT/OTLP_PROTOCOL are validated enums; OTLP_ENDPOINT an optional URL", () => { assert.equal(loadConfig({ LOG_LEVEL: "debug" }).logLevel, "debug"); assert.equal(loadConfig({ LOG_LEVEL: "none" }).logLevel, "none"); diff --git a/src/config.ts b/src/config.ts index b14dde7..dada1fc 100644 --- a/src/config.ts +++ b/src/config.ts @@ -2,6 +2,8 @@ // secret, a bad URL or an out-of-range port throws here, never at request time. Every value has a // working dev default, so `docker compose up` runs with zero config. +import { parseTrustedProxies } from "./http/request-fields.ts"; + // Log verbosity, most→least severe; "none" silences everything (matches @larvit/log's levels). export const LOG_LEVELS = ["error", "warn", "info", "verbose", "debug", "silly", "none"] as const; export type LogLevel = (typeof LOG_LEVELS)[number]; @@ -61,6 +63,7 @@ export interface Config { revocationTtlSec: number; // how long a revoke entry lives; keep ≥ tokenizer TTL + clock skew secureCookies: boolean; serviceName: string; // OTLP service.name — an implementer brands their own logs/traces + trustedProxies: string[]; // IPs/CIDRs whose X-Forwarded-For names the caller; empty ⇒ the socket peer is the caller } type Env = Record; @@ -149,6 +152,12 @@ function readPosInt(env: Env, key: string, devDefault: number): number { return n; } +function readTrustedProxies(env: Env): string[] { + const entries = (env["TRUSTED_PROXIES"] ?? "").split(",").map((entry) => entry.trim()).filter(Boolean); + parseTrustedProxies(entries); // throws on a bad entry; the app parses the list again + return entries; +} + export function loadConfig(env: Env = process.env): Config { const requireSecure = readBool(env, "REQUIRE_SECURE_SECRETS", false); return { @@ -176,8 +185,7 @@ export function loadConfig(env: Env = process.env): Config { ketoWriteUrl: readUrl(env, "KETO_WRITE_URL", "http://keto:4467"), kratosAdminUrl: readUrl(env, "KRATOS_ADMIN_URL", "http://kratos:4434"), kratosPublicUrl: readUrl(env, "KRATOS_PUBLIC_URL", "http://kratos:4433"), - // observability. Console-only by default (clean clone). Setting OTLP_ENDPOINT to an - // OpenTelemetry Collector exports structured logs + per-request spans there (Loki/Tempo). + // Console-only by default; OTLP_ENDPOINT exports logs + per-request spans to an OpenTelemetry Collector. logFormat: readEnum(env, "LOG_FORMAT", ["json", "text"] as const, "text"), logLevel: readEnum(env, "LOG_LEVEL", LOG_LEVELS, "info"), oryTimeoutSec: readPosInt(env, "ORY_TIMEOUT_SEC", 5), @@ -199,5 +207,6 @@ export function loadConfig(env: Env = process.env): Config { // Set Secure on our session/CSRF cookies. Off by default (dev runs http); prod (https) sets it. secureCookies: readBool(env, "SECURE_COOKIES", false), serviceName: env["SERVICE_NAME"] || "plainpages", // OTLP service.name; empty ⇒ default + trustedProxies: readTrustedProxies(env), }; } diff --git a/src/function-limits.test.ts b/src/function-limits.test.ts index d2a852e..4931297 100644 --- a/src/function-limits.test.ts +++ b/src/function-limits.test.ts @@ -13,8 +13,8 @@ const LIMITS = { lines: 50, complexity: 20 }; // Each function over a limit, at its measurement. A ceiling follows its function down, and a metric // leaves the entry once it fits, so a function that shrank can't grow back. const grandfathered: Record = { - "src/http/app.ts createApp": { lines: 318, complexity: 28 }, - "src/http/app.ts createApp > handleRequest": { lines: 167, complexity: 43 }, + "src/http/app.ts createApp": { lines: 291, complexity: 28 }, + "src/http/app.ts createApp > handleRequest": { lines: 166, complexity: 43 }, "src/auth/flow-view.ts buildFlowView": { complexity: 24 }, "src/auth/hydra-admin.ts createHydraAdmin": { lines: 87 }, "src/auth/kratos-admin.ts createKratosAdmin": { lines: 68 }, diff --git a/src/http/app-request-log.test.ts b/src/http/app-request-log.test.ts new file mode 100644 index 0000000..71012b0 --- /dev/null +++ b/src/http/app-request-log.test.ts @@ -0,0 +1,49 @@ +import assert from "node:assert/strict"; +import type { AddressInfo } from "node:net"; +import { test, type TestContext } from "node:test"; +import { createLogger } from "../logger.ts"; +import { createApp } from "./app.ts"; + +// The `request` line, parsed, once the server has logged it (it logs on the response's close). +async function requestLineOf(lines: string[]): Promise> { + for (let i = 0; i < 200; i++) { + const line = lines.map((l) => JSON.parse(l) as Record).find((rec) => rec["message"] === "request" || rec["msg"] === "request"); + if (line) return line; + await new Promise((r) => setTimeout(r, 10)); + } + throw new Error("no request line was logged"); +} + +async function serve(t: TestContext, trustedProxies: string[]): Promise<{ lines: string[]; url: string }> { + const lines: string[] = []; + const log = createLogger({ format: "json", level: "info", stderr: () => {}, stdout: (l: string) => lines.push(l) }); + const app = createApp({ log, trustedProxies }); + await new Promise((r) => app.listen(0, r)); + t.after(() => app.close()); + return { lines, url: `http://localhost:${(app.address() as AddressInfo).port}` }; +} + +test("the request line names the caller, the site and the matched route in OpenTelemetry's terms", async (t) => { + const { lines, url } = await serve(t, []); + await (await fetch(`${url}/?token=secret`, { headers: { "user-agent": "TV/1.0", "x-forwarded-for": "198.51.100.7" } })).text(); + const line = await requestLineOf(lines); + + assert.equal(line["http.request.method"], "GET"); + assert.equal(line["url.path"], "/"); // never the query + assert.equal(line["http.response.status_code"], 200); + assert.equal(line["http.route"], "/"); + assert.equal(line["server.address"], "localhost"); + assert.equal(line["user_agent.original"], "TV/1.0"); + assert.match(String(line["client.address"]), /^(127\.0\.0\.1|::1)$/); // the forged header is not believed + for (const old of ["method", "path", "status", "ms"]) assert.equal(line[old], undefined, old); +}); + +test("a listed proxy lets X-Forwarded-For name the caller; an unmatched path carries no route", async (t) => { + const { lines, url } = await serve(t, ["127.0.0.0/8", "::1"]); + await (await fetch(`${url}/no-such-page`, { headers: { "x-forwarded-for": "198.51.100.7" } })).text(); + const line = await requestLineOf(lines); + + assert.equal(line["client.address"], "198.51.100.7"); + assert.equal(line["http.response.status_code"], 404); + assert.equal(line["http.route"], undefined); +}); diff --git a/src/http/app.test.ts b/src/http/app.test.ts index 2174639..62ea7a8 100644 --- a/src/http/app.test.ts +++ b/src/http/app.test.ts @@ -132,11 +132,8 @@ test("emits a structured access-log line per request (the injected logger)", asy } assert.ok(line, "an access line is logged for the request"); const rec = JSON.parse(line!); - assert.equal(rec.method, "GET"); - assert.equal(rec.path, "/"); // pathname only — the ?q=… query is dropped (may carry tokens) - assert.equal(rec.status, 200); + assert.equal(rec["url.path"], "/"); // pathname only — the ?q=… query is dropped (may carry tokens) assert.equal(rec["service.name"], "plainpages"); - assert.equal(typeof rec.ms, "number"); assert.ok(rec.requestId, "carries a requestId for log↔trace correlation"); }); diff --git a/src/http/app.ts b/src/http/app.ts index f7b2c77..a2c1cdd 100644 --- a/src/http/app.ts +++ b/src/http/app.ts @@ -1,4 +1,4 @@ -import { randomBytes, randomUUID } from "node:crypto"; +import { randomBytes } from "node:crypto"; import { createServer, type IncomingMessage, type Server, type ServerResponse } from "node:http"; import { dirname, join } from "node:path"; import { fileURLToPath } from "node:url"; @@ -21,7 +21,7 @@ import { resolveSession, type VerifyOptions } from "../auth/jwt-middleware.ts"; import type { KetoClient } from "../auth/keto-client.ts"; import type { KratosAdmin } from "../auth/kratos-admin.ts"; import type { KratosPublic } from "../auth/kratos-public.ts"; -import { createLogger, type Log, requestLogger, runWithLog } from "../logger.ts"; +import { createLogger, type Log } from "../logger.ts"; import { remintSession } from "../auth/login.ts"; import { DEFAULT_MENU, type MenuConfig } from "../ui/menu-config.ts"; import { declaredPermissions, type Plugin, type RouteHandler, type RouteResult } from "../plugin-host/plugin.ts"; @@ -30,6 +30,8 @@ import type { SystemCapabilities } from "../plugin-host/system.ts"; import { allows, type Gate } from "../auth/gate.ts"; import { allowedMethods, matchRoute } from "../plugin-host/router.ts"; import { buildAuthRoutes } from "../auth/routes.ts"; +import { parseTrustedProxies } from "./request-fields.ts"; +import { trackRequest } from "./request-tracking.ts"; import { securityHeaders } from "./security-headers.ts"; import { localPath } from "./safe-url.ts"; import { publicAssets } from "./static.ts"; @@ -58,6 +60,7 @@ export interface AppOptions { publicDir?: string; secureCookies?: boolean; // set Secure on our session/CSRF cookies (config.secureCookies; off in dev http) settingsCatalog?: readonly PluginSettings[]; // resolved at boot (server.ts, needs the env); → ctx.declaredSettings + trustedProxies?: readonly string[]; // IPs/CIDRs whose X-Forwarded-For names the caller (config.trustedProxies); omitted ⇒ the socket peer viewsDir?: string; } @@ -73,6 +76,7 @@ export function createApp(options: AppOptions = {}): Server { const canonicalOrigin = canonical?.origin; // scheme + host[:port], no trailing slash const csrfSecret = options.csrfSecret ?? randomBytes(32).toString("hex"); // server passes config; tests pass their own const secureCookies = options.secureCookies ?? false; + const trustedProxies = parseTrustedProxies(options.trustedProxies); const hydra = options.hydra; const i18n = options.i18n ?? ENGLISH_I18N; const jwks = options.jwks; @@ -214,12 +218,9 @@ export function createApp(options: AppOptions = {}): Server { // the themed forms and the cross-origin Kratos POST share one cookie host — otherwise the // host-scoped Kratos CSRF cookie is lost and login dumps onto /error. GET/HEAD only: a 308 // must not replay a cross-host POST. - if (canonicalHost && (method === "GET" || method === "HEAD")) { - const host = req.headers.host; - if (host !== undefined && host !== canonicalHost) { - res.writeHead(308, { location: canonicalOrigin + (req.url ?? "/") }).end(); - return; - } + if (canonicalHost && (method === "GET" || method === "HEAD") && req.headers.host !== undefined && req.headers.host !== canonicalHost) { + res.writeHead(308, { location: canonicalOrigin + (req.url ?? "/") }).end(); + return; } // `explicit` (the URL asked for a locale) is what makes the choice travel: the chrome, this @@ -294,6 +295,7 @@ export function createApp(options: AppOptions = {}): Server { const match = matchRoute(plugins, method, pathname); if (match) { + reqLog.context["http.route"] = match.route.path; const routeCtx = contextFor(match.plugin.id, match.params); if (!allows(match.route, routeCtx.user)) { await refuse(match.route, routeCtx); @@ -310,6 +312,7 @@ export function createApp(options: AppOptions = {}): Server { const builtin = matchBuiltinRoute(builtinRoutes, method, pathname); if (builtin) { + reqLog.context["http.route"] = builtin.path; if (!allows(builtin, ctx.user)) { await refuse(builtin, ctx); return; } await sendResult(res, await builtin.handler(ctx, csrfMint, contextFor), viewsFor(ctx), carryLocale); return; @@ -350,34 +353,7 @@ export function createApp(options: AppOptions = {}): Server { } }; - return createServer((req, res) => { - // "close" (not "finish") fires on both a completed response and a premature disconnect, so an - // aborted request is still logged and its span flushed. - const startMs = Date.now(); - const reqLog = requestLogger(log, { - requestId: randomUUID(), - ...(typeof req.headers.traceparent === "string" ? { traceparent: req.headers.traceparent } : {}), - }); - // end() must run exactly once, after BOTH the handler has unwound AND the response has closed. - // Earlier would throw "already ended" from a still-running handler's ctx.log on a client abort, - // or drop the access line on the happy path (the handler settles before close). - let settled = false; - let closed = false; - const finalize = (): void => { if (settled && closed) void reqLog.end().catch(() => {}); }; - res.on("close", () => { - closed = true; - try { - // path only (no query — it may carry tokens); method/status are header-safe here. - reqLog.info("request", { method: req.method ?? "GET", ms: Date.now() - startMs, path: (req.url ?? "/").split("?", 1)[0] ?? "/", status: res.statusCode }); - } catch { /* never let logging crash a served request */ } - finalize(); - }); - // Make reqLog ambient for the whole handler so all outbound fetch is traced. The .catch logs a - // pathological escape via the app logger — not reqLog, which may be the thing that broke. - void runWithLog(reqLog, () => handleRequest(req, res, reqLog)) - .catch((err) => log.error("request handler escaped its try/catch", { error: err instanceof Error ? (err.stack ?? err.message) : String(err) })) - .finally(() => { settled = true; finalize(); }); - }); + return createServer((req, res) => trackRequest(log, trustedProxies, req, res, handleRequest)); } // The Referer as a host-relative path, when it is one of ours — the page a form was submitted diff --git a/src/http/request-fields.test.ts b/src/http/request-fields.test.ts new file mode 100644 index 0000000..2a853a7 --- /dev/null +++ b/src/http/request-fields.test.ts @@ -0,0 +1,55 @@ +import assert from "node:assert/strict"; +import type { IncomingMessage } from "node:http"; +import { test } from "node:test"; +import { clientAddress, parseTrustedProxies, requestFields } from "./request-fields.ts"; + +const proxies = parseTrustedProxies(["10.0.0.0/8", "192.168.1.5", "fd00::/8"]); +const none = parseTrustedProxies([]); + +test("clientAddress: the socket peer, unless the peer is a listed proxy", () => { + assert.equal(clientAddress("203.0.113.9", "198.51.100.1", proxies), "203.0.113.9"); // header ignored from a stranger + assert.equal(clientAddress("10.1.2.3", "198.51.100.1", proxies), "198.51.100.1"); + assert.equal(clientAddress("10.1.2.3", "198.51.100.1", none), "10.1.2.3"); // nothing trusted by default + assert.equal(clientAddress("192.168.1.5", undefined, proxies), "192.168.1.5"); // trusted peer, no header + assert.equal(clientAddress(undefined, "198.51.100.1", proxies), undefined); +}); + +test("clientAddress: walks the chain from the right, so a forged leftmost entry is not believed", () => { + assert.equal(clientAddress("10.0.0.1", "6.6.6.6, 198.51.100.1, 10.0.0.2", proxies), "198.51.100.1"); + assert.equal(clientAddress("10.0.0.1", "10.0.0.7, 10.0.0.2", proxies), "10.0.0.7"); // every hop trusted → the origin +}); + +test("clientAddress: a malformed hop or a mapped IPv4 peer never yields garbage", () => { + assert.equal(clientAddress("10.0.0.1", "not-an-ip", proxies), "10.0.0.1"); + assert.equal(clientAddress("::ffff:10.0.0.1", "198.51.100.1", proxies), "198.51.100.1"); + assert.equal(clientAddress("::ffff:203.0.113.9", undefined, none), "203.0.113.9"); + assert.equal(clientAddress("fd00::1", "2001:db8::7", proxies), "2001:db8::7"); +}); + +test("parseTrustedProxies: refuses an entry that is not an IP or a CIDR range", () => { + for (const bad of ["proxy.internal", "10.0.0.0/33", "10.0.0.0/x", "::1/129", ""]) { + assert.throws(() => parseTrustedProxies([bad]), /TRUSTED_PROXIES/, bad); + } +}); + +const request = (headers: Record, remoteAddress = "203.0.113.9", url = "/a/b?token=secret", method = "POST") => + ({ headers, method, socket: { remoteAddress }, url }) as unknown as IncomingMessage; + +test("requestFields: OpenTelemetry names for the caller, the site and the request, without the query", () => { + const fields = requestFields(request({ host: "Example.com:8080", "user-agent": "TV/1.0" }), none); + assert.deepEqual(fields, { + "client.address": "203.0.113.9", + "http.request.method": "POST", + "server.address": "example.com", + "url.path": "/a/b", + "user_agent.original": "TV/1.0", + }); +}); + +test("requestFields: drops what the request lacks or sent malformed, and reads X-Forwarded-For only via a trusted peer", () => { + assert.deepEqual(requestFields(request({ host: "bad host" }, "10.0.0.1", "/"), proxies), { + "client.address": "10.0.0.1", "http.request.method": "POST", "url.path": "/", + }); + const fields = requestFields(request({ "x-forwarded-for": "198.51.100.1" }, "10.0.0.1"), proxies); + assert.equal(fields["client.address"], "198.51.100.1"); +}); diff --git a/src/http/request-fields.ts b/src/http/request-fields.ts new file mode 100644 index 0000000..0525610 --- /dev/null +++ b/src/http/request-fields.ts @@ -0,0 +1,65 @@ +import type { IncomingMessage } from "node:http"; +import { BlockList, isIP } from "node:net"; + +export type TrustedProxies = BlockList; + +// Each entry is an IP address or a CIDR range (`10.0.0.0/8`). Fails loud: a typo here would +// silently log a proxy's address for every caller, or trust a stranger's header. +export function parseTrustedProxies(entries: readonly string[] = []): TrustedProxies { + const list = new BlockList(); + for (const entry of entries) { + const [address = "", prefix, ...rest] = entry.split("/"); + const family = isIP(address); + const length = prefix === undefined ? undefined : Number(prefix); + const maxLength = family === 4 ? 32 : 128; + if (family === 0 || rest.length > 0 || (length !== undefined && !(Number.isInteger(length) && length >= 0 && length <= maxLength))) { + throw new Error(`config: TRUSTED_PROXIES entry "${entry}" is not an IP address or CIDR range`); + } + const kind = family === 4 ? "ipv4" : "ipv6"; + if (length === undefined) list.addAddress(address, kind); + else list.addSubnet(address, length, kind); + } + return list; +} + +// A dual-stack socket reports an IPv4 peer as `::ffff:a.b.c.d`; log the plain form. +const plain = (address: string): string => (address.startsWith("::ffff:") && isIP(address.slice(7)) === 4 ? address.slice(7) : address); + +// The socket's peer, unless the peer is a listed proxy: then the nearest address in X-Forwarded-For +// that is not itself a listed proxy. Reading from the right is what makes a forged leftmost entry +// harmless — only a hop a trusted proxy appended is believed. +export function clientAddress(peer: string | undefined, forwardedFor: string | undefined, trusted: TrustedProxies): string | undefined { + if (peer === undefined) return undefined; + const isTrusted = (address: string): boolean => trusted.check(address, isIP(address) === 4 ? "ipv4" : "ipv6"); + const direct = plain(peer); + if (!isTrusted(direct)) return direct; + const hops = (forwardedFor ?? "").split(",").map((hop) => plain(hop.trim())).filter(Boolean); + let client = direct; + for (let i = hops.length - 1; i >= 0; i--) { + const hop = hops[i]!; + if (isIP(hop) === 0) return direct; + client = hop; + if (!isTrusted(hop)) break; + } + return client; +} + +// OpenTelemetry HTTP semantic-convention attributes every request carries on its span and `request` +// line. The path only: the query may carry tokens. +export function requestFields(req: IncomingMessage, trusted: TrustedProxies): Record { + const fields: Record = { + "http.request.method": req.method ?? "GET", + "url.path": (req.url ?? "/").split("?", 1)[0] ?? "/", + }; + const client = clientAddress(req.socket.remoteAddress, headerValue(req.headers["x-forwarded-for"]), trusted); + if (client !== undefined) fields["client.address"] = client; + const host = headerValue(req.headers.host); + if (host !== undefined) { + try { fields["server.address"] = new URL(`http://${host}`).hostname; } catch { /* malformed Host: leave it off */ } + } + const agent = headerValue(req.headers["user-agent"]); + if (agent !== undefined) fields["user_agent.original"] = agent; + return fields; +} + +const headerValue = (value: string | string[] | undefined): string | undefined => (Array.isArray(value) ? value.join(", ") : value); diff --git a/src/http/request-tracking.ts b/src/http/request-tracking.ts new file mode 100644 index 0000000..0db535f --- /dev/null +++ b/src/http/request-tracking.ts @@ -0,0 +1,42 @@ +import { randomUUID } from "node:crypto"; +import type { IncomingMessage, ServerResponse } from "node:http"; +import { type Log, requestLogger, runWithLog } from "../logger.ts"; +import { requestFields, type TrustedProxies } from "./request-fields.ts"; + +// Gives one request its own logger and span, runs `handle` under it, and writes the `request` line +// when the response closes. The handler adds `http.route` to the logger's context once it knows it. +export function trackRequest( + log: Log, + trusted: TrustedProxies, + req: IncomingMessage, + res: ServerResponse, + handle: (req: IncomingMessage, res: ServerResponse, reqLog: Log) => Promise, +): void { + // "close" (not "finish") fires on both a completed response and a premature disconnect, so an + // aborted request is still logged and its span flushed. + const reqLog = requestLogger(log, { + attributes: requestFields(req, trusted), + requestId: randomUUID(), + ...(typeof req.headers.traceparent === "string" ? { traceparent: req.headers.traceparent } : {}), + }); + // end() must run exactly once, after BOTH the handler has unwound AND the response has closed. + // Earlier would throw "already ended" from a still-running handler's ctx.log on a client abort, + // or drop the access line on the happy path (the handler settles before close). + let settled = false; + let closed = false; + const finalize = (): void => { if (settled && closed) void reqLog.end().catch(() => {}); }; + res.on("close", () => { + closed = true; + try { + // The context is what the span exports, so the status goes there; the span's duration is the latency. + reqLog.context["http.response.status_code"] = res.statusCode; + reqLog.info("request"); + } catch { /* never let logging crash a served request */ } + finalize(); + }); + // Make reqLog ambient for the whole handler so all outbound fetch is traced. The .catch logs a + // pathological escape via the app logger — not reqLog, which may be the thing that broke. + void runWithLog(reqLog, () => handle(req, res, reqLog)) + .catch((err) => log.error("request handler escaped its try/catch", { error: err instanceof Error ? (err.stack ?? err.message) : String(err) })) + .finally(() => { settled = true; finalize(); }); +} diff --git a/src/logger.ts b/src/logger.ts index 9cd81a5..8be87dd 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -61,9 +61,10 @@ export const tracedFetch: typeof fetch = (input, init) => { // request its own root trace, so requests aren't all nested under one app-lifetime span, while // inheriting the parent's level/format/streams/OTLP. A valid upstream `traceparent` is adopted; // malformed ⇒ ignored, a fresh trace starts. `end()` on response finish exports the span. -export function requestLogger(appLog: Log, opts: { requestId: string; traceparent?: string | undefined }): Log { +// `attributes` ride the context, so they land on the span and on every line the request logs. +export function requestLogger(appLog: Log, opts: { attributes?: Record; requestId: string; traceparent?: string | undefined }): Log { return appLog.clone({ - context: { ...appLog.context, requestId: opts.requestId }, + context: { ...appLog.context, ...opts.attributes, requestId: opts.requestId }, spanName: "request", ...(opts.traceparent ? { traceparent: opts.traceparent } : {}), }); diff --git a/src/server.ts b/src/server.ts index c950b64..bb347f4 100644 --- a/src/server.ts +++ b/src/server.ts @@ -107,6 +107,7 @@ const server = createApp({ plugins, secureCookies: config.secureCookies, settingsCatalog: settings.catalog, + trustedProxies: config.trustedProxies, }).listen(config.port, () => { log.info("listening", { apiVersion: HOST_API_VERSION, port: config.port, url: config.appUrl ?? `http://localhost:${config.port}` }); }); diff --git a/todo.md b/todo.md index b7fcbbb..b24f4c6 100644 --- a/todo.md +++ b/todo.md @@ -12,7 +12,6 @@ | ID | Release | Blocked by | Exempt | Item | L | E | I | R | S | Moves | Score | |---|---|---|---|---|---|---|---|---|---|---|---| -| 57 | 0.5.0 | | owner | **Put the caller's IP, user agent and host on every request's span and `request` log line, under OpenTelemetry's HTTP semantic conventions, reading the IP through a proxy only where configuration names it trusted.** | 2 | 2 | 2 | 4 | 3 | 1 by 3 | 3.3 | | 19 | 0.6.0 | | question | **Run the documented Docker commands on macOS and fix whatever misbehaves.** | 2 | 2 | 1 | 3 | 3 | 1 by 3 | 3.3 | | 16 | 0.6.0 | | question | **Decide whether the single Keto `Resource` namespace splits into per-domain namespaces.** | 3 | 2 | 3 | 6 | 6 | 7 by 2 | 0.5 | | 28 | 0.6.0 | | | **Let a plugin add entries to the profile menu through the plugin API.** | 2 | 2 | 2 | 4 | 4 | 7 by 4, 1 by 2 | 4.2 | @@ -30,23 +29,6 @@ ## Details -### 57. Put the caller's IP, user agent and host on every request's span and `request` log line, under OpenTelemetry's HTTP semantic conventions, reading the IP through a proxy only where configuration names it trusted. - -Today the `request` line and span in `src/http/app.ts` carry only method, path, status and `ms`, so -a dashboard can't filter requests by site or tell one caller from another. Add `server.address` -(the `Host`), `user_agent.original`, `client.address` and `http.route` where a route matched, and -rename the four fields already there to their convention names (`http.request.method`, `url.path`, -`http.response.status_code`, and the span's own duration for `ms`). Every plugin gains them with no -code of its own. - -`client.address` is the socket's peer unless a new setting, such as `TRUSTED_PROXIES`, lists that -peer. Only then does the host take the address `X-Forwarded-For` names (goal 10: an explicit -choice). Trusting the header from anyone would let a caller write any IP into the logs. - -A caller's IP and user agent are personal data, so the README says the host logs them, and a -deployment's privacy policy must say so too. bender-infra's Requests dashboard (its todo.md item -117) reads these names, and fastjira (its item 161) is the first plugin to send them. - ### 19. Run the documented Docker commands on macOS and fix whatever misbehaves. Needs a Mac. Two suspects, both from `--user "$(id -u):$(id -g)"`: a macOS `id -g` is `20`, which is