From 67bfc64980c0de39d32d4eeaf11ff8816f0db19e Mon Sep 17 00:00:00 2001 From: soterika Date: Wed, 1 Jul 2026 17:36:00 +0000 Subject: [PATCH] feat: implement comprehensive logging standards (#536) - Add AppLoggerService: structured JSON logs, correlation IDs, NestJS ConsoleLogger extension, convenience methods (logRequest, logEvent, logQuery) - Add redaction.util: recursive sensitive-data redaction for 30+ key patterns (password, token, secret, authorization, jwt, pin, cvv, etc.) - Add LoggingInterceptor: global HTTP request/response logger with duration, status code, and correlation ID echo header - Add LoggingMiddleware: lightweight middleware to propagate correlation ID to response headers - Add LoggingModule (@Global): registers AppLoggerService, interceptor, and middleware; imported once in AppModule - Add 87 unit tests across 3 suites covering all acceptance criteria - Add docs/logging.md: usage guide, log level table, configuration, integration examples Closes #536 --- docs/logging.md | 240 ++++++++++++++++++++++ src/app.module.ts | 2 + src/logging/app-logger.service.spec.ts | 238 ++++++++++++++++++++++ src/logging/app-logger.service.ts | 257 ++++++++++++++++++++++++ src/logging/logging.interceptor.spec.ts | 211 +++++++++++++++++++ src/logging/logging.interceptor.ts | 84 ++++++++ src/logging/logging.middleware.ts | 53 +++++ src/logging/logging.module.ts | 48 +++++ src/logging/redaction.util.spec.ts | 178 ++++++++++++++++ src/logging/redaction.util.ts | 120 +++++++++++ 10 files changed, 1431 insertions(+) create mode 100644 docs/logging.md create mode 100644 src/logging/app-logger.service.spec.ts create mode 100644 src/logging/app-logger.service.ts create mode 100644 src/logging/logging.interceptor.spec.ts create mode 100644 src/logging/logging.interceptor.ts create mode 100644 src/logging/logging.middleware.ts create mode 100644 src/logging/logging.module.ts create mode 100644 src/logging/redaction.util.spec.ts create mode 100644 src/logging/redaction.util.ts diff --git a/docs/logging.md b/docs/logging.md new file mode 100644 index 00000000..1d95c696 --- /dev/null +++ b/docs/logging.md @@ -0,0 +1,240 @@ +# Logging Standards — TeachLink Backend + +> Issue [#536](https://github.com/rinafcode/teachLink_backend/issues/536) + +--- + +## Overview + +TeachLink backend uses a centralised, structured logging system built on top of NestJS's +built-in `ConsoleLogger`. Every log line is emitted as a **single-line JSON object** so +that log-shipping tools (Filebeat, Fluent Bit, CloudWatch Logs Insights, Datadog, etc.) +can parse and index individual fields without regular expressions. + +--- + +## Architecture + +``` +src/logging/ +├── app-logger.service.ts # Core logger — inject this everywhere +├── app-logger.service.spec.ts # Unit tests for AppLoggerService +├── logging.interceptor.ts # Global HTTP request/response logger +├── logging.interceptor.spec.ts # Unit tests for LoggingInterceptor +├── logging.middleware.ts # Correlation-ID propagation middleware +├── logging.module.ts # @Global NestJS module — import once in AppModule +├── redaction.util.ts # Sensitive-data redaction helper +└── redaction.util.spec.ts # Unit tests for redaction +``` + +All modules import `LoggingModule` **indirectly** (it is `@Global()`), so only +`AppModule` needs to explicitly import it. + +--- + +## Log Record Shape + +Every emitted record conforms to `IAppLogRecord`: + +```jsonc +{ + "level": "info", // debug | info | warn | error | fatal + "message": "User enrolled", // human-readable description + "context": "CoursesService", // NestJS context / class name + "correlationId": "cid-...", // request trace ID (from x-request-id header) + "timestamp": "2026-07-01T17:18:27.123Z", + "metadata": { // optional – all sensitive fields redacted + "courseId": "c-123", + "userId": "u-456", + "type": "business_event" + }, + "error": { // only present on error / fatal calls + "name": "Error", + "message": "Connection refused", + "stack": "Error: Connection refused\n at ..." + } +} +``` + +--- + +## Log Levels — Usage Guide + +| Level | When to use | +|---------|-----------------------------------------------------------------------------------------------------| +| `debug` | Internal state, SQL queries, algorithm steps. Disabled by default in production. | +| `info` | Normal operational events: requests completed, jobs processed, user actions recorded. | +| `warn` | Recoverable anomalies: retries, degraded mode, slow queries, deprecated feature usage. | +| `error` | Unexpected failures that need investigation but did not crash the process. | +| `fatal` | Critical failures that require immediate operator action (DB unreachable, OOM, startup failure). | + +--- + +## Correlation IDs + +The correlation ID is a short unique string that is attached to **every log line +generated within a single HTTP request**. This allows you to search for all logs +from one request across all services. + +Flow: +1. `correlationMiddleware` (registered in `main.ts`) reads `x-request-id` from the + incoming request header, or generates a new one (`cid--`). +2. The ID is stored in `AsyncLocalStorage` (thread-local equivalent for Node.js). +3. `AppLoggerService._emit()` calls `getCorrelationId()` from that storage on every + log call — no manual threading required. +4. `LoggingInterceptor` and `LoggingMiddleware` echo the ID back in the response + header so that API callers can record it and use it for support tickets. + +To trace a request end-to-end, search your log system for: + +``` +correlationId:"cid-lxj83k-abcdef12" +``` + +--- + +## Sensitive Data Redaction + +`redactSensitiveData()` (in `redaction.util.ts`) is called automatically on every +`metadata` payload before the log is serialised. + +### Redacted by default + +Any key whose **lower-cased name contains** one of these substrings will have its +value replaced with `"[REDACTED]"`: + +``` +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, +encryption_key, jwt, refresh_token, id_token +``` + +### Example + +```ts +logger.info('login attempt', { + username: 'alice', + password: 'hunter2', // → "[REDACTED]" + accessToken: 'eyJhbGc...', // → "[REDACTED]" +}); +``` + +Resulting log record: + +```json +{ + "level": "info", + "message": "login attempt", + "metadata": { + "username": "alice", + "password": "[REDACTED]", + "accessToken": "[REDACTED]" + } +} +``` + +--- + +## Usage + +### 1. Inject AppLoggerService + +```typescript +import { Injectable } from '@nestjs/common'; +import { AppLoggerService } from '../logging/app-logger.service'; + +@Injectable() +export class CoursesService { + constructor(private readonly logger: AppLoggerService) { + this.logger.setContext(CoursesService.name); + } + + async enroll(userId: string, courseId: string): Promise { + this.logger.info('Enrolling user', { userId, courseId }); + + try { + // ... business logic + this.logger.logEvent('user.enrolled', { userId, courseId }); + } catch (err) { + this.logger.error('Enrollment failed', err as Error, { userId, courseId }); + throw err; + } + } +} +``` + +### 2. HTTP request logging (automatic) + +`LoggingInterceptor` is registered globally via `APP_INTERCEPTOR` in `LoggingModule`. +You do not need to add anything to individual controllers. + +Every request emits two lines automatically: + +```json +{ "level": "debug", "message": "→ POST /courses/enroll", ... } +{ "level": "info", "message": "POST /courses/enroll 201", "metadata": { "durationMs": 14 } } +``` + +### 3. Forwarding correlation ID in outbound HTTP calls + +```typescript +import { + getCorrelationId, + CORRELATION_ID_HEADER, + injectCorrelationIdToHeaders, +} from '../common/utils/correlation.utils'; + +// Using the helper +const headers = injectCorrelationIdToHeaders({ 'content-type': 'application/json' }); +await this.httpService.post(url, body, { headers }); +``` + +--- + +## Configuration + +| Environment variable | Default | Description | +|----------------------|---------------|-------------------------------------------------------------------------------| +| `LOG_LEVEL` | `log` | NestJS built-in: `debug`, `log`, `warn`, `error`, `fatal` | +| `NODE_ENV` | `development` | Controls log verbosity in some external tools (no effect on NestJS directly). | + +Set `LOG_LEVEL=debug` in development to see SQL queries and algorithm steps. +Set `LOG_LEVEL=warn` in production to reduce noise (error and fatal still emitted). + +### NestJS bootstrap + +To pass `LOG_LEVEL` to NestJS at startup: + +```typescript +// main.ts +const app = await NestFactory.create(AppModule, { + logger: (process.env.LOG_LEVEL?.split(',') as LogLevel[]) ?? ['log', 'warn', 'error', 'fatal'], +}); +``` + +--- + +## Testing + +```bash +# Run only logging tests +npx jest src/logging --testPathPattern="logging|redaction|app-logger" + +# Run all unit tests with coverage +npm run test:ci +``` + +--- + +## Integration with External Systems + +The JSON format is compatible with: + +- **Elasticsearch / Kibana** — index via Filebeat or Fluent Bit; map `level`, `correlationId`, `timestamp` as keyword fields. +- **AWS CloudWatch Logs Insights** — query with `fields @message | filter level = "error"`. +- **Datadog** — auto-parsed by the Node.js tracer; set `DD_LOGS_INJECTION=true` to auto-inject trace IDs. +- **Grafana Loki** — ship via `promtail`; label streams by `level` and `context`. + +See `logging/shipper/filebeat.yml` for a working Filebeat configuration. diff --git a/src/app.module.ts b/src/app.module.ts index 4ed5dd5a..62717e77 100644 --- a/src/app.module.ts +++ b/src/app.module.ts @@ -39,6 +39,7 @@ import { GatewayModule } from './gateway/gateway.module'; import { NotificationsModule } from './notifications/notifications.module'; import { MessagingModule } from './messaging/messaging.module'; import { DashboardModule } from './dashboard/dashboard.module'; +import { LoggingModule } from './logging/logging.module'; const featureFlags = loadFeatureFlags(); @@ -47,6 +48,7 @@ const featureFlags = loadFeatureFlags(); ConfigModule.forRoot({ isGlobal: true }), 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/logging.module.ts b/src/logging/logging.module.ts new file mode 100644 index 00000000..b569ebfb --- /dev/null +++ b/src/logging/logging.module.ts @@ -0,0 +1,48 @@ +import { Global, MiddlewareConsumer, Module, NestModule } from '@nestjs/common'; +import { APP_INTERCEPTOR } from '@nestjs/core'; + +import { AppLoggerService } from './app-logger.service'; +import { LoggingInterceptor } from './logging.interceptor'; +import { LoggingMiddleware } from './logging.middleware'; + +/** + * LoggingModule + * ───────────── + * Centralised logging infrastructure. Marked `@Global` so that + * `AppLoggerService` can be injected anywhere without re-importing this module. + * + * What it provides + * ──────────────── + * • `AppLoggerService` — structured, correlation-ID-aware logger. + * • `LoggingInterceptor` — global HTTP request/response logger (registered via + * `APP_INTERCEPTOR` so it applies to every route automatically). + * • `LoggingMiddleware` — echoes the correlation ID in response headers and + * logs the raw incoming request before any guard/pipe runs. + * + * Registration + * ──────────── + * Import once in `AppModule`: + * + * ```ts + * @Module({ + * imports: [LoggingModule, ...], + * }) + * export class AppModule {} + * ``` + */ +@Global() +@Module({ + providers: [ + AppLoggerService, + { + provide: APP_INTERCEPTOR, + useClass: LoggingInterceptor, + }, + ], + exports: [AppLoggerService], +}) +export class LoggingModule implements NestModule { + configure(consumer: MiddlewareConsumer): void { + consumer.apply(LoggingMiddleware).forRoutes('*'); + } +} 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; +}