diff --git a/apps/journal/app/lib/logger.server.test.ts b/apps/journal/app/lib/logger.server.test.ts new file mode 100644 index 0000000..34b028b --- /dev/null +++ b/apps/journal/app/lib/logger.server.test.ts @@ -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(); + }); +}); diff --git a/apps/journal/app/lib/logger.server.ts b/apps/journal/app/lib/logger.server.ts index a0454ef..7fafe99 100644 --- a/apps/journal/app/lib/logger.server.ts +++ b/apps/journal/app/lib/logger.server.ts @@ -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(); 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" } } : {}), diff --git a/apps/journal/server.ts b/apps/journal/server.ts index abb58ff..89dbf93 100644 --- a/apps/journal/server.ts +++ b/apps/journal/server.ts @@ -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 () => {