diff --git a/src/app.ts b/src/app.ts index afb99e4..551d345 100644 --- a/src/app.ts +++ b/src/app.ts @@ -78,6 +78,7 @@ const securityHeadersMiddleware = (req: Request, res: Response, next: NextFuncti export function createApp(readinessReport: StartupReadinessReport): Express { const app = express(); + app.use(requestLogger); app.use(securityHeadersMiddleware); app.use(apiVersionMiddleware); app.use(versionResponseMiddleware); @@ -87,7 +88,6 @@ export function createApp(readinessReport: StartupReadinessReport): Express { // 3. Body Parsing app.use(express.json()); app.use(createCorsMiddleware()); - app.use(requestLogger); if (process.env.METRICS_ENABLED === "true") { app.get("/metrics", async (_req: Request, res: Response) => { diff --git a/src/middleware/errorHandler.ts b/src/middleware/errorHandler.ts index 0543d9d..91eae1f 100644 --- a/src/middleware/errorHandler.ts +++ b/src/middleware/errorHandler.ts @@ -38,6 +38,7 @@ import { isAppError, isValidationError, } from "../types/errors.js"; +import { logger } from "../utils/logger.js"; type ErrorEnvelope = { status: "error"; @@ -248,8 +249,8 @@ export const errorHandler = ( const statusCode = getStatusCode(err); // Log structured server-side context without leaking DB details or request bodies. - console.error("[Error]", { - level: "error", + logger.error({ + type: "request_error", errorType: err instanceof Error ? err.name : typeof err, message: err instanceof Error ? err.message : "Non-Error throwable", stack: err instanceof Error ? err.stack : undefined, @@ -262,7 +263,6 @@ export const errorHandler = ( path: req.path, method: req.method, requestId, - timestamp: new Date().toISOString(), }); // Create standardized error envelope diff --git a/src/middleware/requestLogger.ts b/src/middleware/requestLogger.ts index c54c265..9ab30c5 100644 --- a/src/middleware/requestLogger.ts +++ b/src/middleware/requestLogger.ts @@ -1,5 +1,5 @@ import { Request, Response, NextFunction } from "express"; -import { logger } from "../utils/logger.js"; +import { logger, runWithLoggerContext } from "../utils/logger.js"; import { randomUUID } from "crypto"; import { httpRequestDuration } from "../metrics.js"; @@ -13,6 +13,9 @@ export interface CorrelatedRequest extends Request { } const REDACTED = "[REDACTED]"; +const CORRELATION_ID_HEADER = "x-correlation-id"; +const LEGACY_REQUEST_ID_HEADER = "x-request-id"; +const CORRELATION_ID_PATTERN = /^[a-zA-Z0-9._:/=@-]{8,128}$/; /** Headers whose values must never appear in logs. */ export const REDACTED_HEADERS = new Set([ @@ -36,6 +39,21 @@ export const REDACTED_QUERY_PARAMS = new Set([ "code", ]); +export function sanitizeCorrelationId(value: unknown): string | undefined { + const candidate = Array.isArray(value) ? value[0] : value; + + if (typeof candidate !== "string") { + return undefined; + } + + const trimmed = candidate.trim(); + if (!CORRELATION_ID_PATTERN.test(trimmed)) { + return undefined; + } + + return trimmed; +} + function redactQuery(query: Record): Record { const result: Record = {}; for (const [key, value] of Object.entries(query)) { @@ -66,54 +84,48 @@ function redactQuery(query: Record): Record { export function requestLogger(req: Request, res: Response, next: NextFunction) { const start = process.hrtime(); - // Generate or reuse correlation ID from X-Request-ID header - // Use existing header if provided (for distributed tracing), otherwise generate new UUID - const correlationId = (req.headers["x-request-id"] as string) || randomUUID(); + const correlationId = + sanitizeCorrelationId(req.headers[CORRELATION_ID_HEADER]) ?? + sanitizeCorrelationId(req.headers[LEGACY_REQUEST_ID_HEADER]) ?? + randomUUID(); - // Attach correlation ID to request for use in downstream handlers (req as CorrelatedRequest).correlationId = correlationId; + res.locals.requestId = correlationId; + res.locals.correlationId = correlationId; - // Set correlation ID in response header for client-side tracing + res.setHeader("X-Correlation-ID", correlationId); res.setHeader("X-Request-ID", correlationId); - // Log incoming request with correlation ID - const requestLog = { - type: "request", - correlationId, - method: req.method, - path: req.path, - query: redactQuery(req.query as Record), - ip: req.ip, - userAgent: req.headers["user-agent"], - timestamp: new Date().toISOString(), - }; - - logger.info(JSON.stringify(requestLog)); - - // Once the response has finished, compute duration and log - res.on("finish", () => { - const [sec, nano] = process.hrtime(start); - const durationMs = sec * 1e3 + nano / 1e6; - const durationSec = sec + nano / 1e9; - - const route = (req.route?.path as string | undefined) ?? req.path; - httpRequestDuration.observe( - { method: req.method, route, status_code: String(res.statusCode) }, - durationSec, - ); - - const responseLog = { - type: "response", - correlationId, + return runWithLoggerContext({ correlationId }, () => { + logger.info({ + type: "request", method: req.method, path: req.path, - statusCode: res.statusCode, - durationMs: parseFloat(durationMs.toFixed(3)), - timestamp: new Date().toISOString(), - }; - - logger.info(JSON.stringify(responseLog)); + query: redactQuery(req.query as Record), + ip: req.ip, + userAgent: req.headers["user-agent"], + }); + + res.on("finish", () => { + const [sec, nano] = process.hrtime(start); + const durationMs = sec * 1e3 + nano / 1e6; + const durationSec = sec + nano / 1e9; + + const route = (req.route?.path as string | undefined) ?? req.path; + httpRequestDuration.observe( + { method: req.method, route, status_code: String(res.statusCode) }, + durationSec, + ); + + logger.info({ + type: "response", + method: req.method, + path: req.path, + statusCode: res.statusCode, + durationMs: parseFloat(durationMs.toFixed(3)), + }); + }); + + next(); }); - - next(); } diff --git a/src/utils/logger.ts b/src/utils/logger.ts index 0edae1b..1b5c2f9 100644 --- a/src/utils/logger.ts +++ b/src/utils/logger.ts @@ -1,67 +1,186 @@ +import { AsyncLocalStorage } from "node:async_hooks"; + /** - * Structured logger utility with JSON support for request tracing. - * - * Features: - * - Supports both plain text and structured JSON logging - * - Automatic JSON parsing for structured log entries - * - Consistent log level prefixes - * - Compatible with log aggregation tools (e.g., ELK, Datadog) + * Structured logger utility with request-scoped context. * * Security considerations: - * - Never logs sensitive data (passwords, tokens, PII) - * - Sanitizes output to prevent log injection attacks + * - Sensitive fields are redacted recursively before output. + * - Control characters are stripped from string values to prevent log injection. + * - Error objects are reduced to non-secret operational fields. * * @module logger */ +export type LogContext = Record; +type LogLevel = "info" | "warn" | "error"; + +const REDACTED = "[REDACTED]"; +const loggerContext = new AsyncLocalStorage(); + +export const SENSITIVE_LOG_FIELDS = new Set([ + "authorization", + "cookie", + "set-cookie", + "password", + "passwordhash", + "token", + "accesstoken", + "access_token", + "refreshtoken", + "refresh_token", + "resettoken", + "reset_token", + "resetlink", + "secret", + "apikey", + "api_key", + "x-api-key", + "x-auth-token", + "email", +]); + +export function runWithLoggerContext(context: LogContext, callback: () => T): T { + return loggerContext.run(sanitizeLogValue(context) as LogContext, callback); +} + +export function getLoggerContext(): LogContext { + return loggerContext.getStore() ?? {}; +} + export const logger = { - /** - * Log informational messages. - * @param {...any} args - Message arguments (string or JSON string) - */ - info: (...args: any[]) => { - const message = formatLogMessage(args); - console.log("[INFO]", message); - }, - - /** - * Log warning messages. - * @param {...any} args - Message arguments (string or JSON string) - */ - warn: (...args: any[]) => { - const message = formatLogMessage(args); - console.warn("[WARN]", message); - }, - - /** - * Log error messages. - * @param {...any} args - Message arguments (string or JSON string) - */ - error: (...args: any[]) => { - const message = formatLogMessage(args); - console.error("[ERROR]", message); - }, + info: (...args: unknown[]) => writeLog("info", args), + warn: (...args: unknown[]) => writeLog("warn", args), + error: (...args: unknown[]) => writeLog("error", args), }; -/** - * Format log message arguments, handling JSON strings appropriately. - * @param {any[]} args - Log message arguments - * @returns {string} Formatted log message - */ -function formatLogMessage(args: any[]): string { - return args - .map((arg) => { - if (typeof arg === "string") { - // Try to parse JSON strings for pretty printing - try { - const parsed = JSON.parse(arg); - return JSON.stringify(parsed, null, 2); - } catch { - // Not JSON, return as-is - return arg; - } +function writeLog(level: LogLevel, args: unknown[]): void { + const entry = buildLogEntry(level, args); + const output = JSON.stringify(entry); + + if (level === "error") { + console.error(output); + return; + } + + if (level === "warn") { + console.warn(output); + return; + } + + console.log(output); +} + +export function buildLogEntry(level: LogLevel, args: unknown[]): LogContext { + const { message, context } = normalizeLogArgs(args); + const scopedContext = sanitizeLogValue(getLoggerContext()) as LogContext; + const structuredContext = sanitizeLogValue(context) as LogContext; + + return { + ...scopedContext, + ...structuredContext, + ...(message ? { message: sanitizeString(message) } : {}), + timestamp: new Date().toISOString(), + level, + }; +} + +function normalizeLogArgs(args: unknown[]): { message?: string; context: LogContext } { + const context: LogContext = {}; + const messages: string[] = []; + + for (const arg of args) { + if (arg === undefined) { + continue; + } + + if (typeof arg === "string") { + const parsed = tryParseJsonObject(arg); + if (parsed) { + Object.assign(context, parsed); + } else { + messages.push(arg); } - return String(arg); - }) - .join(" "); + continue; + } + + if (isPlainRecord(arg)) { + Object.assign(context, arg); + continue; + } + + if (arg instanceof Error) { + context.err = { + name: arg.name, + message: arg.message, + stack: arg.stack, + }; + continue; + } + + messages.push(String(arg)); + } + + return { + message: messages.length > 0 ? messages.join(" ") : undefined, + context, + }; +} + +function tryParseJsonObject(value: string): LogContext | undefined { + try { + const parsed = JSON.parse(value); + return isPlainRecord(parsed) ? parsed : undefined; + } catch { + return undefined; + } +} + +function sanitizeLogValue(value: unknown, key?: string): unknown { + if (key && SENSITIVE_LOG_FIELDS.has(normalizeFieldName(key))) { + return REDACTED; + } + + if (typeof value === "string") { + return sanitizeString(value); + } + + if (Array.isArray(value)) { + return value.map((item) => sanitizeLogValue(item)); + } + + if (value instanceof Error) { + return { + name: sanitizeString(value.name), + message: sanitizeString(value.message), + stack: value.stack ? sanitizeString(value.stack) : undefined, + }; + } + + if (isPlainRecord(value)) { + const sanitized: LogContext = {}; + for (const [entryKey, entryValue] of Object.entries(value)) { + sanitized[entryKey] = sanitizeLogValue(entryValue, entryKey); + } + return sanitized; + } + + return value; +} + +function sanitizeString(value: string): string { + return value.replace(/[\r\n\t\u0000-\u001f\u007f]+/g, " "); +} + +function normalizeFieldName(key: string): string { + return key.toLowerCase().replace(/[^a-z0-9_-]/g, ""); +} + +function isPlainRecord(value: unknown): value is LogContext { + return ( + typeof value === "object" && + value !== null && + !Array.isArray(value) && + !(value instanceof Date) && + !(value instanceof Error) + ); } diff --git a/tests/README.md b/tests/README.md index 288f0e5..681e273 100644 --- a/tests/README.md +++ b/tests/README.md @@ -263,6 +263,10 @@ Unit tests in `tests/unit/middleware/validate.test.ts` cover `validateBody` and ## Redaction Policy +`requestLogger` seeds a request-scoped correlation id before body parsing, including webhook routes that require raw payloads. Inbound `x-correlation-id` values are reused only when they match the safe character and length policy; otherwise the middleware generates a UUID. The selected id is attached to `req.correlationId`, copied to `res.locals.requestId`, and echoed in both `X-Correlation-ID` and legacy `X-Request-ID` response headers. + +All application logs flow through `src/utils/logger.ts`, which emits one structured JSON object per line and automatically merges the request-scoped `correlationId` into logs written during the request, including auth, attestation, and webhook handlers. + `requestLogger` never writes sensitive values to logs. The policy is enforced via two exported sets in `src/middleware/requestLogger.ts`: | Set | Members | @@ -272,14 +276,17 @@ Unit tests in `tests/unit/middleware/validate.test.ts` cover `validateBody` and Matched values are replaced with the literal string `[REDACTED]` before the log entry is written. Non-sensitive fields pass through unchanged. +`logger.ts` also recursively redacts sensitive structured fields such as `password`, `token`, `accessToken`, `refreshToken`, `resetLink`, `secret`, `apiKey`, and `email` before writing to stdout/stderr. + **Threat model notes:** - Bearer tokens in `Authorization` headers are excluded from logs entirely (headers are not logged). - Cookies and `Set-Cookie` are in `REDACTED_HEADERS` for future-proofing if header logging is added. - OAuth `code` and `state` query params are redacted to prevent authorization-code interception via log aggregators. - Webhook payloads and request bodies are never logged (existing policy). +- Correlation IDs are constrained before reflection to response headers to prevent header or log injection. -To extend the policy, add entries to `REDACTED_HEADERS` or `REDACTED_QUERY_PARAMS` in `src/middleware/requestLogger.ts`. Tests in `tests/integration/auth.test.ts` under `"requestLogger redaction policy"` verify coverage. +To extend the policy, add entries to `REDACTED_HEADERS` or `REDACTED_QUERY_PARAMS` in `src/middleware/requestLogger.ts`, and sensitive structured field names to `SENSITIVE_LOG_FIELDS` in `src/utils/logger.ts`. Tests in `tests/integration/auth.test.ts` under `"requestLogger redaction policy"` and `tests/unit/middleware/requestLogger.test.ts` verify coverage. ## Running Tests diff --git a/tests/integration/auth.test.ts b/tests/integration/auth.test.ts index 1b31cce..754b439 100644 --- a/tests/integration/auth.test.ts +++ b/tests/integration/auth.test.ts @@ -1474,6 +1474,19 @@ describe("Security Considerations", () => { * Verifies that sensitive query params and headers are never written to logs. */ describe("requestLogger redaction policy", () => { + function captureRequestQuery(arg: unknown, loggedQueries: Record[]) { + const parsed = typeof arg === "string" ? JSON.parse(arg) : arg; + if ( + parsed && + typeof parsed === "object" && + "type" in parsed && + parsed.type === "request" && + "query" in parsed + ) { + loggedQueries.push(parsed.query as Record); + } + } + it("REDACTED_QUERY_PARAMS covers expected sensitive keys", async () => { const { REDACTED_QUERY_PARAMS } = await import("../../src/middleware/requestLogger.js"); @@ -1504,10 +1517,9 @@ describe("requestLogger redaction policy", () => { // Capture log output by spying on logger const { logger } = await import("../../src/utils/logger.js"); - const spy = vi.spyOn(logger, "info").mockImplementation((msg: string) => { + const spy = vi.spyOn(logger, "info").mockImplementation((msg: unknown) => { try { - const parsed = JSON.parse(msg); - if (parsed.type === "request") loggedQueries.push(parsed.query); + captureRequestQuery(msg, loggedQueries); } catch {} }); @@ -1530,10 +1542,9 @@ describe("requestLogger redaction policy", () => { testApp.get("/probe", (_req, res) => res.json({ ok: true })); const { logger } = await import("../../src/utils/logger.js"); - const spy = vi.spyOn(logger, "info").mockImplementation((msg: string) => { + const spy = vi.spyOn(logger, "info").mockImplementation((msg: unknown) => { try { - const parsed = JSON.parse(msg); - if (parsed.type === "request") loggedQueries.push(parsed.query); + captureRequestQuery(msg, loggedQueries); } catch {} }); @@ -1559,10 +1570,9 @@ describe("requestLogger redaction policy", () => { testApp.get("/probe", (_req, res) => res.json({ ok: true })); const { logger } = await import("../../src/utils/logger.js"); - const spy = vi.spyOn(logger, "info").mockImplementation((msg: string) => { + const spy = vi.spyOn(logger, "info").mockImplementation((msg: unknown) => { try { - const parsed = JSON.parse(msg); - if (parsed.type === "request") loggedQueries.push(parsed.query); + captureRequestQuery(msg, loggedQueries); } catch {} }); diff --git a/tests/unit/middleware/requestLogger.test.ts b/tests/unit/middleware/requestLogger.test.ts new file mode 100644 index 0000000..f307867 --- /dev/null +++ b/tests/unit/middleware/requestLogger.test.ts @@ -0,0 +1,79 @@ +import express from "express"; +import request from "supertest"; +import { afterEach, describe, expect, it, vi } from "vitest"; +import { + requestLogger, + sanitizeCorrelationId, +} from "../../../src/middleware/requestLogger.js"; + +function createProbeApp() { + const app = express(); + app.use(requestLogger); + app.get("/probe", (req, res) => { + res.json({ correlationId: (req as express.Request & { correlationId: string }).correlationId }); + }); + return app; +} + +function parseJsonLogs(spy: ReturnType) { + return spy.mock.calls.map(([line]) => JSON.parse(String(line)) as Record); +} + +afterEach(() => { + vi.restoreAllMocks(); +}); + +describe("requestLogger correlation id propagation", () => { + it("reuses inbound x-correlation-id, attaches it to req, and echoes response headers", async () => { + const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + const response = await request(createProbeApp()) + .get("/probe") + .set("x-correlation-id", "corr-inbound-123") + .expect(200); + + expect(response.body.correlationId).toBe("corr-inbound-123"); + expect(response.headers["x-correlation-id"]).toBe("corr-inbound-123"); + expect(response.headers["x-request-id"]).toBe("corr-inbound-123"); + + const logs = parseJsonLogs(consoleSpy); + expect(logs).toEqual( + expect.arrayContaining([ + expect.objectContaining({ type: "request", correlationId: "corr-inbound-123" }), + expect.objectContaining({ type: "response", correlationId: "corr-inbound-123" }), + ]), + ); + }); + + it("generates a safe correlation id when the inbound value is missing", async () => { + const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + const response = await request(createProbeApp()).get("/probe").expect(200); + + expect(response.headers["x-correlation-id"]).toMatch( + /^[0-9a-f]{8}-[0-9a-f]{4}-[1-5][0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i, + ); + expect(response.body.correlationId).toBe(response.headers["x-correlation-id"]); + + const logs = parseJsonLogs(consoleSpy); + expect(logs[0].correlationId).toBe(response.headers["x-correlation-id"]); + }); + + it("rejects malformed inbound ids instead of reflecting them into logs or headers", async () => { + const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {}); + const response = await request(createProbeApp()) + .get("/probe") + .set("x-correlation-id", "bad id 123") + .expect(200); + + expect(response.headers["x-correlation-id"]).not.toBe("bad id 123"); + expect(response.headers["x-correlation-id"]).toMatch(/^[a-f0-9-]{36}$/i); + + const serializedLogs = JSON.stringify(parseJsonLogs(consoleSpy)); + expect(serializedLogs).not.toContain("bad id 123"); + }); + + it("sanitizes acceptable ids and rejects unsafe ones", () => { + expect(sanitizeCorrelationId(" trace-123456 ")).toBe("trace-123456"); + expect(sanitizeCorrelationId("short")).toBeUndefined(); + expect(sanitizeCorrelationId("bad\r\nheader")).toBeUndefined(); + }); +}); diff --git a/tests/unit/utils/logger.test.ts b/tests/unit/utils/logger.test.ts new file mode 100644 index 0000000..17d6ba4 --- /dev/null +++ b/tests/unit/utils/logger.test.ts @@ -0,0 +1,44 @@ +import { describe, expect, it } from "vitest"; +import { buildLogEntry, runWithLoggerContext } from "../../../src/utils/logger.js"; + +describe("logger structured fields", () => { + it("merges request-scoped correlation id into log entries", () => { + const entry = runWithLoggerContext({ correlationId: "corr-test-123" }, () => + buildLogEntry("info", ["auth_event", { event: "AUTH_SUCCESS" }]), + ); + + expect(entry).toMatchObject({ + level: "info", + correlationId: "corr-test-123", + event: "AUTH_SUCCESS", + message: "auth_event", + }); + }); + + it("redacts sensitive fields from structured context", () => { + const entry = buildLogEntry("warn", [ + "sensitive_event", + { + email: "user@example.com", + password: "super-secret", + nested: { + accessToken: "access-token", + safe: "kept", + }, + }, + ]); + + expect(entry.email).toBe("[REDACTED]"); + expect(entry.password).toBe("[REDACTED]"); + expect(entry.nested).toMatchObject({ + accessToken: "[REDACTED]", + safe: "kept", + }); + }); + + it("strips control characters from messages to prevent log injection", () => { + const entry = buildLogEntry("error", ["first line\nsecond line\twith tab"]); + + expect(entry.message).toBe("first line second line with tab"); + }); +});