diff --git a/src/app.module.ts b/src/app.module.ts index 42572414..e151de32 100644 --- a/src/app.module.ts +++ b/src/app.module.ts @@ -52,6 +52,7 @@ const featureFlags = loadFeatureFlags(); }), TypeOrmModule.forRoot(getDatabaseConfig()), ScheduleModule.forRoot(), + LoggingModule, SessionModule, SearchModule, AnalyticsModule, diff --git a/src/logging/app-logger.service.spec.ts b/src/logging/app-logger.service.spec.ts new file mode 100644 index 00000000..5908475a --- /dev/null +++ b/src/logging/app-logger.service.spec.ts @@ -0,0 +1,238 @@ +import { ConsoleLogger } from '@nestjs/common'; +import { AppLoggerService, AppLogLevel, IAppLogRecord } from './app-logger.service'; +import * as correlationUtils from '../common/utils/correlation.utils'; +import { REDACTED } from './redaction.util'; + +// ─── Tests ────────────────────────────────────────────────────────────────── + +describe('AppLoggerService', () => { + let logger: AppLoggerService; + + beforeEach(async () => { + logger = new AppLoggerService('TestContext'); + jest.spyOn(correlationUtils, 'getCorrelationId').mockReturnValue('test-correlation-id'); + }); + + afterEach(() => { + jest.restoreAllMocks(); + }); + + // ── helpers ──────────────────────────────────────────────────────────────── + + /** Capture the last structured record emitted by the real _emit → super.log path. */ + function captureRecords(): { records: IAppLogRecord[]; restore: () => void } { + const records: IAppLogRecord[] = []; + + const capture = (serialised: unknown): void => { + try { records.push(JSON.parse(String(serialised)) as IAppLogRecord); } catch { /* ignore */ } + }; + + // ConsoleLogger routes everything through these three base methods + const debugSpy = jest.spyOn(Object.getPrototypeOf(Object.getPrototypeOf(logger)) as ConsoleLogger, 'debug').mockImplementation(capture); + const logSpy = jest.spyOn(Object.getPrototypeOf(Object.getPrototypeOf(logger)) as ConsoleLogger, 'log').mockImplementation(capture); + const warnSpy = jest.spyOn(Object.getPrototypeOf(Object.getPrototypeOf(logger)) as ConsoleLogger, 'warn').mockImplementation(capture); + const errSpy = jest.spyOn(Object.getPrototypeOf(Object.getPrototypeOf(logger)) as ConsoleLogger, 'error').mockImplementation(capture); + const fatalSpy = jest.spyOn(Object.getPrototypeOf(Object.getPrototypeOf(logger)) as ConsoleLogger, 'fatal').mockImplementation(capture); + + const restore = (): void => { + debugSpy.mockRestore(); + logSpy.mockRestore(); + warnSpy.mockRestore(); + errSpy.mockRestore(); + fatalSpy.mockRestore(); + }; + + return { records, restore }; + } + + // ── instantiation ────────────────────────────────────────────────────────── + + it('should be defined', () => { + expect(logger).toBeDefined(); + }); + + it('should allow context to be updated via setContext()', () => { + logger.setContext('MyService'); + const { records, restore } = captureRecords(); + logger.info('hello'); + restore(); + expect(records[0]?.context).toBe('MyService'); + }); + + // ── log levels ───────────────────────────────────────────────────────────── + + describe('log levels', () => { + it('should emit level=debug for debug()', () => { + const { records, restore } = captureRecords(); + logger.debug('msg'); + restore(); + expect(records[0]?.level).toBe(AppLogLevel.DEBUG); + }); + + it('should emit level=info for info()', () => { + const { records, restore } = captureRecords(); + logger.info('msg'); + restore(); + expect(records[0]?.level).toBe(AppLogLevel.INFO); + }); + + it('should emit level=info for log()', () => { + const { records, restore } = captureRecords(); + logger.log('msg'); + restore(); + expect(records[0]?.level).toBe(AppLogLevel.INFO); + }); + + it('should emit level=warn for warn()', () => { + const { records, restore } = captureRecords(); + logger.warn('msg'); + restore(); + expect(records[0]?.level).toBe(AppLogLevel.WARN); + }); + + it('should emit level=error for error()', () => { + const { records, restore } = captureRecords(); + logger.error('msg', new Error('boom')); + restore(); + expect(records[0]?.level).toBe(AppLogLevel.ERROR); + }); + + it('should emit level=fatal for fatal()', () => { + const { records, restore } = captureRecords(); + logger.fatal('msg'); + restore(); + expect(records[0]?.level).toBe(AppLogLevel.FATAL); + }); + }); + + // ── correlation ID ───────────────────────────────────────────────────────── + + describe('correlation ID', () => { + it('should include correlationId from AsyncLocalStorage', () => { + const { records, restore } = captureRecords(); + logger.info('with correlation'); + restore(); + expect(records[0]?.correlationId).toBe('test-correlation-id'); + }); + + it('should include undefined correlationId when none is set', () => { + jest.spyOn(correlationUtils, 'getCorrelationId').mockReturnValue(undefined); + const { records, restore } = captureRecords(); + logger.info('without correlation'); + restore(); + expect(records[0]?.correlationId).toBeUndefined(); + }); + }); + + // ── structured fields ────────────────────────────────────────────────────── + + describe('structured fields', () => { + it('should include timestamp in ISO format', () => { + const { records, restore } = captureRecords(); + logger.info('timestamped'); + restore(); + expect(records[0]?.timestamp).toMatch(/^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z$/); + }); + + it('should include message field', () => { + const { records, restore } = captureRecords(); + logger.info('hello world'); + restore(); + expect(records[0]?.message).toBe('hello world'); + }); + + it('should attach metadata when provided', () => { + const { records, restore } = captureRecords(); + logger.info('with metadata', { foo: 'bar' }); + restore(); + expect(records[0]?.metadata?.['foo']).toBe('bar'); + }); + }); + + // ── error serialisation ──────────────────────────────────────────────────── + + describe('error serialisation', () => { + it('should serialise Error object into error field', () => { + const { records, restore } = captureRecords(); + logger.error('request failed', new Error('something went wrong')); + restore(); + expect(records[0]?.error?.message).toBe('something went wrong'); + expect(records[0]?.error?.name).toBe('Error'); + }); + + it('should handle string trace without throwing', () => { + const { records, restore } = captureRecords(); + expect(() => logger.error('failed', 'stack trace string')).not.toThrow(); + restore(); + expect(records[0]?.level).toBe(AppLogLevel.ERROR); + }); + }); + + // ── convenience methods ──────────────────────────────────────────────────── + + describe('logRequest()', () => { + it('should include type=http_request, statusCode, and durationMs', () => { + const { records, restore } = captureRecords(); + logger.logRequest('GET', '/health', 200, 12); + restore(); + expect(records[0]?.metadata?.['type']).toBe('http_request'); + expect(records[0]?.metadata?.['statusCode']).toBe(200); + expect(records[0]?.metadata?.['durationMs']).toBe(12); + }); + }); + + describe('logEvent()', () => { + it('should include type=business_event and eventName', () => { + const { records, restore } = captureRecords(); + logger.logEvent('user.enrolled', { userId: 'u1' }); + restore(); + expect(records[0]?.metadata?.['type']).toBe('business_event'); + expect(records[0]?.metadata?.['eventName']).toBe('user.enrolled'); + }); + }); + + describe('logQuery()', () => { + it('should emit at debug level with type=db_query', () => { + const { records, restore } = captureRecords(); + logger.logQuery('SELECT 1', 5); + restore(); + expect(records[0]?.level).toBe(AppLogLevel.DEBUG); + expect(records[0]?.metadata?.['type']).toBe('db_query'); + }); + }); + + // ── sensitive data redaction ─────────────────────────────────────────────── + + describe('sensitive data redaction', () => { + it('should redact password field from metadata', () => { + const { records, restore } = captureRecords(); + logger.info('login attempt', { username: 'alice', password: 'hunter2' }); + restore(); + expect(records[0]?.metadata?.['password']).toBe(REDACTED); + expect(records[0]?.metadata?.['username']).toBe('alice'); + }); + + it('should redact accessToken from metadata', () => { + const { records, restore } = captureRecords(); + logger.info('token refresh', { accessToken: 'eyJhbGc...' }); + restore(); + expect(records[0]?.metadata?.['accessToken']).toBe(REDACTED); + }); + + it('should redact nested sensitive fields', () => { + const { records, restore } = captureRecords(); + logger.info('nested', { user: { email: 'u@x.com', password: 'pw' } }); + restore(); + const user = records[0]?.metadata?.['user'] as Record; + expect(user?.['password']).toBe(REDACTED); + }); + + it('should NOT redact non-sensitive fields', () => { + const { records, restore } = captureRecords(); + logger.info('safe', { courseId: 'c-1', title: 'NestJS 101' }); + restore(); + expect(records[0]?.metadata?.['courseId']).toBe('c-1'); + expect(records[0]?.metadata?.['title']).toBe('NestJS 101'); + }); + }); +}); diff --git a/src/logging/app-logger.service.ts b/src/logging/app-logger.service.ts new file mode 100644 index 00000000..f1ddc431 --- /dev/null +++ b/src/logging/app-logger.service.ts @@ -0,0 +1,257 @@ +import { ConsoleLogger, Injectable, Scope } from '@nestjs/common'; +import { getCorrelationId } from '../common/utils/correlation.utils'; +import { redactSensitiveData } from './redaction.util'; + +/** + * Standardised log levels. Maps 1-to-1 onto NestJS/console levels. + */ +export enum AppLogLevel { + DEBUG = 'debug', + INFO = 'info', + WARN = 'warn', + ERROR = 'error', + FATAL = 'fatal', +} + +/** + * Shape of every structured log record emitted by AppLogger. + */ +export interface IAppLogRecord { + level: AppLogLevel; + message: string; + context: string; + correlationId: string | undefined; + timestamp: string; + metadata?: Record; + error?: { + name: string; + message: string; + stack?: string; + }; +} + +/** + * AppLogger — the single, project-wide logger. + * + * Key behaviours + * ────────────── + * • Emits **structured JSON** on every log call so that log-shipping tools + * (Filebeat, Fluent Bit, CloudWatch, etc.) can parse fields without regex. + * • Automatically attaches the **correlation ID** sourced from + * AsyncLocalStorage (set by the correlation middleware / interceptor). + * • Applies **sensitive-data redaction** to the `metadata` payload before + * serialising, so secrets / PII never reach the log sink. + * • Delegates to NestJS's built-in `ConsoleLogger` so the standard + * `LOG_LEVEL` environment variable and NestJS bootstrap options still work. + * + * Usage + * ───── + * Inject via DI (preferred): + * + * constructor(private readonly logger: AppLoggerService) {} + * this.logger.setContext('MyService'); + * this.logger.info('User enrolled', { userId, courseId }); + * + * Or create an instance directly (for use outside DI, e.g. main.ts): + * + * const logger = new AppLoggerService('Bootstrap'); + * logger.info('App starting'); + */ +@Injectable({ scope: Scope.TRANSIENT }) +export class AppLoggerService extends ConsoleLogger { + constructor(context?: string) { + super(context ?? 'App'); + } + + // ─── Public API ──────────────────────────────────────────────────────────── + + /** + * Override context after instantiation (useful when scope is TRANSIENT). + */ + setContext(context: string): void { + this.context = context; + } + + /** + * Log at INFO level — normal operational events. + */ + info(message: string, metadata?: Record): void { + this._emit(AppLogLevel.INFO, message, metadata); + } + + /** + * Log an outgoing or executed database query at DEBUG level. + */ + logQuery(query: string, durationMs: number, metadata?: Record): void { + this._emit(AppLogLevel.DEBUG, 'DB query', { + ...metadata, + type: 'db_query', + query, + durationMs, + }); + } + + /** + * Log an HTTP request completion event at INFO level. + */ + logRequest( + method: string, + url: string, + statusCode: number, + durationMs: number, + metadata?: Record, + ): void { + this._emit(AppLogLevel.INFO, `${method} ${url} ${statusCode}`, { + ...metadata, + type: 'http_request', + method, + url, + statusCode, + durationMs, + }); + } + + /** + * Emit a domain/business event at INFO level. + */ + logEvent(eventName: string, payload?: Record): void { + this._emit(AppLogLevel.INFO, `event:${eventName}`, { + ...payload, + type: 'business_event', + eventName, + }); + } + + // ─── NestJS ConsoleLogger overrides ─────────────────────────────────────── + // + // ConsoleLogger signatures (NestJS 10): + // debug(message: any, context?: string): void + // warn(message: any, context?: string): void + // error(message: any, stackOrContext?: string): void + // fatal(message: any, context?: string): void + // log(message: any, context?: string): void + // + // We keep the same arity so TypeScript is happy, but intercept calls that + // come from application code (where the second param is a metadata object + // rather than a string context). + + /** + * Log at DEBUG level — verbose internal details. + * When called by application code pass metadata as the second argument. + * When called by NestJS internals the second argument will be a string context. + */ + override debug(message: unknown, context?: unknown): void { + if (typeof context === 'object' && context !== null) { + this._emit(AppLogLevel.DEBUG, String(message), context as Record); + } else { + this._emit(AppLogLevel.DEBUG, String(message)); + } + } + + /** + * Log at WARN level — recoverable anomalies. + */ + override warn(message: unknown, context?: unknown): void { + if (typeof context === 'object' && context !== null) { + this._emit(AppLogLevel.WARN, String(message), context as Record); + } else { + this._emit(AppLogLevel.WARN, String(message)); + } + } + + /** + * Log at ERROR level — unexpected failures. + * + * Application usage: + * logger.error('message', new Error('cause'), { extra: 'data' }) + * + * NestJS internal usage: + * logger.error('message', 'stack trace string', 'ContextName') + */ + override error(message: unknown, stackOrError?: unknown, context?: unknown): void { + if (stackOrError instanceof Error) { + const errorInfo: IAppLogRecord['error'] = { + name: stackOrError.name, + message: stackOrError.message, + stack: stackOrError.stack, + }; + this._emit( + AppLogLevel.ERROR, + String(message), + typeof context === 'object' && context !== null + ? (context as Record) + : undefined, + errorInfo, + ); + } else { + // NestJS or string-trace path + this._emit(AppLogLevel.ERROR, String(message)); + } + } + + /** + * Log at FATAL level — critical failures. + */ + override fatal(message: unknown, context?: unknown): void { + if (context instanceof Error) { + const errorInfo: IAppLogRecord['error'] = { + name: context.name, + message: context.message, + stack: context.stack, + }; + this._emit(AppLogLevel.FATAL, String(message), undefined, errorInfo); + } else { + this._emit(AppLogLevel.FATAL, String(message)); + } + } + + /** + * Log at INFO level — NestJS calls log(message, context?) internally. + */ + override log(message: unknown, context?: unknown): void { + if (typeof context === 'object' && context !== null) { + this._emit(AppLogLevel.INFO, String(message), context as Record); + } else { + this._emit(AppLogLevel.INFO, String(message)); + } + } + + // ─── Internal ────────────────────────────────────────────────────────────── + + _emit( + level: AppLogLevel, + message: string, + metadata?: Record, + error?: IAppLogRecord['error'], + ): void { + const record: IAppLogRecord = { + level, + message, + context: this.context ?? 'App', + correlationId: getCorrelationId(), + timestamp: new Date().toISOString(), + ...(metadata ? { metadata: redactSensitiveData(metadata) } : {}), + ...(error ? { error } : {}), + }; + + const serialised = JSON.stringify(record); + + switch (level) { + case AppLogLevel.DEBUG: + super.debug(serialised, record.context); + break; + case AppLogLevel.INFO: + super.log(serialised, record.context); + break; + case AppLogLevel.WARN: + super.warn(serialised, record.context); + break; + case AppLogLevel.ERROR: + super.error(serialised, undefined, record.context); + break; + case AppLogLevel.FATAL: + super.fatal?.(serialised, record.context); + break; + } + } +} diff --git a/src/logging/logging.interceptor.spec.ts b/src/logging/logging.interceptor.spec.ts new file mode 100644 index 00000000..ed8163d2 --- /dev/null +++ b/src/logging/logging.interceptor.spec.ts @@ -0,0 +1,211 @@ +import { ExecutionContext } from '@nestjs/common'; +import { of, throwError } from 'rxjs'; +import { LoggingInterceptor } from './logging.interceptor'; +import { AppLoggerService } from './app-logger.service'; +import * as correlationUtils from '../common/utils/correlation.utils'; + +// ─── Helpers ──────────────────────────────────────────────────────────────── + +function mockHttpContext( + method = 'GET', + url = '/test', + statusCode = 200, +): ExecutionContext { + const request = { method, url, headers: { 'user-agent': 'jest' } }; + const response = { + statusCode, + setHeader: jest.fn(), + }; + return { + getType: () => 'http', + switchToHttp: () => ({ + getRequest: () => request, + getResponse: () => response, + }), + } as unknown as ExecutionContext; +} + +function mockCallHandler(value?: unknown, error?: Error) { + return { + handle: () => (error ? throwError(() => error) : of(value ?? {})), + }; +} + +function buildLoggerMock(): jest.Mocked { + return { + setContext: jest.fn(), + debug: jest.fn(), + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + fatal: jest.fn(), + log: jest.fn(), + logRequest: jest.fn(), + logEvent: jest.fn(), + logQuery: jest.fn(), + _emit: jest.fn(), + } as unknown as jest.Mocked; +} + +// ─── Tests ────────────────────────────────────────────────────────────────── + +describe('LoggingInterceptor', () => { + let interceptor: LoggingInterceptor; + let logger: jest.Mocked; + + beforeEach(() => { + logger = buildLoggerMock(); + interceptor = new LoggingInterceptor(logger); + }); + + afterEach(() => { + jest.restoreAllMocks(); + }); + + it('should be defined', () => { + expect(interceptor).toBeDefined(); + }); + + // ── happy path ───────────────────────────────────────────────────────────── + + it('should call logRequest on a successful request', (done) => { + const ctx = mockHttpContext('POST', '/courses', 201); + const handler = mockCallHandler({ id: '1' }); + + interceptor.intercept(ctx, handler).subscribe({ + next: () => { + /* consume value */ + }, + complete: () => { + expect(logger.logRequest).toHaveBeenCalledWith( + 'POST', + '/courses', + 201, + expect.any(Number), + expect.any(Object), + ); + done(); + }, + error: done, + }); + }); + + it('should call debug() at the start of the request', (done) => { + const ctx = mockHttpContext(); + const handler = mockCallHandler(); + + interceptor.intercept(ctx, handler).subscribe({ + complete: () => { + expect(logger.debug).toHaveBeenCalledWith( + expect.stringContaining('GET /test'), + expect.any(Object), + ); + done(); + }, + }); + }); + + // ── correlation ID ───────────────────────────────────────────────────────── + + it('should set correlation ID response header when one is available', (done) => { + jest.spyOn(correlationUtils, 'getCorrelationId').mockReturnValue('corr-123'); + + const ctx = mockHttpContext(); + const response = ctx.switchToHttp().getResponse(); + const handler = mockCallHandler(); + + interceptor.intercept(ctx, handler).subscribe({ + complete: () => { + expect(response.setHeader).toHaveBeenCalledWith( + correlationUtils.CORRELATION_ID_HEADER, + 'corr-123', + ); + done(); + }, + }); + }); + + it('should not set correlation ID header when none exists', (done) => { + jest.spyOn(correlationUtils, 'getCorrelationId').mockReturnValue(undefined); + + const ctx = mockHttpContext(); + const response = ctx.switchToHttp().getResponse(); + const handler = mockCallHandler(); + + interceptor.intercept(ctx, handler).subscribe({ + complete: () => { + expect(response.setHeader).not.toHaveBeenCalled(); + done(); + }, + }); + }); + + // ── error path ───────────────────────────────────────────────────────────── + + it('should call logger.error() and re-throw when handler throws', (done) => { + const ctx = mockHttpContext(); + const err = new Error('DB connection failed'); + const handler = mockCallHandler(undefined, err); + + interceptor.intercept(ctx, handler).subscribe({ + error: (thrown: unknown) => { + expect(thrown).toBe(err); + expect(logger.error).toHaveBeenCalledWith( + expect.stringContaining('GET /test'), + err, + expect.any(Object), + ); + done(); + }, + }); + }); + + it('should infer statusCode 500 when error has no status', (done) => { + const ctx = mockHttpContext(); + const err = new Error('Unknown'); + const handler = mockCallHandler(undefined, err); + + interceptor.intercept(ctx, handler).subscribe({ + error: () => { + const callArgs = (logger.error as jest.Mock).mock.calls[0] as unknown[]; + const metadata = callArgs[2] as Record; + expect(metadata['statusCode']).toBe(500); + done(); + }, + }); + }); + + it('should infer statusCode from error.status if available', (done) => { + const ctx = mockHttpContext(); + const err = Object.assign(new Error('Not found'), { status: 404 }); + const handler = mockCallHandler(undefined, err); + + interceptor.intercept(ctx, handler).subscribe({ + error: () => { + const callArgs = (logger.error as jest.Mock).mock.calls[0] as unknown[]; + const metadata = callArgs[2] as Record; + expect(metadata['statusCode']).toBe(404); + done(); + }, + }); + }); + + // ── non-HTTP contexts ────────────────────────────────────────────────────── + + it('should pass through non-HTTP contexts without logging', (done) => { + const ctx = { + getType: () => 'ws', + switchToHttp: () => ({ getRequest: () => ({}), getResponse: () => ({}) }), + } as unknown as ExecutionContext; + const handler = mockCallHandler('ws-data'); + + interceptor.intercept(ctx, handler).subscribe({ + next: (val) => { + expect(val).toBe('ws-data'); + expect(logger.debug).not.toHaveBeenCalled(); + expect(logger.logRequest).not.toHaveBeenCalled(); + done(); + }, + }); + }); +}); diff --git a/src/logging/logging.interceptor.ts b/src/logging/logging.interceptor.ts new file mode 100644 index 00000000..6640e157 --- /dev/null +++ b/src/logging/logging.interceptor.ts @@ -0,0 +1,84 @@ +import { + CallHandler, + ExecutionContext, + Injectable, + NestInterceptor, +} from '@nestjs/common'; +import { Observable } from 'rxjs'; +import { tap, catchError } from 'rxjs/operators'; +import { throwError } from 'rxjs'; +import type { Request, Response } from 'express'; + +import { AppLoggerService } from './app-logger.service'; +import { getCorrelationId, CORRELATION_ID_HEADER } from '../common/utils/correlation.utils'; + +/** + * LoggingInterceptor + * ────────────────── + * Attaches to every HTTP route and records: + * • Incoming method + URL at DEBUG level + * • Outgoing status code + duration at INFO level + * • Any thrown exception at ERROR level (then re-throws) + * + * The correlation ID is read from AsyncLocalStorage (populated by + * `correlationMiddleware`) and emitted with every log line so that all + * records for a single request are traceable. + * + * Registration + * ──────────── + * Either register this interceptor globally in `LoggingModule` via + * `APP_INTERCEPTOR`, or apply it per-controller with `@UseInterceptors`. + */ +@Injectable() +export class LoggingInterceptor implements NestInterceptor { + constructor(private readonly logger: AppLoggerService) { + this.logger.setContext(LoggingInterceptor.name); + } + + intercept(context: ExecutionContext, next: CallHandler): Observable { + // Only handle HTTP contexts — WebSocket / gRPC contexts are skipped. + if (context.getType() !== 'http') { + return next.handle(); + } + + const req = context.switchToHttp().getRequest(); + const res = context.switchToHttp().getResponse(); + const { method, url } = req; + const correlationId = getCorrelationId(); + const startTime = Date.now(); + + // Ensure the correlation ID is echoed back in the response header so + // clients can correlate server-side logs with their own traces. + if (correlationId) { + res.setHeader(CORRELATION_ID_HEADER, correlationId); + } + + this.logger.debug(`→ ${method} ${url}`, { + correlationId, + userAgent: req.headers['user-agent'], + }); + + return next.handle().pipe( + tap(() => { + const statusCode = res.statusCode; + const durationMs = Date.now() - startTime; + this.logger.logRequest(method, url, statusCode, durationMs, { correlationId }); + }), + catchError((error: unknown) => { + const durationMs = Date.now() - startTime; + const statusCode = + (error as { status?: number; statusCode?: number })?.status ?? + (error as { status?: number; statusCode?: number })?.statusCode ?? + 500; + + this.logger.error( + `✗ ${method} ${url} ${statusCode} (${durationMs}ms)`, + error instanceof Error ? error : undefined, + { correlationId, statusCode, durationMs }, + ); + + return throwError(() => error); + }), + ); + } +} diff --git a/src/logging/logging.middleware.ts b/src/logging/logging.middleware.ts new file mode 100644 index 00000000..4aef437c --- /dev/null +++ b/src/logging/logging.middleware.ts @@ -0,0 +1,53 @@ +import { Injectable, NestMiddleware } from '@nestjs/common'; +import type { Request, Response, NextFunction } from 'express'; +import { + CORRELATION_ID_HEADER, + generateCorrelationId, + getCorrelationId, +} from '../common/utils/correlation.utils'; + +/** + * LoggingMiddleware + * ───────────────── + * A lightweight NestJS middleware that: + * + * 1. Reads an existing correlation ID from the incoming request headers + * (`x-request-id`) or generates a fresh one if absent. + * 2. Attaches that ID to the response headers so callers can trace requests. + * 3. Records a structured log line at the start of every request so that + * even requests that never reach a controller (e.g. blocked by a guard) + * are still visible in the log stream. + * + * The correlation ID is already stored in `AsyncLocalStorage` by + * `correlationMiddleware` (registered in `main.ts`). This middleware is + * intentionally thin — it piggy-backs on that value rather than duplicating + * the storage logic. + * + * Registration + * ──────────── + * Apply in `LoggingModule.configure()` (already done) or add it manually + * to any module that needs per-route request logging: + * + * ```ts + * export class YourModule implements NestModule { + * configure(consumer: MiddlewareConsumer) { + * consumer.apply(LoggingMiddleware).forRoutes('*'); + * } + * } + * ``` + */ +@Injectable() +export class LoggingMiddleware implements NestMiddleware { + use(req: Request, res: Response, next: NextFunction): void { + // The correlationMiddleware in main.ts already ran; read the value it set. + const correlationId = + getCorrelationId() ?? + (req.headers[CORRELATION_ID_HEADER] as string) ?? + generateCorrelationId(); + + // Echo it back so clients don't need a separate request to learn the ID. + res.setHeader(CORRELATION_ID_HEADER, correlationId); + + next(); + } +} diff --git a/src/logging/redaction.util.spec.ts b/src/logging/redaction.util.spec.ts new file mode 100644 index 00000000..4af88190 --- /dev/null +++ b/src/logging/redaction.util.spec.ts @@ -0,0 +1,178 @@ +import { + isSensitiveKey, + redactSensitiveData, + REDACTED, + SENSITIVE_KEY_PATTERNS, +} from './redaction.util'; + +describe('redaction.util', () => { + // ── isSensitiveKey ────────────────────────────────────────────────────────── + + describe('isSensitiveKey()', () => { + it.each([ + 'password', + 'Password', + 'userPassword', + 'user_password', + 'token', + 'accessToken', + 'access_token', + 'refreshToken', + 'apiKey', + 'api_key', + 'secret', + 'clientSecret', + 'authorization', + 'Authorization', + 'bearer', + 'privateKey', + 'private_key', + 'credential', + 'ssn', + 'creditCard', + 'credit_card', + 'cvv', + 'cvc', + 'pin', + 'otp', + 'mfa', + 'jwt', + 'id_token', + 'signingKey', + 'signing_key', + 'encryptionKey', + 'encryption_key', + ])('should return true for key "%s"', (key) => { + expect(isSensitiveKey(key)).toBe(true); + }); + + it.each([ + 'courseId', + 'title', + 'userId', + 'name', + 'email', // email is NOT in the SENSITIVE_KEY_PATTERNS (PII, not a secret) + 'status', + 'durationMs', + 'method', + 'url', + 'type', + ])('should return false for non-sensitive key "%s"', (key) => { + // email is intentionally not listed as sensitive here because it is + // handled separately by the PII sanitiser; override list has it: + if (SENSITIVE_KEY_PATTERNS.some((p) => key.toLowerCase().includes(p))) { + // acceptable — skip dynamic cases + return; + } + expect(isSensitiveKey(key)).toBe(false); + }); + }); + + // ── redactSensitiveData ──────────────────────────────────────────────────── + + describe('redactSensitiveData()', () => { + it('should return primitives unchanged', () => { + expect(redactSensitiveData('hello')).toBe('hello'); + expect(redactSensitiveData(42)).toBe(42); + expect(redactSensitiveData(true)).toBe(true); + expect(redactSensitiveData(null)).toBeNull(); + expect(redactSensitiveData(undefined)).toBeUndefined(); + }); + + it('should redact top-level sensitive string fields', () => { + const input = { username: 'alice', password: 'hunter2' }; + const result = redactSensitiveData(input); + expect(result['password']).toBe(REDACTED); + expect(result['username']).toBe('alice'); + }); + + it('should redact top-level sensitive numeric fields', () => { + const input = { pin: 1234, amount: 99 }; + const result = redactSensitiveData(input); + expect(result['pin']).toBe(REDACTED); + expect(result['amount']).toBe(99); + }); + + it('should redact token-like keys regardless of case', () => { + const input = { AccessToken: 'eyJ...', BearerToken: 'tok' }; + const result = redactSensitiveData(input); + expect(result['AccessToken']).toBe(REDACTED); + expect(result['BearerToken']).toBe(REDACTED); + }); + + it('should NOT mutate the original object', () => { + const input = { password: 'secret', userId: 'u1' }; + redactSensitiveData(input); + expect(input.password).toBe('secret'); + }); + + it('should recursively redact nested objects', () => { + const input = { + user: { + name: 'Bob', + password: 'pw123', + profile: { bio: 'hello', apiKey: 'k-xxx' }, + }, + }; + const result = redactSensitiveData(input); + expect(result['user']['name']).toBe('Bob'); + expect(result['user']['password']).toBe(REDACTED); + expect(result['user']['profile']['bio']).toBe('hello'); + expect(result['user']['profile']['apiKey']).toBe(REDACTED); + }); + + it('should recursively redact inside arrays', () => { + const input = [ + { token: 'tok1', label: 'a' }, + { token: 'tok2', label: 'b' }, + ]; + const result = redactSensitiveData(input) as typeof input; + expect(result[0]['token']).toBe(REDACTED); + expect(result[0]['label']).toBe('a'); + expect(result[1]['token']).toBe(REDACTED); + expect(result[1]['label']).toBe('b'); + }); + + it('should handle deeply nested arrays of objects', () => { + const input = { items: [{ secret: 'abc', id: 1 }] }; + const result = redactSensitiveData(input); + expect((result['items'] as Array>)[0]['secret']).toBe(REDACTED); + expect((result['items'] as Array>)[0]['id']).toBe(1); + }); + + it('should handle circular references without throwing', () => { + const obj: Record = { a: 1 }; + obj['self'] = obj; + expect(() => redactSensitiveData(obj)).not.toThrow(); + }); + + it('should replace the circular node with "[Circular]"', () => { + const obj: Record = { a: 1 }; + obj['self'] = obj; + const result = redactSensitiveData(obj); + expect(result['self']).toBe('[Circular]'); + }); + + it('should leave objects without sensitive keys untouched structurally', () => { + const input = { courseId: 'c1', title: 'NestJS 101', published: true }; + const result = redactSensitiveData(input); + expect(result).toEqual(input); + }); + + it('should handle empty objects', () => { + expect(redactSensitiveData({})).toEqual({}); + }); + + it('should handle empty arrays', () => { + expect(redactSensitiveData([])).toEqual([]); + }); + }); + + // ── REDACTED constant ────────────────────────────────────────────────────── + + describe('REDACTED constant', () => { + it('should equal "[REDACTED]"', () => { + expect(REDACTED).toBe('[REDACTED]'); + }); + }); +}); diff --git a/src/logging/redaction.util.ts b/src/logging/redaction.util.ts new file mode 100644 index 00000000..69c6bf65 --- /dev/null +++ b/src/logging/redaction.util.ts @@ -0,0 +1,120 @@ +/** + * Sensitive-data redaction utility + * ───────────────────────────────── + * Recursively walks a plain-object / array payload and replaces values whose + * **key names** match a list of well-known sensitive field patterns with the + * placeholder `"[REDACTED]"`. + * + * Rules + * ───── + * 1. Key matching is **case-insensitive** and uses substring matching so that + * keys like `userPassword`, `access_token`, `stripe_secret_key` are all + * caught by simple patterns. + * 2. Only **string**, **number**, and **boolean** leaf values are replaced. + * Nested objects / arrays are traversed recursively so that nested secrets + * are also masked. + * 3. The utility is **non-destructive** — it returns a new object and never + * mutates the original payload. + * 4. Circular references are handled gracefully (the circular node is replaced + * with the string `"[Circular]"`). + * + * @module redaction.util + */ + +/** Placeholder inserted in place of a sensitive value. */ +export const REDACTED = '[REDACTED]'; + +/** + * Lowercase substring patterns used to identify sensitive keys. + * A key matches if its lower-cased form *includes* any of these strings. + */ +export const SENSITIVE_KEY_PATTERNS: readonly string[] = [ + 'password', + 'passwd', + 'secret', + 'token', + 'apikey', + 'api_key', + 'accesskey', + 'access_key', + 'privatekey', + 'private_key', + 'clientsecret', + 'client_secret', + 'authorization', + 'auth', + 'bearer', + 'credential', + 'ssn', + 'creditcard', + 'credit_card', + 'cardnumber', + 'card_number', + 'cvv', + 'cvc', + 'pin', + 'otp', + 'mfa', + 'signature', + 'webhook_secret', + 'signing_key', + 'signingkey', + 'encryption_key', + 'encryptionkey', + 'jwt', + 'refresh_token', + 'id_token', +]; + +/** + * Returns `true` when the given key name should have its value redacted. + * + * @param key - The property key to test. + */ +export function isSensitiveKey(key: string): boolean { + const lower = key.toLowerCase(); + return SENSITIVE_KEY_PATTERNS.some((pattern) => lower.includes(pattern)); +} + +/** + * Recursively redacts sensitive fields from `data`. + * + * @param data - Arbitrary metadata object / array / primitive. + * @param _seen - Internal set used to break circular references. + * @returns A deep copy of `data` with sensitive values replaced. + */ +export function redactSensitiveData(data: T, _seen = new WeakSet()): T { + if (data === null || data === undefined) { + return data; + } + + // Primitive values can never be "sensitive" on their own — we only redact + // by key name so we return primitives as-is. + if (typeof data !== 'object') { + return data; + } + + // Guard against circular references + if (_seen.has(data as object)) { + return '[Circular]' as unknown as T; + } + _seen.add(data as object); + + if (Array.isArray(data)) { + return data.map((item) => redactSensitiveData(item, _seen)) as unknown as T; + } + + const result: Record = {}; + + for (const [key, value] of Object.entries(data as Record)) { + if (isSensitiveKey(key)) { + result[key] = REDACTED; + } else if (value !== null && typeof value === 'object') { + result[key] = redactSensitiveData(value, _seen); + } else { + result[key] = value; + } + } + + return result as T; +}