From 3a9c9fd3c9d45e9fc146e04b767ef31eea14ca4c Mon Sep 17 00:00:00 2001 From: Michelle Nifemi Date: Sun, 28 Jun 2026 00:55:34 +0100 Subject: [PATCH] changes --- .env.example | 6 +- README.md | 2 + docs/request-id-propagation.md | 3 + package-lock.json | 53 +++- .../api-key-redaction-regression.test.ts | 30 ++- src/app.ts | 11 +- src/config/env.ts | 2 + src/config/index.ts | 7 + src/index.ts | 12 +- src/middleware/accessLog.test.ts | 149 +++++++++++ src/middleware/accessLog.ts | 232 ++++++++++++++++++ src/middleware/logging.test.ts | 10 +- src/middleware/logging.ts | 50 ---- 13 files changed, 498 insertions(+), 69 deletions(-) create mode 100644 src/middleware/accessLog.test.ts create mode 100644 src/middleware/accessLog.ts diff --git a/.env.example b/.env.example index 3fdea6e..85daff0 100644 --- a/.env.example +++ b/.env.example @@ -150,10 +150,12 @@ APP_VERSION=1.0.0 # ----------------------------------------------------------------------------- # Logging -# ----------------------------------------------------------------------------- +# ----------------------------------------------------------------------------- LOG_LEVEL=info +ACCESS_LOG_SAMPLE_RATE=1 +# ACCESS_LOG_REDACT_FIELDS=path,correlationId -# ----------------------------------------------------------------------------- +# ----------------------------------------------------------------------------- # Profiling # ----------------------------------------------------------------------------- GATEWAY_PROFILING_ENABLED=false diff --git a/README.md b/README.md index 2cd1a20..cb4de9a 100644 --- a/README.md +++ b/README.md @@ -311,6 +311,8 @@ For request-id validation, AsyncLocalStorage propagation, structured logging, an | `HEALTH_CHECK_DB_TIMEOUT` | No | `2000` | DB health check timeout (ms) | | `APP_VERSION` | No | `1.0.0` | Reported in health check responses | | `LOG_LEVEL` | No | `info` | `trace` / `debug` / `info` / `warn` / `error` / `fatal` | +| `ACCESS_LOG_SAMPLE_RATE` | No | `1` | Fraction of requests logged as access events (`1` = 100%) | +| `ACCESS_LOG_REDACT_FIELDS` | No | `""` | Comma-separated access-log fields to redact (`path`, `correlationId`, etc.) | | `GATEWAY_PROFILING_ENABLED` | No | `false` | Enable request profiling | ### Health Check Behavior diff --git a/docs/request-id-propagation.md b/docs/request-id-propagation.md index c980c38..80e20cc 100644 --- a/docs/request-id-propagation.md +++ b/docs/request-id-propagation.md @@ -24,6 +24,9 @@ Both logger paths attach the active request id: - `src/logger.ts` prefixes console-style logs with `[request_id:]`. - `src/middleware/logging.ts` injects `requestId` into Pino structured payloads. +- `src/middleware/accessLog.ts` emits JSON access logs with `method`, `path`, `status`, `ms`, request/response byte counts, and a `correlationId`. +- Access-log sampling defaults to 100% and can be reduced with `ACCESS_LOG_SAMPLE_RATE`. +- Access-log redaction is configurable with `ACCESS_LOG_REDACT_FIELDS`. Sensitive values are still redacted before logging. diff --git a/package-lock.json b/package-lock.json index c3767fc..62504e4 100644 --- a/package-lock.json +++ b/package-lock.json @@ -4275,7 +4275,7 @@ "version": "7.6.13", "resolved": "https://registry.npmjs.org/@types/better-sqlite3/-/better-sqlite3-7.6.13.tgz", "integrity": "sha512-NMv9ASNARoKksWtsq/SHakpYAYnhBrQgGD8zkLYk/jaK8jUGn08CfEdTRgYhMypUQAfzSP8W6gNLe0q19/t4VA==", - "dev": true, + "devOptional": true, "license": "MIT", "dependencies": { "@types/node": "*" @@ -4476,7 +4476,7 @@ "version": "8.20.0", "resolved": "https://registry.npmjs.org/@types/pg/-/pg-8.20.0.tgz", "integrity": "sha512-bEPFOaMAHTEP1EzpvHTbmwR8UsFyHSKsRisLIHVMXnpNefSbGA1bD6CVy+qKjGSqmZqNqBDV2azOBo8TgkcVow==", - "dev": true, + "devOptional": true, "license": "MIT", "dependencies": { "@types/node": "*", @@ -4498,6 +4498,16 @@ "dev": true, "license": "MIT" }, + "node_modules/@types/react": { + "version": "19.2.17", + "resolved": "https://registry.npmjs.org/@types/react/-/react-19.2.17.tgz", + "integrity": "sha512-MXfmqaVPEVgkBT/aY0aGCkRWWtByiYQXo3xdQ8r5RzuFrPiRn8Gar2tQdXSUQ2GKV3bkXckek89V8wQBY2Q/Aw==", + "license": "MIT", + "peer": true, + "dependencies": { + "csstype": "^3.2.2" + } + }, "node_modules/@types/send": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/@types/send/-/send-1.2.1.tgz", @@ -5892,6 +5902,13 @@ "node": ">= 8" } }, + "node_modules/csstype": { + "version": "3.2.3", + "resolved": "https://registry.npmjs.org/csstype/-/csstype-3.2.3.tgz", + "integrity": "sha512-z1HGKcYy2xA8AGQfwrn0PAy+PB7X/GSj3UVJW9qKyn43xWa+gl5nXmU4qqLMRzWVLFC8KusUX8T/0kCiOYpAIQ==", + "license": "MIT", + "peer": true + }, "node_modules/d": { "version": "1.0.2", "resolved": "https://registry.npmjs.org/d/-/d-1.0.2.tgz", @@ -13037,6 +13054,29 @@ "destr": "^2.0.3" } }, + "node_modules/react": { + "version": "19.2.7", + "resolved": "https://registry.npmjs.org/react/-/react-19.2.7.tgz", + "integrity": "sha512-HNe9WslTbXmFK8o8cmwgAeJFSBvt1bPdHCVKtaaV+WlAN36mpT4hcRpwbf3fY56ar2oIXzsBpOAiIRHAdY0OlQ==", + "license": "MIT", + "peer": true, + "engines": { + "node": ">=0.10.0" + } + }, + "node_modules/react-dom": { + "version": "19.2.7", + "resolved": "https://registry.npmjs.org/react-dom/-/react-dom-19.2.7.tgz", + "integrity": "sha512-t0BRVXvbiE/o20Hfw669rLbMCDWtYZLvmJigy2f0MxsXF+71pxhR3xOkspmsO8h3ZlNzyibAmtCa3l4lYKk6gQ==", + "license": "MIT", + "peer": true, + "dependencies": { + "scheduler": "^0.27.0" + }, + "peerDependencies": { + "react": "^19.2.7" + } + }, "node_modules/react-is": { "version": "18.3.1", "resolved": "https://registry.npmjs.org/react-is/-/react-is-18.3.1.tgz", @@ -13224,6 +13264,13 @@ "integrity": "sha512-YZo3K82SD7Riyi0E1EQPojLz7kpepnSQI9IyPbHHg1XXXevb5dJI7tpyN2ADxGcQbHG7vcyRHk0cbwqcQriUtg==", "license": "MIT" }, + "node_modules/scheduler": { + "version": "0.27.0", + "resolved": "https://registry.npmjs.org/scheduler/-/scheduler-0.27.0.tgz", + "integrity": "sha512-eNv+WrVbKu1f3vbYJT/xtiF5syA5HPIMtf9IgY/nKg0sWqzAUEvqY/xm7OcZc/qafLx/iO9FgOmeSAp4v5ti/Q==", + "license": "MIT", + "peer": true + }, "node_modules/semver": { "version": "7.7.4", "resolved": "https://registry.npmjs.org/semver/-/semver-7.7.4.tgz", @@ -14629,7 +14676,7 @@ "version": "5.9.3", "resolved": "https://registry.npmjs.org/typescript/-/typescript-5.9.3.tgz", "integrity": "sha512-jl1vZzPDinLr9eUt3J/t7V6FgNEw9QjvBPdysz9KfQDD41fQrC2Y4vKQdiaUpFT4bXlb1RHhLpp8wtm6M5TgSw==", - "dev": true, + "devOptional": true, "license": "Apache-2.0", "bin": { "tsc": "bin/tsc", diff --git a/src/__tests__/api-key-redaction-regression.test.ts b/src/__tests__/api-key-redaction-regression.test.ts index a63de98..3f5ea6f 100644 --- a/src/__tests__/api-key-redaction-regression.test.ts +++ b/src/__tests__/api-key-redaction-regression.test.ts @@ -2,7 +2,8 @@ import assert from 'node:assert/strict'; import { EventEmitter } from 'node:events'; import type { Request, Response } from 'express'; import { REDACTED_LOG_VALUE, redactLogValue } from '../logger.js'; -import { logger, requestLogger } from '../middleware/logging.js'; +import { logger } from '../middleware/logging.js'; +import { requestLogger } from '../middleware/accessLog.js'; describe('API Key Redaction Regression Tests', () => { describe('redactLogValue - common API key formats', () => { @@ -184,7 +185,12 @@ describe('API Key Redaction Regression Tests', () => { assert(!('headers' in payload), 'headers should not be in log payload'); assert(!('body' in payload), 'body should not be in log payload'); assert(payload.requestId, 'requestId should be in log payload'); + assert(payload.correlationId, 'correlationId should be in log payload'); assert.equal(payload.method, 'POST'); + assert.equal(payload.status, 200); + assert.equal(payload.statusCode, 200); + assert.equal(payload.requestBytes, 0); + assert.equal(payload.responseBytes, 0); } finally { infoSpy.mockRestore(); } @@ -215,14 +221,20 @@ describe('API Key Redaction Regression Tests', () => { res.emit('finish'); // Verify that the authorization header doesn't leak into the request ID or logs - expect(infoSpy.mock.calls[0][0]).toEqual({ - requestId: 'safe-request-id-123', - method: 'GET', - path: '/api/data', - statusCode: 200, - durationMs: expect.any(Number), - clientIp: expect.any(String), - }); + expect(infoSpy.mock.calls[0][0]).toEqual( + expect.objectContaining({ + requestId: 'safe-request-id-123', + correlationId: 'safe-request-id-123', + method: 'GET', + path: '/api/data', + status: 200, + statusCode: 200, + ms: expect.any(Number), + durationMs: expect.any(Number), + requestBytes: 0, + responseBytes: 0, + }), + ); } finally { infoSpy.mockRestore(); } diff --git a/src/app.ts b/src/app.ts index b07ae5f..fd776d2 100644 --- a/src/app.ts +++ b/src/app.ts @@ -40,7 +40,7 @@ import { VaultController } from './controllers/vaultController.js'; import { TransactionBuilderService } from './services/transactionBuilder.js'; import { requestIdMiddleware } from './middleware/requestId.js'; import { validate } from './middleware/validate.js'; -import { requestLogger } from './middleware/logging.js'; +import { createAccessLogMiddleware } from './middleware/accessLog.js'; import { auditEnrichMiddleware } from './middleware/auditEnrich.js'; import { createConfiguredRestRateLimitMiddleware } from './middleware/restRateLimit.js'; import { metricsMiddleware, metricsEndpoint } from './metrics.js'; @@ -148,7 +148,12 @@ export const createApp = (dependencies?: Partial) => { app.use(requestIdMiddleware); app.use(metricsMiddleware); - app.use(requestLogger); + app.use( + createAccessLogMiddleware({ + sampleRate: config.accessLog.sampleRate, + redactFields: config.accessLog.redactFields, + }), + ); // Parse allowed origins with validation const allowedOrigins = (process.env.CORS_ALLOWED_ORIGINS ?? 'http://localhost:5173') @@ -552,4 +557,4 @@ export const createApp = (dependencies?: Partial) => { app.use(errorHandler); return app; -}; \ No newline at end of file +}; diff --git a/src/config/env.ts b/src/config/env.ts index 6ff35bb..b47db4b 100644 --- a/src/config/env.ts +++ b/src/config/env.ts @@ -159,6 +159,8 @@ export const envSchema = z LOG_LEVEL: z .enum(["trace", "debug", "info", "warn", "error", "fatal"]) .default("info"), + ACCESS_LOG_SAMPLE_RATE: z.coerce.number().min(0).max(1).default(1), + ACCESS_LOG_REDACT_FIELDS: z.string().optional(), // Profiling GATEWAY_PROFILING_ENABLED: z diff --git a/src/config/index.ts b/src/config/index.ts index 90fb885..171d468 100644 --- a/src/config/index.ts +++ b/src/config/index.ts @@ -95,6 +95,13 @@ export const config = { port: env.PORT, nodeEnv: env.NODE_ENV, version: env.APP_VERSION, + accessLog: { + sampleRate: env.ACCESS_LOG_SAMPLE_RATE, + redactFields: (env.ACCESS_LOG_REDACT_FIELDS ?? '') + .split(',') + .map((field) => field.trim()) + .filter((field) => field.length > 0), + }, databaseUrl: env.DATABASE_URL, replicaUrls: env.REPLICA_URLS, diff --git a/src/index.ts b/src/index.ts index 86e07b5..adb294e 100644 --- a/src/index.ts +++ b/src/index.ts @@ -4,10 +4,13 @@ import helmet from 'helmet'; import { initializeDb, closeDb } from './db/index.js'; import { closePgPool, pool } from './db.js'; import { closeDbPool } from './config/health.js'; +import { config } from './config/index.js'; import { disconnectPrisma } from './lib/prisma.js'; import { legacyV1DeprecationMiddleware } from './middleware/deprecation.js'; import { errorHandler } from './middleware/errorHandler.js'; import { createGatewayIpAllowlist } from './middleware/ipAllowlist.js'; +import { createAccessLogMiddleware } from './middleware/accessLog.js'; +import { requestIdMiddleware } from './middleware/requestId.js'; import { metricsEndpoint } from './metrics.js'; import { awaitWebhookDispatcherIdle, stopWebhookDispatching } from './webhooks/webhook.dispatcher.js'; import { @@ -36,7 +39,6 @@ import { createPostgresUsageStore } from './services/usageStore.js'; import { createPostgresSettlementStore } from './services/settlementStore.js'; import { createApiRegistry } from './data/apiRegistry.js'; import { ApiKey } from './types/gateway.js'; -import { config } from './config/index.js'; import { listingsCache } from './lib/listingsCache.js'; // Helper for Jest/CommonJS compat @@ -47,6 +49,14 @@ export { createGracefulShutdownHandler, createInFlightDrainTracker, type Drainab export const app = express(); +app.use(requestIdMiddleware); +app.use( + createAccessLogMiddleware({ + sampleRate: config.accessLog.sampleRate, + redactFields: config.accessLog.redactFields, + }), +); + // Standard JSON middleware for non-webhook routes app.use((req, res, next) => { if (req.path === '/api/webhooks') { diff --git a/src/middleware/accessLog.test.ts b/src/middleware/accessLog.test.ts new file mode 100644 index 0000000..9bd7273 --- /dev/null +++ b/src/middleware/accessLog.test.ts @@ -0,0 +1,149 @@ +import { EventEmitter } from 'node:events'; +import type { Request, Response } from 'express'; + +import { logger } from './logging.js'; +import { createAccessLogMiddleware, ACCESS_LOG_REDACTED_VALUE } from './accessLog.js'; + +describe('createAccessLogMiddleware', () => { + test('logs structured JSON with correlation id and byte counts', () => { + const infoSpy = jest.spyOn(logger, 'info').mockImplementation(() => logger); + const middleware = createAccessLogMiddleware({ random: () => 0 }); + + try { + const req = Object.assign(new EventEmitter(), { + method: 'POST', + path: '/api/vault/deposit/prepare', + headers: { 'x-request-id': 'req-access-1' }, + id: 'req-access-1', + }) as unknown as EventEmitter & + Request & { + headers: Record; + id?: string; + }; + + const res = Object.assign(new EventEmitter(), { + statusCode: 201, + writableEnded: true, + setHeader: jest.fn(), + write: jest.fn(() => true), + end: jest.fn(() => true), + }) as unknown as EventEmitter & + Response & { + statusCode: number; + write: jest.Mock; + end: jest.Mock; + setHeader: jest.Mock; + writableEnded: boolean; + }; + + middleware(req, res, jest.fn()); + req.emit('data', Buffer.from('hello')); + req.emit('data', Buffer.from(' world')); + res.write('abc'); + res.end(Buffer.from('def')); + res.emit('finish'); + + expect(infoSpy).toHaveBeenCalledTimes(1); + expect(infoSpy.mock.calls[0][0]).toEqual( + expect.objectContaining({ + correlationId: 'req-access-1', + requestId: 'req-access-1', + method: 'POST', + path: '/api/vault/deposit/prepare', + status: 201, + statusCode: 201, + ms: expect.any(Number), + durationMs: expect.any(Number), + requestBytes: 11, + responseBytes: 6, + }), + ); + } finally { + infoSpy.mockRestore(); + } + }); + + test('redacts configured access-log fields and supports sampling', () => { + const infoSpy = jest.spyOn(logger, 'info').mockImplementation(() => logger); + const middleware = createAccessLogMiddleware({ + redactFields: ['path', 'correlationId'], + sampleRate: 1, + random: () => 0.99, + }); + + try { + const req = Object.assign(new EventEmitter(), { + method: 'GET', + path: '/api/secret', + headers: {}, + id: 'req-redacted', + }) as unknown as EventEmitter & + Request & { + headers: Record; + id?: string; + }; + + const res = Object.assign(new EventEmitter(), { + statusCode: 200, + writableEnded: true, + write: jest.fn(() => true), + end: jest.fn(() => true), + }) as unknown as EventEmitter & + Response & { + statusCode: number; + write: jest.Mock; + end: jest.Mock; + writableEnded: boolean; + }; + + middleware(req, res, jest.fn()); + res.end(); + res.emit('finish'); + + expect(infoSpy).toHaveBeenCalledTimes(1); + expect(infoSpy.mock.calls[0][0]).toEqual( + expect.objectContaining({ + correlationId: ACCESS_LOG_REDACTED_VALUE, + path: ACCESS_LOG_REDACTED_VALUE, + }), + ); + } finally { + infoSpy.mockRestore(); + } + }); + + test('skips logging when sample rate is zero', () => { + const infoSpy = jest.spyOn(logger, 'info').mockImplementation(() => logger); + const middleware = createAccessLogMiddleware({ sampleRate: 0, random: () => 0 }); + + try { + const req = Object.assign(new EventEmitter(), { + method: 'GET', + path: '/api/health', + headers: {}, + id: 'req-sampled-out', + }) as unknown as EventEmitter & Request & { id?: string }; + + const res = Object.assign(new EventEmitter(), { + statusCode: 200, + writableEnded: true, + write: jest.fn(() => true), + end: jest.fn(() => true), + }) as unknown as EventEmitter & + Response & { + statusCode: number; + write: jest.Mock; + end: jest.Mock; + writableEnded: boolean; + }; + + middleware(req, res, jest.fn()); + res.end(); + res.emit('finish'); + + expect(infoSpy).not.toHaveBeenCalled(); + } finally { + infoSpy.mockRestore(); + } + }); +}); diff --git a/src/middleware/accessLog.ts b/src/middleware/accessLog.ts new file mode 100644 index 0000000..579029f --- /dev/null +++ b/src/middleware/accessLog.ts @@ -0,0 +1,232 @@ +import type { NextFunction, Request, Response } from 'express'; +import { v4 as uuidv4 } from 'uuid'; +import { getClientIp } from '../lib/clientIp.js'; +import { getRequestId } from '../utils/asyncContext.js'; +import { logger } from './logging.js'; +import { sanitizeRequestId } from './requestId.js'; + +export const ACCESS_LOG_REDACTED_VALUE = '[REDACTED]'; +export const DEFAULT_ACCESS_LOG_SAMPLE_RATE = 1; + +export type AccessLogField = + | 'method' + | 'path' + | 'status' + | 'statusCode' + | 'ms' + | 'durationMs' + | 'requestBytes' + | 'responseBytes' + | 'correlationId' + | 'requestId' + | 'clientIp'; + +export interface AccessLogOptions { + sampleRate?: number; + redactFields?: readonly string[]; + random?: () => number; + logger?: Pick; +} + +type AccessLogPayload = { + correlationId: string; + requestId: string; + method: string; + path: string; + status: number; + statusCode: number; + ms: number; + durationMs: number; + requestBytes: number; + responseBytes: number; + clientIp?: string; +}; + +const REDACTABLE_FIELD_LOOKUP = new Map( + [ + 'method', + 'path', + 'status', + 'statusCode', + 'ms', + 'durationMs', + 'requestBytes', + 'responseBytes', + 'correlationId', + 'requestId', + 'clientIp', + ].map((field) => [field.toLowerCase(), field as AccessLogField]), +); + +const TRUST_PROXY = process.env.TRUST_PROXY_HEADERS === 'true'; + +const byteLength = (chunk: unknown, encoding?: BufferEncoding): number => { + if (chunk === null || chunk === undefined) { + return 0; + } + if (Buffer.isBuffer(chunk)) { + return chunk.length; + } + if (typeof chunk === 'string') { + return Buffer.byteLength(chunk, encoding); + } + return Buffer.byteLength(String(chunk)); +}; + +const normalizeField = (field: string): AccessLogField | undefined => { + const candidate = field.trim(); + if (!candidate) return undefined; + const lower = candidate.toLowerCase(); + return REDACTABLE_FIELD_LOOKUP.get(lower); +}; + +const redactPayload = ( + payload: AccessLogPayload, + redactFields: readonly AccessLogField[] | undefined, +): AccessLogPayload => { + if (!redactFields?.length) { + return payload; + } + + const redacted = { ...payload }; + for (const field of redactFields) { + if (field in redacted) { + (redacted as Record)[field] = ACCESS_LOG_REDACTED_VALUE; + } + } + return redacted; +}; + +const shouldSample = (sampleRate: number, random: () => number): boolean => { + if (sampleRate <= 0) return false; + if (sampleRate >= 1) return true; + return random() < sampleRate; +}; + +/** + * Structured HTTP access logging middleware. + * + * Mount this before request body parsing so request byte counts can be + * observed without buffering or re-reading the stream. + */ +export function createAccessLogMiddleware(options: AccessLogOptions = {}) { + const sampleRate = options.sampleRate ?? DEFAULT_ACCESS_LOG_SAMPLE_RATE; + const redactFields = options.redactFields?.map((field) => normalizeField(field)).filter( + (field): field is AccessLogField => Boolean(field), + ); + const random = options.random ?? Math.random; + const accessLogger = options.logger ?? logger; + + return function accessLogMiddleware(req: Request, res: Response, next: NextFunction): void { + const startAt = process.hrtime.bigint(); + const requestHeaders = req.headers ?? {}; + const requestId = + sanitizeRequestId(req.id) ?? + getRequestId() ?? + sanitizeRequestId( + Array.isArray(requestHeaders['x-request-id']) + ? requestHeaders['x-request-id'][0] + : requestHeaders['x-request-id'], + ) ?? + uuidv4(); + + if (typeof res.setHeader === 'function') { + res.setHeader('x-request-id', requestId); + } + + const clientIp = getClientIp(req, TRUST_PROXY); + const requestHeaderLengthRaw = + typeof req.header === 'function' + ? req.header('content-length') + : Array.isArray(requestHeaders['content-length']) + ? requestHeaders['content-length'][0] + : requestHeaders['content-length']; + const requestHeaderLength = Number(requestHeaderLengthRaw); + let requestBytes = 0; + let sawRequestData = false; + let responseBytes = 0; + let emitted = false; + + const onData = (chunk: Buffer | string): void => { + sawRequestData = true; + requestBytes += byteLength(chunk); + }; + + if (typeof req.on === 'function') { + req.on('data', onData); + } + + const originalWrite = typeof res.write === 'function' ? res.write.bind(res) : undefined; + const originalEnd = typeof res.end === 'function' ? res.end.bind(res) : undefined; + + if (originalWrite) { + res.write = ((chunk: unknown, encoding?: unknown, callback?: unknown) => { + responseBytes += byteLength(chunk, typeof encoding === 'string' ? encoding as BufferEncoding : undefined); + return originalWrite(chunk as never, encoding as never, callback as never); + }) as typeof res.write; + } + + if (originalEnd) { + res.end = ((chunk?: unknown, encoding?: unknown, callback?: unknown) => { + responseBytes += byteLength(chunk, typeof encoding === 'string' ? encoding as BufferEncoding : undefined); + return originalEnd(chunk as never, encoding as never, callback as never); + }) as typeof res.end; + } + + const emitLog = (): void => { + if (emitted) { + return; + } + emitted = true; + if (typeof req.off === 'function') { + req.off('data', onData); + } else if (typeof req.removeListener === 'function') { + req.removeListener('data', onData); + } + + if (!sawRequestData && Number.isFinite(requestHeaderLength) && requestHeaderLength >= 0) { + requestBytes = requestHeaderLength; + } + + if (!shouldSample(sampleRate, random)) { + return; + } + + const elapsedMs = Number(process.hrtime.bigint() - startAt) / 1_000_000; + const status = res.statusCode; + const payload: AccessLogPayload = { + correlationId: requestId, + requestId, + method: req.method, + path: req.path, + status, + statusCode: status, + ms: Number(elapsedMs.toFixed(3)), + durationMs: Number(elapsedMs.toFixed(3)), + requestBytes, + responseBytes, + ...(clientIp ? { clientIp } : {}), + }; + + const logPayload = redactPayload(payload, redactFields); + if (status >= 500 && typeof accessLogger.error === 'function') { + accessLogger.error(logPayload, 'request completed'); + } else if (status >= 400 && typeof accessLogger.warn === 'function') { + accessLogger.warn(logPayload, 'request completed'); + } else { + accessLogger.info(logPayload, 'request completed'); + } + }; + + res.once('finish', emitLog); + res.once('close', () => { + if (!res.writableEnded) { + emitLog(); + } + }); + + next(); + }; +} + +export const requestLogger = createAccessLogMiddleware(); diff --git a/src/middleware/logging.test.ts b/src/middleware/logging.test.ts index b402942..e6a5ec9 100644 --- a/src/middleware/logging.test.ts +++ b/src/middleware/logging.test.ts @@ -2,7 +2,8 @@ import { EventEmitter } from 'node:events'; import type { Request, Response } from 'express'; import { REDACTED_LOG_VALUE } from '../logger.js'; -import { logger, requestLogger, structuredLoggerOptions } from './logging.js'; +import { logger, structuredLoggerOptions } from './logging.js'; +import { requestLogger } from './accessLog.js'; describe('structured logger options', () => { test('redaction hook masks sensitive structured fields before logging', () => { @@ -95,10 +96,15 @@ describe('requestLogger', () => { const [payload, message] = infoSpy.mock.calls[0] as [Record, string]; expect(message).toBe('request completed'); expect(payload.requestId).toBe('req-safe-1'); + expect(payload.correlationId).toBe('req-safe-1'); expect(payload.method).toBe('POST'); expect(payload.path).toBe('/api/vault/deposit/prepare'); + expect(payload.status).toBe(200); expect(payload.statusCode).toBe(200); + expect(typeof payload.ms).toBe('number'); expect(typeof payload.durationMs).toBe('number'); + expect(payload.requestBytes).toBe(0); + expect(payload.responseBytes).toBe(0); expect('headers' in payload).toBe(false); expect('body' in payload).toBe(false); } finally { @@ -130,6 +136,7 @@ describe('requestLogger', () => { const [payload] = infoSpy.mock.calls[0] as [Record, string]; expect(payload.requestId).toBe('req-from-id-property'); + expect(payload.correlationId).toBe('req-from-id-property'); expect(res.setHeader).toHaveBeenCalledWith('x-request-id', 'req-from-id-property'); } finally { infoSpy.mockRestore(); @@ -160,6 +167,7 @@ describe('requestLogger', () => { expect(errorSpy).toHaveBeenCalledTimes(1); const [payload, message] = errorSpy.mock.calls[0] as [Record, string]; expect(message).toBe('request completed'); + expect(payload.status).toBe(503); expect(payload.statusCode).toBe(503); } finally { errorSpy.mockRestore(); diff --git a/src/middleware/logging.ts b/src/middleware/logging.ts index 970bcaa..11a404a 100644 --- a/src/middleware/logging.ts +++ b/src/middleware/logging.ts @@ -1,8 +1,5 @@ -import type { Request, Response, NextFunction } from 'express'; import pino from 'pino'; -import { v4 as uuidv4 } from 'uuid'; import { PINO_REDACT_PATHS, REDACTED_LOG_VALUE, redactLogArguments } from '../logger.js'; -import { getClientIp } from '../lib/clientIp.js'; import { getRequestId } from '../utils/asyncContext.js'; const isProduction = process.env.NODE_ENV === 'production'; @@ -64,50 +61,3 @@ export const structuredLoggerOptions: Parameters[0] = { }; export const logger = pino(structuredLoggerOptions); - -const TRUST_PROXY = process.env.TRUST_PROXY_HEADERS === 'true'; - -export function requestLogger(req: Request, res: Response, next: NextFunction): void { - // Prefer the sanitized ID already set by requestIdMiddleware (req.id). - // Fall back to the raw header value for contexts where requestIdMiddleware - // hasn't run (e.g. isolated unit tests), and finally generate a UUID. - const requestId = req.id || getRequestId() || - (Array.isArray(req.headers['x-request-id']) - ? req.headers['x-request-id'][0] - : req.headers['x-request-id']) || - uuidv4(); - - res.setHeader('x-request-id', requestId); - - // Resolve client IP once, before the response finishes, using the same - // proxy-aware logic as the IP-allowlist middleware (shared via clientIp.ts). - // When TRUST_PROXY_HEADERS=true the leftmost entry of x-forwarded-for is - // used; otherwise the direct socket address is used to prevent spoofing. - const clientIp = getClientIp(req, TRUST_PROXY); - - const startAt = process.hrtime.bigint(); - - res.on('finish', () => { - const durationMs = Number(process.hrtime.bigint() - startAt) / 1_000_000; - const statusCode = res.statusCode; - - const logPayload = { - requestId, - method: req.method, - path: req.path, - statusCode, - durationMs: Number(durationMs.toFixed(3)), - clientIp, - }; - - if (statusCode >= 500) { - logger.error(logPayload, 'request completed'); - } else if (statusCode >= 400) { - logger.warn(logPayload, 'request completed'); - } else { - logger.info(logPayload, 'request completed'); - } - }); - - next(); -}