Put the caller, site and route on every request's span and log line #216
@@ -12,6 +12,20 @@ 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`.
|
||||
|
||||
### The `request` log line renames `method`, `path`, `status` and `ms`, and gains the caller, site and route
|
||||
|
||||
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 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
|
||||
|
||||
Call `buildPaginationModel(page, hrefFor, { label?, pageSizes?, pageParam?, pageSizeParam? })` from
|
||||
|
||||
@@ -1238,6 +1238,7 @@ The app is **environment-agnostic**: no `NODE_ENV`, every behaviour its own expl
|
||||
| `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) |
|
||||
| `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) |
|
||||
@@ -1762,9 +1763,32 @@ 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 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
|
||||
`traceparent` is **adopted**, continuing a trace started upstream.
|
||||
|
||||
**Distributed tracing covers every outbound call.** Because the request logger is ambient, all
|
||||
@@ -1850,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
|
||||
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,
|
||||
|
||||
@@ -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.
|
||||
|
||||
@@ -340,3 +340,22 @@ Inherited architect, decided by:
|
||||
- Locality, Shape: `src/http/app.ts:271` `shared`: the two buildContext calls differ only in the translator and params
|
||||
- Self-sufficiency: `src/http/context.ts:28` `RequestContext.assetHref`: the contract field says on the spot what it does and how it differs from the view local
|
||||
- Self-sufficiency: `README.md:1050` pagination sketch: URL to partial in five lines, with the param-renaming rule
|
||||
|
||||
## 2026-11-08T14:10:47Z, PR #216 at bb134a3, against 6ca63c6
|
||||
|
||||
Ruling: better
|
||||
|
||||
| Seat | Navigation | Locality | Shape | Self-sufficiency | Overall |
|
||||
|---|---|---|---|---|---|
|
||||
| Mid A | better | same | better | same | better |
|
||||
| Inherited architect | same | better | better | same | better |
|
||||
|
||||
Mid A, decided by:
|
||||
|
||||
- Navigation, Shape: `src/http/request-tracking.ts:9` `trackRequest`: the per-request logger, span and access line now live in a named module instead of the tail of the 318-line `createApp`
|
||||
- Navigation, Shape: `src/http/request-fields.ts:33` `clientAddress`: the caller-IP and X-Forwarded-For rule has its own pure function in a file named for it
|
||||
|
||||
Inherited architect, decided by:
|
||||
|
||||
- Locality, Shape: `src/http/request-tracking.ts:9` `trackRequest`: the exactly-once finalize and close listener are one named unit, changeable without reading `createApp`'s other state
|
||||
- Locality, Shape: `src/http/request-fields.ts:33` `clientAddress`: pure function of peer, header and list, with the reasons for reading from the right beside it
|
||||
|
||||
@@ -354,3 +354,20 @@ Read most (opens and searches):
|
||||
- `src/plugin-host/discovery.ts` 2
|
||||
- `src/test-tooling/stylesheet-floor.test.ts` 2
|
||||
- `.dockerignore` 1
|
||||
|
||||
## Reading cost, chunk dcd9bc01df44, finished 2026-11-08T13:55:26Z
|
||||
|
||||
212195 new input tokens before the first commit.
|
||||
|
||||
Read most (opens and searches):
|
||||
|
||||
- `README.md` 10
|
||||
- `todo.md` 8
|
||||
- `src/http/app.ts` 4
|
||||
- `src/http/app.test.ts` 3
|
||||
- `src/http/static.ts` 3
|
||||
- `CHANGELOG.md` 2
|
||||
- `examples/plugins/admin/admin-users.ts` 2
|
||||
- `release-tooling/contract-version.test.ts` 2
|
||||
- `examples/plugins/admin/admin-clients.ts` 1
|
||||
- `examples/plugins/admin/admin-groups.ts` 1
|
||||
|
||||
@@ -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");
|
||||
|
||||
+11
-2
@@ -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<string, string | undefined>;
|
||||
@@ -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 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),
|
||||
@@ -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),
|
||||
};
|
||||
}
|
||||
|
||||
@@ -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<string, { lines?: number; complexity?: number }> = {
|
||||
"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 },
|
||||
|
||||
@@ -0,0 +1,66 @@
|
||||
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).
|
||||
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[], 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, plugins, 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
|
||||
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();
|
||||
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);
|
||||
});
|
||||
@@ -115,31 +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<void>((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.method, "GET");
|
||||
assert.equal(rec.path, "/"); // pathname only — the ?q=… query is dropped (may carry tokens)
|
||||
assert.equal(rec.status, 200);
|
||||
assert.equal(rec["service.name"], "plainpages");
|
||||
assert.equal(typeof rec.ms, "number");
|
||||
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 }[] = [];
|
||||
|
||||
+14
-38
@@ -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,15 +21,17 @@ 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";
|
||||
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";
|
||||
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;
|
||||
@@ -179,7 +183,7 @@ export function createApp(options: AppOptions = {}): Server {
|
||||
{ handler: serveDashboard, method: "GET", path: "/dashboard", session: true },
|
||||
];
|
||||
|
||||
// The request handler. Run inside runWithLog (below) so the per-request logger is ambient: every
|
||||
// The request handler. Run inside runWithLog (request-tracking.ts) so the per-request logger is ambient: every
|
||||
// outbound fetch (the Ory clients via tracedFetch) and any deep module joins this request's trace
|
||||
// and correlation with no logger threaded through their signatures.
|
||||
const handleRequest = async (req: IncomingMessage, res: ServerResponse, reqLog: Log): Promise<void> => {
|
||||
@@ -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"] = 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);
|
||||
@@ -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
|
||||
|
||||
@@ -0,0 +1,69 @@
|
||||
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: 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", "", "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);
|
||||
}
|
||||
});
|
||||
|
||||
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");
|
||||
});
|
||||
@@ -0,0 +1,67 @@
|
||||
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`). 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) {
|
||||
const [address = "", prefix, ...rest] = entry.split("/");
|
||||
const family = isIP(address);
|
||||
const length = prefix === undefined ? undefined : Number(prefix);
|
||||
const maxLength = family === 4 ? 32 : 128;
|
||||
// `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";
|
||||
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);
|
||||
@@ -0,0 +1,43 @@
|
||||
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 routing has
|
||||
// matched.
|
||||
export function trackRequest(
|
||||
log: Log,
|
||||
trusted: TrustedProxies,
|
||||
req: IncomingMessage,
|
||||
res: ServerResponse,
|
||||
handle: (req: IncomingMessage, res: ServerResponse, reqLog: Log) => Promise<void>,
|
||||
): void {
|
||||
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(() => {}); };
|
||||
// "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.
|
||||
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(); });
|
||||
}
|
||||
+5
-4
@@ -38,7 +38,7 @@ export function createLogger(opts: LoggerOptions = {}): Log {
|
||||
// The ambient per-request Log (see the header); set by runWithLog, read by currentLog/tracedFetch.
|
||||
const requestStore = new AsyncLocalStorage<Log>();
|
||||
|
||||
// Run `fn` with `log` as the ambient request logger (app.ts wraps each request). currentLog() reads
|
||||
// Run `fn` with `log` as the ambient request logger (request-tracking.ts wraps each request). currentLog() reads
|
||||
// it back; returns undefined outside any request (boot, tests) so callers use `currentLog()?.info(…)`.
|
||||
export function runWithLog<T>(log: Log, fn: () => T): T {
|
||||
return requestStore.run(log, fn);
|
||||
@@ -50,7 +50,7 @@ export function currentLog(): Log | undefined {
|
||||
// A drop-in `fetch` that traces through the active request log — a client span under the request
|
||||
// span, with a W3C `traceparent` injected so the downstream service continues the same trace.
|
||||
// Outside a request, or for a non-string/URL input, it is a plain `fetch`. Note log.fetch throws
|
||||
// synchronously once the request log has ended; app.ts ends it only after the handler unwinds.
|
||||
// synchronously once the request log has ended; request-tracking.ts ends it only after the handler unwinds.
|
||||
export const tracedFetch: typeof fetch = (input, init) => {
|
||||
const log = currentLog();
|
||||
if (log && (typeof input === "string" || input instanceof URL)) return log.fetch(input, init);
|
||||
@@ -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<string, string>; 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 } : {}),
|
||||
});
|
||||
|
||||
+2
-1
@@ -23,7 +23,7 @@ const config = loadConfig(); // validates the env (incl. enforced secrets) — f
|
||||
// depth, not a boundary (AGENTS.md) — and only ever move this line earlier, never later.
|
||||
delete process.env["PLUGIN_DB_SECRET"];
|
||||
// App-level logger: structured, OTLP-capable when OTLP_ENDPOINT is set. The hot path clones it
|
||||
// per request for access logging + a trace span (src/http/app.ts); console-only otherwise.
|
||||
// per request for access logging + a trace span (src/http/request-tracking.ts); console-only otherwise.
|
||||
const log = createLogger({ format: config.logFormat, level: config.logLevel, otlpEndpoint: config.otlpEndpoint, otlpProtocol: config.otlpProtocol, serviceName: config.serviceName });
|
||||
const menu = await loadMenuConfig(); // config/menu.ts override + branding — fails loud if malformed
|
||||
// Every outbound Ory call is traced through the active request's logger (a client span continuing
|
||||
@@ -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}` });
|
||||
});
|
||||
|
||||
@@ -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
|
||||
|
||||
Reference in New Issue
Block a user