From b19b43685ce2a434db52bfe5c5aa0751ae2a7386 Mon Sep 17 00:00:00 2001 From: Lilleman auf Larv Date: Sun, 8 Nov 2026 15:06:19 +0100 Subject: [PATCH] =?UTF-8?q?Answer=20stability=20round=201:=202=20?= =?UTF-8?q?=F0=9F=94=B4,=203=20=F0=9F=9F=A1=20(0=20misread);=20refuse=20a?= =?UTF-8?q?=20trailing-slash=20range,=20full=20plugin=20route,=20merged=20?= =?UTF-8?q?tests,=20compose=20passes=20TRUSTED=5FPROXIES?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- CHANGELOG.md | 21 ++++++++++--------- README.md | 36 ++++++++++++++++++++++---------- compose.yml | 1 + src/config.ts | 2 +- src/http/app-request-log.test.ts | 21 +++++++++++++++++-- src/http/app.test.ts | 22 ------------------- src/http/app.ts | 4 ++-- src/http/request-fields.test.ts | 16 +++++++++++++- src/http/request-fields.ts | 8 ++++--- src/http/request-tracking.ts | 9 ++++---- 10 files changed, 84 insertions(+), 56 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 05a8dff..2616f22 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,18 +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` log line renames `method`, `path`, `status` and `ms`, and gains the caller, site and 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. +Update dashboards and log queries: the `request` line and the request span now use OpenTelemetry's +HTTP names. `method`, `path` and `status` become `http.request.method`, `url.path` and +`http.response.status_code`. `ms` is gone: latency is the span's duration, so it needs +`OTLP_ENDPOINT`. New are `http.route` (when a route matched), `server.address` (the `Host`), +`user_agent.original` and `client.address`. A plugin's own lines for a request carry them too, +except the status. -`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. +`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 it follows `X-Forwarded-For`; a bad entry refuses the boot. +README → Observability says which ranges to list. 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 diff --git a/README.md b/README.md index 030c100..36655fd 100644 --- a/README.md +++ b/README.md @@ -1237,8 +1237,8 @@ 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` | +| `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)) | | `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 | | `HYDRA_ADMIN_URL` | `http://hydra:4445` | OAuth2 provider admin API (login/consent handshake) | @@ -1763,15 +1763,29 @@ 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, 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. +Every request emits one access line, and its span carries the same fields, named by +OpenTelemetry's HTTP conventions: + +- `http.request.method`, `url.path` (the query is dropped, it can carry tokens), + `http.response.status_code`, `server.address` (the `Host`), `user_agent.original`, + `client.address` and `requestId`. +- `http.route`: the matched pattern, such as `/admin/users/:id`. It is absent when no route + matched (a 404, a 405, a `/public/` file, a redirect) and on a plugin's `onRequest` short-circuit. +- Latency is the span's duration, so it reaches you only with `OTLP_ENDPOINT` set. OTLP carries every + attribute as a string. + +A plugin's own lines for a request carry them too, except the status, which is known only when +the response closes. + +**These 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. Behind a reverse proxy that is the proxy, so set +`TRUSTED_PROXIES` to its IPs or CIDR ranges: for a request from a listed peer, the address is the +nearest one in `X-Forwarded-For` that is not itself listed. Anything else in the header is +ignored. List only addresses a caller cannot send from. In Docker, `compose.yml` publishes the port +on every interface, so a range that includes the bridge gateway lets a direct caller write any +`client.address`. 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 @@ -1860,7 +1874,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, request-fields (span/log attributes) + static, safe-url (safeUrl + localPath), security-headers, request-fields · request-tracking (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/compose.yml b/compose.yml index 6e252bc..987c103 100644 --- a/compose.yml +++ b/compose.yml @@ -24,6 +24,7 @@ services: PLUGIN_DB_URL: ${PLUGIN_DB_URL:-} REQUIRE_SECURE_SECRETS: "true" SECURE_COOKIES: "true" # prod serves https — mark session/CSRF cookies Secure + TRUSTED_PROXIES: ${TRUSTED_PROXIES:-} # IPs/CIDRs of your reverse proxy; empty ⇒ X-Forwarded-For is ignored # Wait for the services the app talks to (kratos + keto + hydra for the OAuth2 login/ # consent handler) + the one-shot bootstrap (admin + JWKS seed). Postgres too: a plugin that # declares `storage` opens its connection in onBoot, before the server listens. diff --git a/src/config.ts b/src/config.ts index dada1fc..b9baa2d 100644 --- a/src/config.ts +++ b/src/config.ts @@ -185,7 +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"), - // Console-only by default; OTLP_ENDPOINT exports logs + per-request spans to an OpenTelemetry Collector. + // Console-only unless OTLP_ENDPOINT names a 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), diff --git a/src/http/app-request-log.test.ts b/src/http/app-request-log.test.ts index 71012b0..869111e 100644 --- a/src/http/app-request-log.test.ts +++ b/src/http/app-request-log.test.ts @@ -2,6 +2,7 @@ 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 type { Plugin } from "../plugin-host/plugin.ts"; import { createApp } from "./app.ts"; // The `request` line, parsed, once the server has logged it (it logs on the response's close). @@ -14,10 +15,10 @@ async function requestLineOf(lines: string[]): Promise> throw new Error("no request line was logged"); } -async function serve(t: TestContext, trustedProxies: string[]): Promise<{ lines: string[]; url: string }> { +async function serve(t: TestContext, trustedProxies: string[], plugins: Plugin[] = []): 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 }); + const app = createApp({ log, plugins, trustedProxies }); await new Promise((r) => app.listen(0, r)); t.after(() => app.close()); return { lines, url: `http://localhost:${(app.address() as AddressInfo).port}` }; @@ -35,9 +36,25 @@ test("the request line names the caller, the site and the matched route in OpenT 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 + assert.equal(line["service.name"], "plainpages"); + assert.ok(line["requestId"], "carries a requestId for log↔trace correlation"); for (const old of ["method", "path", "status", "ms"]) assert.equal(line[old], undefined, old); }); +test("http.route is the full pattern, plugin prefix included, so two plugins' routes never merge", async (t) => { + const plugin: Plugin = { + apiVersion: "1.0.0", + id: "demo", + routes: [{ handler: () => ({ json: {} }), method: "GET", path: "/items/:id", public: true }], + }; + const { lines, url } = await serve(t, [], [plugin]); + await (await fetch(`${url}/demo/items/7`)).text(); + const line = await requestLineOf(lines); + + assert.equal(line["http.route"], "/demo/items/:id"); + assert.equal(line["url.path"], "/demo/items/7"); +}); + 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(); diff --git a/src/http/app.test.ts b/src/http/app.test.ts index 62ea7a8..4b89d0f 100644 --- a/src/http/app.test.ts +++ b/src/http/app.test.ts @@ -115,28 +115,6 @@ test("renders branding from the menu config into the shell: logo + default theme assert.match(html, /id="theme-dark"\s+checked/); // config default theme reaches the switch }); -test("emits a structured access-log line per request (the injected logger)", async (t) => { - const lines: string[] = []; - const app = createApp({ log: createLogger({ format: "json", level: "info", stderr: () => {}, stdout: (m) => lines.push(m) }) }); - await new Promise((r) => app.listen(0, r)); - t.after(() => app.close()); - const res = await fetch(`http://localhost:${(app.address() as AddressInfo).port}/?q=zz`); // the public "/" — no auth - assert.equal(res.status, 200); - await res.text(); // consume the body so the connection closes (the access line emits on close) - - // The line is emitted on connection close (after the body is sent) — poll briefly for it. - let line: string | undefined; - for (let i = 0; i < 50 && !line; i++) { - line = lines.find((l) => l.includes('"msg":"request"')); - if (!line) await new Promise((r) => setTimeout(r, 10)); - } - assert.ok(line, "an access line is logged for the request"); - const rec = JSON.parse(line!); - assert.equal(rec["url.path"], "/"); // pathname only — the ?q=… query is dropped (may carry tokens) - assert.equal(rec["service.name"], "plainpages"); - assert.ok(rec.requestId, "carries a requestId for log↔trace correlation"); -}); - test("ctx.log: a handler logs in the request trace, and ctx.log.fetch continues the inbound trace", async (t) => { const lines: string[] = []; const upstream: { traceparent: string | undefined; url: string }[] = []; diff --git a/src/http/app.ts b/src/http/app.ts index a2c1cdd..f71ebca 100644 --- a/src/http/app.ts +++ b/src/http/app.ts @@ -24,7 +24,7 @@ import type { KratosPublic } from "../auth/kratos-public.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"; +import { declaredPermissions, fullPath, type Plugin, type RouteHandler, type RouteResult } from "../plugin-host/plugin.ts"; import type { PluginSettings } from "../plugin-host/settings.ts"; import type { SystemCapabilities } from "../plugin-host/system.ts"; import { allows, type Gate } from "../auth/gate.ts"; @@ -295,7 +295,7 @@ export function createApp(options: AppOptions = {}): Server { const match = matchRoute(plugins, method, pathname); if (match) { - reqLog.context["http.route"] = match.route.path; + reqLog.context["http.route"] = fullPath(match.plugin.id, match.route.path); const routeCtx = contextFor(match.plugin.id, match.params); if (!allows(match.route, routeCtx.user)) { await refuse(match.route, routeCtx); diff --git a/src/http/request-fields.test.ts b/src/http/request-fields.test.ts index 2a853a7..761b959 100644 --- a/src/http/request-fields.test.ts +++ b/src/http/request-fields.test.ts @@ -26,8 +26,22 @@ test("clientAddress: a malformed hop or a mapped IPv4 peer never yields garbage" assert.equal(clientAddress("fd00::1", "2001:db8::7", proxies), "2001:db8::7"); }); +test("parseTrustedProxies: a range covers exactly its prefix, and the extremes are legal", () => { + const one = parseTrustedProxies(["10.1.2.3/32", "fd00::7/128", "192.168.0.0/16"]); + assert.equal(clientAddress("10.1.2.3", "198.51.100.1", one), "198.51.100.1"); + assert.equal(clientAddress("10.1.2.4", "198.51.100.1", one), "10.1.2.4"); // /32 is one address + assert.equal(clientAddress("fd00::8", "2001:db8::7", one), "fd00::8"); // /128 is one address + assert.equal(clientAddress("192.168.255.1", "198.51.100.1", one), "198.51.100.1"); + assert.equal(clientAddress("192.169.0.1", "198.51.100.1", one), "192.169.0.1"); + assert.equal(clientAddress("203.0.113.9", "198.51.100.1", parseTrustedProxies(["0.0.0.0/0"])), "198.51.100.1"); // /0 is a choice, not a typo +}); + +test("clientAddress: a malformed hop left of a trusted one is not believed over the peer", () => { + assert.equal(clientAddress("10.0.0.1", "garbage, 10.0.0.2", proxies), "10.0.0.1"); +}); + 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", ""]) { + for (const bad of ["proxy.internal", "10.0.0.0/33", "10.0.0.0/x", "::1/129", "", "10.0.0.1/", "10.0.0.0/ ", "fd00::1/", "10.0.0.0//8", "10.0.0.0/8/8", "10.0.0.0/-1", "10.0.0.0/1e1"]) { assert.throws(() => parseTrustedProxies([bad]), /TRUSTED_PROXIES/, bad); } }); diff --git a/src/http/request-fields.ts b/src/http/request-fields.ts index 0525610..09cf6f7 100644 --- a/src/http/request-fields.ts +++ b/src/http/request-fields.ts @@ -3,8 +3,8 @@ 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. +// Each entry is an IP address or a CIDR range (`10.0.0.0/8`). A bad entry refuses the boot: a +// misread one could trust every caller's X-Forwarded-For. export function parseTrustedProxies(entries: readonly string[] = []): TrustedProxies { const list = new BlockList(); for (const entry of entries) { @@ -12,7 +12,9 @@ export function parseTrustedProxies(entries: readonly string[] = []): TrustedPro 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))) { + // `Number("")` is 0, so a trailing slash must be refused before the range check sees it. + const badPrefix = prefix !== undefined && !(/^\d{1,3}$/.test(prefix) && length! <= maxLength); + if (family === 0 || rest.length > 0 || badPrefix) { throw new Error(`config: TRUSTED_PROXIES entry "${entry}" is not an IP address or CIDR range`); } const kind = family === 4 ? "ipv4" : "ipv6"; diff --git a/src/http/request-tracking.ts b/src/http/request-tracking.ts index 0db535f..db99afc 100644 --- a/src/http/request-tracking.ts +++ b/src/http/request-tracking.ts @@ -4,7 +4,8 @@ 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. +// when the response closes. The handler adds `http.route` to the logger's context once routing has +// matched. export function trackRequest( log: Log, trusted: TrustedProxies, @@ -12,8 +13,6 @@ export function trackRequest( 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(), @@ -25,10 +24,12 @@ export function trackRequest( let settled = false; let closed = false; const finalize = (): void => { if (settled && closed) void reqLog.end().catch(() => {}); }; + // "close" (not "finish") fires on both a completed response and a premature disconnect, so an + // aborted request is still logged and its span flushed. 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. + // The context is what the span exports, so the status goes there. reqLog.context["http.response.status_code"] = res.statusCode; reqLog.info("request"); } catch { /* never let logging crash a served request */ }