From f9993561bfa09bf42343612cddd1116dde2effed Mon Sep 17 00:00:00 2001 From: Banx17 Date: Fri, 1 May 2026 17:31:51 +0100 Subject: [PATCH] test(observability): requestId propagation --- src/middleware/logging.ts | 15 +- src/middleware/requestId.test.ts | 107 +++++--------- src/middleware/requestId.ts | 17 ++- .../integration/requestIdPropagation.test.ts | 138 ++++++++++++++++++ 4 files changed, 186 insertions(+), 91 deletions(-) create mode 100644 tests/integration/requestIdPropagation.test.ts diff --git a/src/middleware/logging.ts b/src/middleware/logging.ts index 832e87d..063c4fb 100644 --- a/src/middleware/logging.ts +++ b/src/middleware/logging.ts @@ -41,16 +41,11 @@ 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 reqWithId = req as Request & { id?: string }; - const requestId = - req.id || - (Array.isArray(req.headers['x-request-id']) - ? req.headers['x-request-id'][0] - : req.headers['x-request-id']) || - uuidv4(); + // Prefer the safely generated ID already set by requestIdMiddleware (req.id). + // Fall back to generating a new UUID for contexts where requestIdMiddleware + // hasn't run (e.g., isolated unit tests). We strictly avoid reading the raw + // x-request-id header here to prevent unsanitized IDs or PII from entering logs. + const requestId = req.id || uuidv4(); res.setHeader('x-request-id', requestId); diff --git a/src/middleware/requestId.test.ts b/src/middleware/requestId.test.ts index 6b697ec..261f380 100644 --- a/src/middleware/requestId.test.ts +++ b/src/middleware/requestId.test.ts @@ -3,21 +3,23 @@ import type { Request, Response, NextFunction } from 'express'; import { getRequestId } from '../logger.js'; import { requestIdMiddleware, sanitizeRequestId, REQUEST_ID_MAX_LENGTH } from './requestId.js'; +const VALID_UUID = '123e4567-e89b-12d3-a456-426614174000'; + describe('sanitizeRequestId', () => { - test('returns the value unchanged for a normal id', () => { - assert.equal(sanitizeRequestId('trace-abc-123'), 'trace-abc-123'); + test('returns the value unchanged for a valid UUID', () => { + assert.equal(sanitizeRequestId(VALID_UUID), VALID_UUID); }); - test('trims surrounding whitespace', () => { - assert.equal(sanitizeRequestId(' test-trim-id '), 'test-trim-id'); + test('trims surrounding whitespace and accepts valid UUID', () => { + assert.equal(sanitizeRequestId(` ${VALID_UUID} `), VALID_UUID); }); - test('strips CR and LF to prevent header injection', () => { - assert.equal(sanitizeRequestId('id\r\nX-Evil: injected'), 'idX-Evil: injected'); + test('returns undefined for non-UUID string', () => { + assert.equal(sanitizeRequestId('trace-abc-123'), undefined); }); - test('strips all ASCII control characters', () => { - assert.equal(sanitizeRequestId('id\x00\x01\x1F\x7F'), 'id'); + test('returns undefined for UUID with injected malicious characters', () => { + assert.equal(sanitizeRequestId(`${VALID_UUID}\r\nX-Evil: injected`), undefined); }); test('returns undefined for empty string', () => { @@ -33,39 +35,34 @@ describe('sanitizeRequestId', () => { }); test('returns undefined when value exceeds REQUEST_ID_MAX_LENGTH', () => { - const oversized = 'a'.repeat(REQUEST_ID_MAX_LENGTH + 1); + const oversized = VALID_UUID + 'a'; assert.equal(sanitizeRequestId(oversized), undefined); }); - - test('accepts value exactly at REQUEST_ID_MAX_LENGTH', () => { - const maxLen = 'a'.repeat(REQUEST_ID_MAX_LENGTH); - assert.equal(sanitizeRequestId(maxLen), maxLen); - }); }); describe('requestId middleware', () => { - test('uses incoming x-request-id header as request id and response header', (done) => { + test('uses incoming x-request-id header if it is a valid UUID', (done) => { const req = { - header: (name: string) => (name.toLowerCase() === 'x-request-id' ? 'test-id-123' : undefined), + header: (name: string) => (name.toLowerCase() === 'x-request-id' ? VALID_UUID : undefined), } as unknown as Request; const res = { setHeader: (name: string, value: string) => { assert.equal(name, 'X-Request-Id'); - assert.equal(value, 'test-id-123'); + assert.equal(value, VALID_UUID); }, } as unknown as Response; const next = (() => { - assert.equal((req as any).id, 'test-id-123'); - assert.equal(getRequestId(), 'test-id-123'); + assert.equal((req as any).id, VALID_UUID); + assert.equal(getRequestId(), VALID_UUID); done(); }) as NextFunction; requestIdMiddleware(req, res, next); }); - test('generates a UUID request id when header is absent and sets it on response', (done) => { + test('generates a new UUID request id when header is absent', (done) => { const req = { header: () => undefined, } as unknown as Request; @@ -83,7 +80,7 @@ describe('requestId middleware', () => { assert.ok(setHeaderValue, 'response X-Request-Id must be set'); assert.equal((req as any).id, setHeaderValue); - const uuidRegex = /^[0-9a-f]{8}-[0-9a-f]{4}-4[0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i; + const uuidRegex = /^[0-9a-f]{8}-[0-9a-f]{4}-[1-5][0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i; assert.match(setHeaderValue ?? '', uuidRegex); assert.match((req as any).id, uuidRegex); assert.equal(getRequestId(), (req as any).id); @@ -94,82 +91,46 @@ describe('requestId middleware', () => { requestIdMiddleware(req, res, next); }); - test('strips whitespace from x-request-id header before using it', (done) => { + test('generates a new UUID when header is not a valid UUID (e.g. contains PII)', (done) => { const req = { - header: (name: string) => (name.toLowerCase() === 'x-request-id' ? ' test-trim-id ' : undefined), + header: (name: string) => (name.toLowerCase() === 'x-request-id' ? 'john.doe@example.com' : undefined), } as unknown as Request; + let setHeaderValue: string | undefined; + const res = { setHeader: (_name: string, value: string) => { - assert.equal(value, 'test-trim-id'); + setHeaderValue = value; }, } as unknown as Response; const next = (() => { - assert.equal((req as any).id, 'test-trim-id'); - done(); - }) as NextFunction; - - requestIdMiddleware(req, res, next); - }); - - test('generates a UUID when header contains only control characters', (done) => { - const req = { - header: (name: string) => (name.toLowerCase() === 'x-request-id' ? '\r\n\x00' : undefined), - } as unknown as Request; - - let setHeaderValue: string | undefined; - const res = { - setHeader: (_name: string, value: string) => { setHeaderValue = value; }, - } as unknown as Response; - - const next = (() => { - const uuidRegex = /^[0-9a-f]{8}-[0-9a-f]{4}-4[0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i; - assert.match(setHeaderValue ?? '', uuidRegex); - done(); - }) as NextFunction; - - requestIdMiddleware(req, res, next); - }); - - test('generates a UUID when header value exceeds max length', (done) => { - const oversized = 'x'.repeat(REQUEST_ID_MAX_LENGTH + 1); - const req = { - header: (name: string) => (name.toLowerCase() === 'x-request-id' ? oversized : undefined), - } as unknown as Request; + assert.notEqual(setHeaderValue, 'john.doe@example.com'); + assert.notEqual((req as any).id, 'john.doe@example.com'); - let setHeaderValue: string | undefined; - const res = { - setHeader: (_name: string, value: string) => { setHeaderValue = value; }, - } as unknown as Response; - - const next = (() => { - // Must not echo the oversized value back - assert.notEqual(setHeaderValue, oversized); - const uuidRegex = /^[0-9a-f]{8}-[0-9a-f]{4}-4[0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i; + const uuidRegex = /^[0-9a-f]{8}-[0-9a-f]{4}-[1-5][0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i; assert.match(setHeaderValue ?? '', uuidRegex); + assert.match((req as any).id, uuidRegex); + done(); }) as NextFunction; requestIdMiddleware(req, res, next); }); - test('strips CRLF injection attempt and uses sanitized value', (done) => { - // After stripping control chars the remaining value is non-empty, so it should be used. + test('strips whitespace from valid UUID before using it', (done) => { const req = { - header: (name: string) => - name.toLowerCase() === 'x-request-id' ? 'safe-id\r\nX-Evil: injected' : undefined, + header: (name: string) => (name.toLowerCase() === 'x-request-id' ? ` ${VALID_UUID} ` : undefined), } as unknown as Request; - let setHeaderValue: string | undefined; const res = { - setHeader: (_name: string, value: string) => { setHeaderValue = value; }, + setHeader: (_name: string, value: string) => { + assert.equal(value, VALID_UUID); + }, } as unknown as Response; const next = (() => { - assert.equal(setHeaderValue, 'safe-idX-Evil: injected'); - assert.ok(!setHeaderValue?.includes('\r')); - assert.ok(!setHeaderValue?.includes('\n')); + assert.equal((req as any).id, VALID_UUID); done(); }) as NextFunction; diff --git a/src/middleware/requestId.ts b/src/middleware/requestId.ts index c84870f..c0654bd 100644 --- a/src/middleware/requestId.ts +++ b/src/middleware/requestId.ts @@ -6,21 +6,22 @@ const REQUEST_ID_HEADER = 'x-request-id'; /** * Maximum byte length accepted for a client-supplied X-Request-Id value. - * Anything longer is discarded and a fresh UUID is generated instead. - * 128 chars comfortably covers UUID v4 (36), ULID (26), and common trace-id formats. + * We restrict this to 36 characters to strictly allow only UUIDs. */ -export const REQUEST_ID_MAX_LENGTH = 128; +export const REQUEST_ID_MAX_LENGTH = 36; + +const UUID_REGEX = /^[0-9a-f]{8}-[0-9a-f]{4}-[1-5][0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i; /** * Sanitise a raw header value so it is safe to echo back in a response header. - * - Strips ASCII control characters (including CR/LF) to prevent header injection. - * - Trims surrounding whitespace. - * - Returns undefined when the result is empty or exceeds REQUEST_ID_MAX_LENGTH. + * - Only accepts valid UUID strings. + * - Trims surrounding whitespace before validation. + * - Returns undefined when the result is not a valid UUID. */ export const sanitizeRequestId = (raw: string | undefined): string | undefined => { if (!raw) return undefined; - const sanitized = raw.replace(/[\x00-\x1F\x7F]/g, '').trim(); - if (!sanitized.length || sanitized.length > REQUEST_ID_MAX_LENGTH) return undefined; + const sanitized = raw.trim(); + if (!UUID_REGEX.test(sanitized)) return undefined; return sanitized; }; diff --git a/tests/integration/requestIdPropagation.test.ts b/tests/integration/requestIdPropagation.test.ts new file mode 100644 index 0000000..a4414bf --- /dev/null +++ b/tests/integration/requestIdPropagation.test.ts @@ -0,0 +1,138 @@ +import express from 'express'; +import request from 'supertest'; +import { requestIdMiddleware } from '../../src/middleware/requestId.js'; +import { requestLogger, logger as pinoLogger } from '../../src/middleware/logging.js'; +import { errorHandler } from '../../src/middleware/errorHandler.js'; +import { BadRequestError } from '../../src/errors/index.js'; +import { logger as customLogger } from '../../src/logger.js'; + +describe('Request ID Propagation', () => { + let app: express.Application; + + beforeEach(() => { + jest.clearAllMocks(); + jest.restoreAllMocks(); + + jest.spyOn(pinoLogger, 'info').mockImplementation(() => undefined as any); + jest.spyOn(pinoLogger, 'warn').mockImplementation(() => undefined as any); + jest.spyOn(pinoLogger, 'error').mockImplementation(() => undefined as any); + + jest.spyOn(customLogger, 'error').mockImplementation(() => undefined as any); + + app = express(); + app.use(requestIdMiddleware); + app.use(requestLogger); + + app.get('/success', (req, res) => { + res.json({ status: 'ok' }); + }); + + app.get('/error', (req, res, next) => { + next(new BadRequestError('Test bad request')); + }); + + app.use(errorHandler); + }); + + afterEach(() => { + jest.restoreAllMocks(); + }); + + it('should propagate a valid generated UUID to the response header and logger for successful requests', async () => { + const response = await request(app).get('/success'); + + expect(response.status).toBe(200); + const requestId = response.headers['x-request-id']; + expect(requestId).toBeDefined(); + + const uuidRegex = /^[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(requestId).toMatch(uuidRegex); + + await new Promise(resolve => setTimeout(resolve, 50)); + + expect(pinoLogger.info).toHaveBeenCalledWith( + expect.objectContaining({ + requestId: requestId, + statusCode: 200, + path: '/success' + }), + 'request completed' + ); + }); + + it('should propagate the exact same UUID to error response body and error logger', async () => { + const response = await request(app).get('/error'); + + expect(response.status).toBe(400); + const headerRequestId = response.headers['x-request-id']; + const bodyRequestId = response.body.requestId; + + expect(headerRequestId).toBeDefined(); + expect(bodyRequestId).toBeDefined(); + expect(headerRequestId).toBe(bodyRequestId); + + expect(customLogger.error).toHaveBeenCalledWith( + '[errorHandler]', + expect.objectContaining({ + requestId: headerRequestId, + statusCode: 400 + }) + ); + + await new Promise(resolve => setTimeout(resolve, 50)); + + expect(pinoLogger.warn).toHaveBeenCalledWith( + expect.objectContaining({ + requestId: headerRequestId, + statusCode: 400, + path: '/error' + }), + 'request completed' + ); + }); + + it('should use provided valid UUID and propagate it', async () => { + const validUuid = '123e4567-e89b-12d3-a456-426614174000'; + const response = await request(app) + .get('/success') + .set('X-Request-Id', validUuid); + + expect(response.status).toBe(200); + expect(response.headers['x-request-id']).toBe(validUuid); + + await new Promise(resolve => setTimeout(resolve, 50)); + + expect(pinoLogger.info).toHaveBeenCalledWith( + expect.objectContaining({ + requestId: validUuid + }), + 'request completed' + ); + }); + + it('should reject invalid X-Request-Id (e.g. PII) and generate a new UUID', async () => { + const invalidId = 'john.doe@example.com'; + const response = await request(app) + .get('/error') + .set('X-Request-Id', invalidId); + + expect(response.status).toBe(400); + const headerRequestId = response.headers['x-request-id']; + + expect(headerRequestId).toBeDefined(); + expect(headerRequestId).not.toBe(invalidId); + + const uuidRegex = /^[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(headerRequestId).toMatch(uuidRegex); + expect(response.body.requestId).toBe(headerRequestId); + + await new Promise(resolve => setTimeout(resolve, 50)); + + expect(customLogger.error).toHaveBeenCalledWith( + '[errorHandler]', + expect.objectContaining({ + requestId: headerRequestId + }) + ); + }); +});