feat(journal): per-request requestId propagated through logs

Every HTTP request now gets a requestId (inbound X-Request-Id header is
honored, otherwise a fresh UUID is minted) and the value is echoed on
the response. The server wraps the request in
\`requestContext.run({ requestId }, ...)\` — an AsyncLocalStorage scope —
so pino's \`mixin\` callback can read it on every log call without the
caller threading it through.

Net effect: \`logger.info({ ... }, \"db error\")\` from a loader, action,
or downstream lib now lands in JSON with a \`requestId\` field, making
cross-handler debugging trivial (\`grep requestId=abc-123\` returns the
full request trace).

Out of scope here:
- Planner gets the same treatment (separate, smaller PR after this lands).
- BRouter / Fedify outbound calls don't propagate the requestId yet —
  those are HTTP boundaries where we'd add it as a header, but the
  audit value was the in-process trace.

Tests:
- logger.server.test.ts (2 cases — als-bound info tags requestId; no
  context = no tag).

Full repo: pnpm typecheck, pnpm lint, pnpm test all green.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
Ullrich Schäfer 2026-05-24 12:31:30 +02:00
parent 3d34e215b9
commit f070914362
No known key found for this signature in database
GPG key ID: A32FF691A0F752D9
3 changed files with 96 additions and 16 deletions

View file

@ -0,0 +1,49 @@
import { describe, it, expect } from "vitest";
import { Writable } from "node:stream";
import pino from "pino";
import { AsyncLocalStorage } from "node:async_hooks";
// We test the *mixin contract* — that pino's `mixin` callback reads
// from the async-local store and tags every record. Constructing a
// fresh pino instance per test (vs. importing the module-level one)
// lets us capture stdout cleanly.
describe("logger mixin attaches requestId from async context", () => {
function captureLogger(als: AsyncLocalStorage<{ requestId: string }>) {
const lines: string[] = [];
const sink = new Writable({
write(chunk, _enc, cb) {
lines.push(chunk.toString());
cb();
},
});
const lg = pino(
{
level: "info",
mixin: () => {
const ctx = als.getStore();
return ctx ? { requestId: ctx.requestId } : {};
},
},
sink,
);
return { lg, lines };
}
it("tags log records with requestId when inside als.run()", () => {
const als = new AsyncLocalStorage<{ requestId: string }>();
const { lg, lines } = captureLogger(als);
als.run({ requestId: "abc-123" }, () => lg.info("hello"));
const record = JSON.parse(lines[0]!);
expect(record.requestId).toBe("abc-123");
expect(record.msg).toBe("hello");
});
it("omits requestId when no async context is active", () => {
const als = new AsyncLocalStorage<{ requestId: string }>();
const { lg, lines } = captureLogger(als);
lg.info("bare");
const record = JSON.parse(lines[0]!);
expect(record.requestId).toBeUndefined();
});
});

View file

@ -1,7 +1,27 @@
import pino from "pino";
import { AsyncLocalStorage } from "node:async_hooks";
/**
* Per-request context propagated through the async stack. The HTTP
* server wraps each request in `requestContext.run({ requestId }, ...)`
* so every downstream `logger.info(...)` automatically tags log lines
* with `requestId` no need to thread it through every call site.
*/
export interface RequestContext {
requestId: string;
}
export const requestContext = new AsyncLocalStorage<RequestContext>();
export const logger = pino({
level: process.env.LOG_LEVEL ?? "info",
// Mixin runs on every log call and merges its return value into the
// emitted record. Reading from ALS here is what makes requestId
// automatic for every downstream logger.info/warn/error.
mixin: () => {
const ctx = requestContext.getStore();
return ctx ? { requestId: ctx.requestId } : {};
},
...(process.env.NODE_ENV !== "production"
? { transport: { target: "pino-pretty" } }
: {}),

View file

@ -4,7 +4,8 @@ import { createRequestListener } from "@react-router/node";
import { createServer, type IncomingMessage, type ServerResponse } from "node:http";
import { createReadStream, statSync } from "node:fs";
import { join, extname, resolve } from "node:path";
import { logger } from "./app/lib/logger.server.ts";
import { logger, requestContext } from "./app/lib/logger.server.ts";
import { randomUUID } from "node:crypto";
import { httpRequestDuration, registry } from "./app/lib/metrics.server.ts";
import { createBoss, startWorker } from "@trails-cool/jobs";
import { getDatabaseUrl } from "@trails-cool/db";
@ -93,22 +94,32 @@ const server = createServer((req, res) => {
const url = req.url ?? "/";
const start = Date.now();
if (!url.startsWith("/assets/") && url !== "/api/health" && url !== "/api/metrics") {
res.on("finish", () => {
const duration = Date.now() - start;
logger.info({ method: req.method, path: url, status: res.statusCode, duration }, "request");
httpRequestDuration.observe(
{ method: req.method ?? "GET", route: url.split("?")[0]!, status: String(res.statusCode) },
duration / 1000,
);
});
}
// Honor an inbound X-Request-Id header (e.g. from Caddy or a probe)
// so request IDs propagate across the proxy hop. Mint a fresh one if
// absent. Echo on the response so clients can correlate.
const inbound = req.headers["x-request-id"];
const requestId =
(Array.isArray(inbound) ? inbound[0] : inbound) || randomUUID();
res.setHeader("X-Request-Id", requestId);
if (url === "/api/health") { handleHealth(req, res); return; }
if (url === "/api/metrics") { handleMetrics(req, res); return; }
if (!serveStatic(req, res)) {
listener(req, res);
}
requestContext.run({ requestId }, () => {
if (!url.startsWith("/assets/") && url !== "/api/health" && url !== "/api/metrics") {
res.on("finish", () => {
const duration = Date.now() - start;
logger.info({ method: req.method, path: url, status: res.statusCode, duration }, "request");
httpRequestDuration.observe(
{ method: req.method ?? "GET", route: url.split("?")[0]!, status: String(res.statusCode) },
duration / 1000,
);
});
}
if (url === "/api/health") { handleHealth(req, res); return; }
if (url === "/api/metrics") { handleMetrics(req, res); return; }
if (!serveStatic(req, res)) {
listener(req, res);
}
});
});
server.listen(port, async () => {