diff --git a/README.md b/README.md index 337ee4f..7e90197 100644 --- a/README.md +++ b/README.md @@ -89,6 +89,10 @@ API key for the metering flow until API-key enforcement lands. Add your own `X-Request-Id` header when you want to correlate client logs with backend responses. The backend echoes the value on success and structured errors. +Structured logs default to `info` outside tests and `silent` in +`NODE_ENV=test`. Set `LOG_LEVEL` to one of `fatal`, `error`, `warn`, `info`, +`debug`, `trace`, or `silent` to override the default. + Set a shell variable for the local base URL: ```bash diff --git a/package-lock.json b/package-lock.json index b163bcc..0c674c5 100644 --- a/package-lock.json +++ b/package-lock.json @@ -9,7 +9,8 @@ "version": "1.0.0", "license": "MIT", "dependencies": { - "express": "^5.2.1" + "express": "^5.2.1", + "pino": "^10.3.1" }, "devDependencies": { "@eslint/js": "^9.39.4", @@ -261,6 +262,12 @@ "@noble/hashes": "^1.1.5" } }, + "node_modules/@pinojs/redact": { + "version": "0.4.0", + "resolved": "https://registry.npmjs.org/@pinojs/redact/-/redact-0.4.0.tgz", + "integrity": "sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==", + "license": "MIT" + }, "node_modules/@types/body-parser": { "version": "1.19.6", "resolved": "https://registry.npmjs.org/@types/body-parser/-/body-parser-1.19.6.tgz", @@ -760,6 +767,15 @@ "dev": true, "license": "MIT" }, + "node_modules/atomic-sleep": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/atomic-sleep/-/atomic-sleep-1.0.0.tgz", + "integrity": "sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==", + "license": "MIT", + "engines": { + "node": ">=8.0.0" + } + }, "node_modules/balanced-match": { "version": "4.0.4", "resolved": "https://registry.npmjs.org/balanced-match/-/balanced-match-4.0.4.tgz", @@ -1938,6 +1954,15 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/on-exit-leak-free": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/on-exit-leak-free/-/on-exit-leak-free-2.1.2.tgz", + "integrity": "sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==", + "license": "MIT", + "engines": { + "node": ">=14.0.0" + } + }, "node_modules/on-finished": { "version": "2.4.1", "resolved": "https://registry.npmjs.org/on-finished/-/on-finished-2.4.1.tgz", @@ -2061,6 +2086,43 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/pino": { + "version": "10.3.1", + "resolved": "https://registry.npmjs.org/pino/-/pino-10.3.1.tgz", + "integrity": "sha512-r34yH/GlQpKZbU1BvFFqOjhISRo1MNx1tWYsYvmj6KIRHSPMT2+yHOEb1SG6NMvRoHRF0a07kCOox/9yakl1vg==", + "license": "MIT", + "dependencies": { + "@pinojs/redact": "^0.4.0", + "atomic-sleep": "^1.0.0", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^3.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0", + "quick-format-unescaped": "^4.0.3", + "real-require": "^0.2.0", + "safe-stable-stringify": "^2.3.1", + "sonic-boom": "^4.0.1", + "thread-stream": "^4.0.0" + }, + "bin": { + "pino": "bin.js" + } + }, + "node_modules/pino-abstract-transport": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/pino-abstract-transport/-/pino-abstract-transport-3.0.0.tgz", + "integrity": "sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==", + "license": "MIT", + "dependencies": { + "split2": "^4.0.0" + } + }, + "node_modules/pino-std-serializers": { + "version": "7.1.0", + "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-7.1.0.tgz", + "integrity": "sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==", + "license": "MIT" + }, "node_modules/prelude-ls": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/prelude-ls/-/prelude-ls-1.2.1.tgz", @@ -2087,6 +2149,22 @@ "url": "https://github.com/prettier/prettier?sponsor=1" } }, + "node_modules/process-warning": { + "version": "5.0.0", + "resolved": "https://registry.npmjs.org/process-warning/-/process-warning-5.0.0.tgz", + "integrity": "sha512-a39t9ApHNx2L4+HBnQKqxxHNs1r7KF+Intd8Q/g1bUh6q0WIp9voPXJ/x0j+ZL45KF1pJd9+q2jLIRMfvEshkA==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "MIT" + }, "node_modules/proxy-addr": { "version": "2.0.7", "resolved": "https://registry.npmjs.org/proxy-addr/-/proxy-addr-2.0.7.tgz", @@ -2126,6 +2204,12 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/quick-format-unescaped": { + "version": "4.0.4", + "resolved": "https://registry.npmjs.org/quick-format-unescaped/-/quick-format-unescaped-4.0.4.tgz", + "integrity": "sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==", + "license": "MIT" + }, "node_modules/range-parser": { "version": "1.3.0", "resolved": "https://registry.npmjs.org/range-parser/-/range-parser-1.3.0.tgz", @@ -2154,6 +2238,15 @@ "node": ">= 0.10" } }, + "node_modules/real-require": { + "version": "0.2.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-0.2.0.tgz", + "integrity": "sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg==", + "license": "MIT", + "engines": { + "node": ">= 12.13.0" + } + }, "node_modules/router": { "version": "2.2.0", "resolved": "https://registry.npmjs.org/router/-/router-2.2.0.tgz", @@ -2170,6 +2263,15 @@ "node": ">= 18" } }, + "node_modules/safe-stable-stringify": { + "version": "2.5.0", + "resolved": "https://registry.npmjs.org/safe-stable-stringify/-/safe-stable-stringify-2.5.0.tgz", + "integrity": "sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==", + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/safer-buffer": { "version": "2.1.2", "resolved": "https://registry.npmjs.org/safer-buffer/-/safer-buffer-2.1.2.tgz", @@ -2360,6 +2462,24 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/sonic-boom": { + "version": "4.2.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-4.2.1.tgz", + "integrity": "sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==", + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, + "node_modules/split2": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/split2/-/split2-4.2.0.tgz", + "integrity": "sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg==", + "license": "ISC", + "engines": { + "node": ">= 10.x" + } + }, "node_modules/statuses": { "version": "2.0.2", "resolved": "https://registry.npmjs.org/statuses/-/statuses-2.0.2.tgz", @@ -2407,6 +2527,24 @@ "node": ">=6.4.0" } }, + "node_modules/thread-stream": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/thread-stream/-/thread-stream-4.2.0.tgz", + "integrity": "sha512-e2zZ96wSChazBsbENf/Pcm/4swHt2cEKQ92rhUjkL9GCKiTDJIaTBenjE/m9DXi0QBmTMDkFDdOomUy20A1tDQ==", + "license": "MIT", + "dependencies": { + "real-require": "^1.0.0" + }, + "engines": { + "node": ">=20" + } + }, + "node_modules/thread-stream/node_modules/real-require": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-1.0.0.tgz", + "integrity": "sha512-P4nbQYQfePJxRSmY+v/KINxVucm4NF3p3s7pJveMTtom52FR4YGltUQLB8idDXwDDWW+eYrWDFbuzUnjoWHF7g==", + "license": "MIT" + }, "node_modules/tinyglobby": { "version": "0.2.17", "resolved": "https://registry.npmjs.org/tinyglobby/-/tinyglobby-0.2.17.tgz", diff --git a/package.json b/package.json index 3dbf8c7..dc7a22b 100644 --- a/package.json +++ b/package.json @@ -36,6 +36,7 @@ "typescript-eslint": "^8.61.1" }, "dependencies": { - "express": "^5.2.1" + "express": "^5.2.1", + "pino": "^10.3.1" } } diff --git a/src/index.ts b/src/index.ts index 9ece0f2..d1ea817 100644 --- a/src/index.ts +++ b/src/index.ts @@ -1,4 +1,11 @@ import express from "express"; +import { + logger, + logForcedShutdown, + logServerCloseError, + logServerStarted, + logShutdownSignal, +} from "./logger.js"; import { installPreRouteMiddleware, installRequestStateMiddleware, @@ -46,20 +53,20 @@ const app = createApp(); if (process.argv[1]?.endsWith("index.js") || process.argv[1]?.endsWith("index.ts")) { const server = app.listen(PORT, () => { - console.log(`AgentPay backend listening on port ${PORT}`); + logServerStarted(logger, PORT); }); const shutdown = (signal: string) => { - console.log(`Received ${signal}, draining…`); + logShutdownSignal(logger, signal); server.close((err) => { if (err) { - console.error("server.close error:", err); + logServerCloseError(logger, err); process.exit(1); } process.exit(0); }); setTimeout(() => { - console.error("Forced exit after 10s drain timeout"); + logForcedShutdown(logger, 10_000); process.exit(1); }, 10_000).unref(); }; diff --git a/src/logger.test.ts b/src/logger.test.ts new file mode 100644 index 0000000..5e0737f --- /dev/null +++ b/src/logger.test.ts @@ -0,0 +1,135 @@ +import { describe, it, afterEach } from "node:test"; +import assert from "node:assert"; +import type { DestinationStream } from "pino"; +import { createLogger, logRequestCompletion, logServerCloseError } from "./logger.js"; + +type Capture = { + stream: DestinationStream; + lines: string[]; + records: () => Record[]; +}; + +function createCapture(): Capture { + const lines: string[] = []; + return { + stream: { + write(message: string) { + lines.push(message); + }, + }, + lines, + records: () => + lines + .join("") + .split("\n") + .filter(Boolean) + .map((line) => JSON.parse(line) as Record), + }; +} + +const originalNodeEnv = process.env.NODE_ENV; +const originalLogLevel = process.env.LOG_LEVEL; + +afterEach(() => { + if (originalNodeEnv === undefined) { + delete process.env.NODE_ENV; + } else { + process.env.NODE_ENV = originalNodeEnv; + } + + if (originalLogLevel === undefined) { + delete process.env.LOG_LEVEL; + } else { + process.env.LOG_LEVEL = originalLogLevel; + } +}); + +void describe("structured logger", () => { + void it("defaults to silent in test mode", () => { + process.env.NODE_ENV = "test"; + delete process.env.LOG_LEVEL; + const capture = createCapture(); + const logger = createLogger({ destination: capture.stream }); + + logger.info({ event: "test-mode" }, "should be quiet"); + + assert.deepStrictEqual(capture.records(), []); + }); + + void it("honors log level filtering", () => { + const capture = createCapture(); + const logger = createLogger({ destination: capture.stream, level: "warn" }); + + logger.info({ event: "ignored" }, "below threshold"); + logger.error({ event: "kept" }, "at threshold"); + + const records = capture.records(); + assert.strictEqual(records.length, 1); + assert.strictEqual(records[0]?.event, "kept"); + assert.strictEqual(records[0]?.level, 50); + }); + + void it("redacts API keys and generated key fields", () => { + const capture = createCapture(); + const logger = createLogger({ destination: capture.stream, level: "info" }); + + logger.info( + { + apiKey: "tenant-secret", + generatedKey: "generated-secret", + key: "returned-secret", + headers: { "x-api-key": "header-secret" }, + req: { headers: { "x-api-key": "nested-header-secret" } }, + }, + "redaction check" + ); + + const output = capture.lines.join(""); + assert.doesNotMatch(output, /tenant-secret/); + assert.doesNotMatch(output, /generated-secret/); + assert.doesNotMatch(output, /returned-secret/); + assert.doesNotMatch(output, /header-secret/); + assert.doesNotMatch(output, /nested-header-secret/); + assert.match(output, /\[Redacted\]/); + }); + + void it("logs request completion with requestId correlation fields", () => { + const capture = createCapture(); + const logger = createLogger({ destination: capture.stream, level: "info" }); + + logRequestCompletion(logger, { + requestId: "req-123", + method: "POST", + path: "/api/v1/usage", + status: 201, + durationMs: 12.3, + }); + + const [record] = capture.records(); + assert.strictEqual(record?.requestId, "req-123"); + assert.strictEqual(record?.method, "POST"); + assert.strictEqual(record?.path, "/api/v1/usage"); + assert.strictEqual(record?.status, 201); + assert.strictEqual(record?.durationMs, 12.3); + assert.strictEqual(record?.msg, "request completed"); + }); + + void it("serializes shutdown errors without leaking keys", () => { + const capture = createCapture(); + const logger = createLogger({ destination: capture.stream, level: "error" }); + + logServerCloseError( + logger, + Object.assign(new Error("close failed"), { + apiKey: "error-secret", + }) + ); + + const output = capture.lines.join(""); + assert.match(output, /close failed/); + assert.doesNotMatch(output, /error-secret/); + const [record] = capture.records(); + assert.strictEqual(record?.msg, "server close failed"); + assert.strictEqual(record?.level, 50); + }); +}); diff --git a/src/logger.ts b/src/logger.ts new file mode 100644 index 0000000..3d52428 --- /dev/null +++ b/src/logger.ts @@ -0,0 +1,90 @@ +import pino, { type DestinationStream, type Logger, type LoggerOptions } from "pino"; + +const LOG_LEVELS = new Set([ + "fatal", + "error", + "warn", + "info", + "debug", + "trace", + "silent", +]); + +const REDACT_PATHS = [ + "apiKey", + "generatedKey", + "key", + "*.apiKey", + "*.generatedKey", + "*.key", + 'headers["x-api-key"]', + 'headers["X-API-Key"]', + 'req.headers["x-api-key"]', + 'req.headers["X-API-Key"]', +]; + +type CreateLoggerOptions = { + level?: string; + destination?: DestinationStream; +}; + +type RequestCompletionFields = { + requestId?: string; + method: string; + path: string; + status: number; + durationMs: number; +}; + +function normalizeLogLevel(level: string | undefined): string { + if (level && LOG_LEVELS.has(level)) return level; + if (process.env.NODE_ENV === "test") return "silent"; + return "info"; +} + +/** + * Builds the shared structured logger with environment-aware level selection + * and defensive redaction for API-key shaped fields. + */ +export function createLogger(options: CreateLoggerOptions = {}): Logger { + const loggerOptions: LoggerOptions = { + level: normalizeLogLevel(options.level ?? process.env.LOG_LEVEL), + redact: { + paths: REDACT_PATHS, + censor: "[Redacted]", + }, + serializers: { + err: pino.stdSerializers.err, + }, + }; + + if (options.destination) { + return pino(loggerOptions, options.destination); + } + return pino(loggerOptions); +} + +export const logger = createLogger(); + +export function logRequestCompletion( + log: Logger, + fields: RequestCompletionFields +): void { + log.info(fields, "request completed"); +} + +export function logServerStarted(log: Logger, port: string | number): void { + log.info({ port }, "server started"); +} + +export function logShutdownSignal(log: Logger, signal: string): void { + log.info({ signal }, "shutdown signal received"); +} + +export function logServerCloseError(log: Logger, err: unknown): void { + log.error({ err }, "server close failed"); +} + +export function logForcedShutdown(log: Logger, timeoutMs: number): void { + log.error({ timeoutMs }, "forced exit after drain timeout"); +} diff --git a/src/middleware/index.ts b/src/middleware/index.ts index 53859a7..d854473 100644 --- a/src/middleware/index.ts +++ b/src/middleware/index.ts @@ -5,6 +5,7 @@ import express, { type Request, type Response, } from "express"; +import { logger, logRequestCompletion } from "../logger.js"; import { apiKeyStore, pauseState, @@ -150,17 +151,13 @@ function requestTimerMiddleware(req: Request, res: Response, next: NextFunction) if (!res.headersSent) { res.setHeader("Server-Timing", `app;dur=${ms.toFixed(1)}`); } - if (process.env.NODE_ENV !== "test") { - console.log( - JSON.stringify({ - requestId: (req as AgentPayRequest).id, - method: req.method, - path: req.path, - status: res.statusCode, - durationMs: Math.round(ms * 10) / 10, - }) - ); - } + logRequestCompletion(logger, { + requestId: (req as AgentPayRequest).id, + method: req.method, + path: req.path, + status: res.statusCode, + durationMs: Math.round(ms * 10) / 10, + }); }); next(); }