Put the caller, site and route on every request's span and log line

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<Record<string, unknown>> {
+  for (let i = 0; i < 200; i++) {
+    const line = lines.map((l) => JSON.parse(l) as Record<string, unknown>).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<void>((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);
+});

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");
 });
 

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

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<string, string>, 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");
+});

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<string, string> {
+  const fields: Record<string, string> = {
+    "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);

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>,
+): 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(); });
+}