From 009a194b3e8cea41e963440a687ab253f077fa66 Mon Sep 17 00:00:00 2001 From: iajibose Date: Thu, 25 Jun 2026 17:09:58 +0100 Subject: [PATCH] feat: add API request/response logging with correlation IDs --- src/app.module.ts | 2 + src/logging/http-logging.interceptor.spec.ts | 180 +++++++++++++++++++ src/logging/http-logging.interceptor.ts | 90 ++++++++++ src/logging/logger.service.spec.ts | 65 +++++++ src/logging/logger.service.ts | 107 +++++++++++ src/logging/logging.module.ts | 14 ++ src/logging/sensitive-data.masker.spec.ts | 103 +++++++++++ src/logging/sensitive-data.masker.ts | 64 +++++++ 8 files changed, 625 insertions(+) create mode 100644 src/logging/http-logging.interceptor.spec.ts create mode 100644 src/logging/http-logging.interceptor.ts create mode 100644 src/logging/logger.service.spec.ts create mode 100644 src/logging/logger.service.ts create mode 100644 src/logging/logging.module.ts create mode 100644 src/logging/sensitive-data.masker.spec.ts create mode 100644 src/logging/sensitive-data.masker.ts diff --git a/src/app.module.ts b/src/app.module.ts index 81dd098b..5391f4c8 100644 --- a/src/app.module.ts +++ b/src/app.module.ts @@ -32,11 +32,13 @@ import { CachingModule } from './caching/caching.module'; import { CoursesModule } from './courses/courses.module'; import { AuthModule } from './auth/auth.module'; import { CohortsModule } from './cohorts/cohorts.module'; +import { LoggingModule } from './logging/logging.module'; const featureFlags = loadFeatureFlags(); @Module({ imports: [ + LoggingModule, ConfigModule.forRoot({ isGlobal: true }), TypeOrmModule.forRoot(getDatabaseConfig()), ScheduleModule.forRoot(), diff --git a/src/logging/http-logging.interceptor.spec.ts b/src/logging/http-logging.interceptor.spec.ts new file mode 100644 index 00000000..a663bbac --- /dev/null +++ b/src/logging/http-logging.interceptor.spec.ts @@ -0,0 +1,180 @@ +import { Test, TestingModule } from '@nestjs/testing'; +import { ExecutionContext, CallHandler } from '@nestjs/common'; +import { of, throwError } from 'rxjs'; +import { HttpLoggingInterceptor } from './http-logging.interceptor'; +import { runWithCorrelationId } from '../common/utils/correlation.utils'; + +function buildContext(overrides: Partial<{ + method: string; + url: string; + body: Record; + headers: Record; +}> = {}): ExecutionContext { + const { method = 'GET', url = '/test', body = {}, headers = {} } = overrides; + return { + getType: () => 'http', + switchToHttp: () => ({ + getRequest: () => ({ + method, + url, + originalUrl: url, + body, + headers, + socket: { remoteAddress: '127.0.0.1' }, + }), + getResponse: () => ({ + statusCode: 200, + }), + }), + } as unknown as ExecutionContext; +} + +function buildHandler(value: unknown = { data: 'ok' }): CallHandler { + return { handle: () => of(value) }; +} + +function buildErrorHandler(err: Error): CallHandler { + return { handle: () => throwError(() => err) }; +} + +describe('HttpLoggingInterceptor', () => { + let interceptor: HttpLoggingInterceptor; + let logSpy: jest.SpyInstance; + let errorSpy: jest.SpyInstance; + + beforeEach(async () => { + const module: TestingModule = await Test.createTestingModule({ + providers: [HttpLoggingInterceptor], + }).compile(); + + interceptor = module.get(HttpLoggingInterceptor); + logSpy = jest.spyOn((interceptor as unknown as { logger: { log: jest.Mock } }).logger, 'log').mockImplementation(() => undefined); + errorSpy = jest.spyOn((interceptor as unknown as { logger: { error: jest.Mock } }).logger, 'error').mockImplementation(() => undefined); + }); + + it('should be defined', () => { + expect(interceptor).toBeDefined(); + }); + + it('logs request entry and response', (done) => { + const ctx = buildContext({ method: 'GET', url: '/api/courses' }); + const handler = buildHandler(); + + runWithCorrelationId(() => { + interceptor.intercept(ctx, handler).subscribe({ + complete: () => { + expect(logSpy).toHaveBeenCalledTimes(2); + const requestLog = JSON.parse(logSpy.mock.calls[0][0]); + expect(requestLog.event).toBe('http_request'); + expect(requestLog.method).toBe('GET'); + expect(requestLog.url).toBe('/api/courses'); + const responseLog = JSON.parse(logSpy.mock.calls[1][0]); + expect(responseLog.event).toBe('http_response'); + expect(responseLog.statusCode).toBe(200); + done(); + }, + }); + }, 'test-cid'); + }); + + it('includes correlation ID in log entries', (done) => { + const ctx = buildContext(); + const handler = buildHandler(); + + runWithCorrelationId(() => { + interceptor.intercept(ctx, handler).subscribe({ + complete: () => { + const requestLog = JSON.parse(logSpy.mock.calls[0][0]); + expect(requestLog.correlationId).toBe('my-cid-123'); + done(); + }, + }); + }, 'my-cid-123'); + }); + + it('tracks response time in milliseconds', (done) => { + const ctx = buildContext(); + const handler = buildHandler(); + + runWithCorrelationId(() => { + interceptor.intercept(ctx, handler).subscribe({ + complete: () => { + const responseLog = JSON.parse(logSpy.mock.calls[1][0]); + expect(typeof responseLog.durationMs).toBe('number'); + expect(responseLog.durationMs).toBeGreaterThanOrEqual(0); + done(); + }, + }); + }, 'cid-1'); + }); + + it('masks sensitive fields in request body', (done) => { + const ctx = buildContext({ + method: 'POST', + url: '/auth/login', + body: { email: 'user@example.com', password: 'secret' }, + }); + const handler = buildHandler(); + + runWithCorrelationId(() => { + interceptor.intercept(ctx, handler).subscribe({ + complete: () => { + const requestLog = JSON.parse(logSpy.mock.calls[0][0]); + expect(requestLog.body.password).toBe('***MASKED***'); + expect(requestLog.body.email).toBe('user@example.com'); + done(); + }, + }); + }, 'cid-2'); + }); + + it('masks authorization header', (done) => { + const ctx = buildContext({ + headers: { authorization: 'Bearer token123', 'content-type': 'application/json' }, + }); + const handler = buildHandler(); + + runWithCorrelationId(() => { + interceptor.intercept(ctx, handler).subscribe({ + complete: () => { + const requestLog = JSON.parse(logSpy.mock.calls[0][0]); + expect(requestLog.headers.authorization).toBe('***MASKED***'); + expect(requestLog.headers['content-type']).toBe('application/json'); + done(); + }, + }); + }, 'cid-3'); + }); + + it('logs errors with http_error event', (done) => { + const ctx = buildContext(); + const err = Object.assign(new Error('Not found'), { status: 404 }); + const handler = buildErrorHandler(err); + + runWithCorrelationId(() => { + interceptor.intercept(ctx, handler).subscribe({ + error: () => { + expect(errorSpy).toHaveBeenCalledTimes(1); + const errorLog = JSON.parse(errorSpy.mock.calls[0][0]); + expect(errorLog.event).toBe('http_error'); + expect(errorLog.statusCode).toBe(404); + expect(errorLog.durationMs).toBeGreaterThanOrEqual(0); + done(); + }, + }); + }, 'cid-4'); + }); + + it('skips non-http contexts', () => { + const wsContext = { + getType: () => 'ws', + } as unknown as ExecutionContext; + const handler = buildHandler(); + const handleSpy = jest.spyOn(handler, 'handle'); + + interceptor.intercept(wsContext, handler); + + expect(handleSpy).toHaveBeenCalledTimes(1); + expect(logSpy).not.toHaveBeenCalled(); + }); +}); diff --git a/src/logging/http-logging.interceptor.ts b/src/logging/http-logging.interceptor.ts new file mode 100644 index 00000000..5470f7c1 --- /dev/null +++ b/src/logging/http-logging.interceptor.ts @@ -0,0 +1,90 @@ +import { Injectable, NestInterceptor, ExecutionContext, CallHandler, Logger } from '@nestjs/common'; +import { Observable } from 'rxjs'; +import { tap } from 'rxjs/operators'; +import { Request, Response } from 'express'; +import { getCorrelationId } from '../common/utils/correlation.utils'; +import { maskSensitiveData, maskHeaders } from './sensitive-data.masker'; + +const MAX_BODY_LENGTH = 4096; + +function truncate(value: unknown): unknown { + if (typeof value === 'string' && value.length > MAX_BODY_LENGTH) { + return value.slice(0, MAX_BODY_LENGTH) + '...[truncated]'; + } + return value; +} + +function sanitizeBody(body: unknown): unknown { + if (!body || typeof body !== 'object') return truncate(body); + return maskSensitiveData(body); +} + +@Injectable() +export class HttpLoggingInterceptor implements NestInterceptor { + private readonly logger = new Logger(HttpLoggingInterceptor.name); + + intercept(context: ExecutionContext, next: CallHandler): Observable { + if (context.getType() !== 'http') { + return next.handle(); + } + + const req = context.switchToHttp().getRequest(); + const res = context.switchToHttp().getResponse(); + const correlationId = getCorrelationId() || 'unknown'; + const startTime = Date.now(); + + const requestLog: Record = { + event: 'http_request', + correlationId, + method: req.method, + url: req.originalUrl || req.url, + headers: maskHeaders(req.headers as Record), + remoteAddress: req.headers['x-forwarded-for'] || req.socket?.remoteAddress, + }; + + if (req.body && Object.keys(req.body).length > 0) { + requestLog.body = sanitizeBody(req.body); + } + + this.logger.log(JSON.stringify(requestLog)); + + return next.handle().pipe( + tap({ + next: () => { + const durationMs = Date.now() - startTime; + this.logger.log( + JSON.stringify({ + event: 'http_response', + correlationId, + method: req.method, + url: req.originalUrl || req.url, + statusCode: res.statusCode, + durationMs, + }), + ); + }, + error: (err: unknown) => { + const durationMs = Date.now() - startTime; + const statusCode = + (err as { status?: number; statusCode?: number })?.status || + (err as { status?: number; statusCode?: number })?.statusCode || + 500; + this.logger.error( + JSON.stringify({ + event: 'http_error', + correlationId, + method: req.method, + url: req.originalUrl || req.url, + statusCode, + durationMs, + error: + err instanceof Error + ? { message: err.message, name: err.name } + : String(err), + }), + ); + }, + }), + ); + } +} diff --git a/src/logging/logger.service.spec.ts b/src/logging/logger.service.spec.ts new file mode 100644 index 00000000..5b75db54 --- /dev/null +++ b/src/logging/logger.service.spec.ts @@ -0,0 +1,65 @@ +import { Test, TestingModule } from '@nestjs/testing'; +import { AppLoggerService } from './logger.service'; +import { runWithCorrelationId } from '../common/utils/correlation.utils'; + +describe('AppLoggerService', () => { + let service: AppLoggerService; + + beforeEach(async () => { + process.env.LOG_TO_FILE = 'false'; + const module: TestingModule = await Test.createTestingModule({ + providers: [AppLoggerService], + }).compile(); + service = module.get(AppLoggerService); + }); + + it('should be defined', () => { + expect(service).toBeDefined(); + }); + + it('exposes standard NestJS logger methods', () => { + expect(typeof service.log).toBe('function'); + expect(typeof service.error).toBe('function'); + expect(typeof service.warn).toBe('function'); + expect(typeof service.debug).toBe('function'); + expect(typeof service.verbose).toBe('function'); + }); + + it('exposes request/response log helpers', () => { + expect(typeof service.logRequest).toBe('function'); + expect(typeof service.logResponse).toBe('function'); + }); + + it('calls log without throwing', () => { + expect(() => service.log('hello', 'TestContext')).not.toThrow(); + }); + + it('calls error without throwing', () => { + expect(() => service.error('err msg', 'stack trace', 'TestContext')).not.toThrow(); + }); + + it('calls warn without throwing', () => { + expect(() => service.warn('warning', 'TestContext')).not.toThrow(); + }); + + it('calls logRequest without throwing', () => { + expect(() => service.logRequest({ method: 'GET', url: '/test' })).not.toThrow(); + }); + + it('calls logResponse without throwing', () => { + expect(() => service.logResponse({ statusCode: 200, durationMs: 42 })).not.toThrow(); + }); + + it('includes correlation ID in log output when set', () => { + const winstonSpy = jest.spyOn( + (service as unknown as { winston: { info: jest.Mock } }).winston, + 'info', + ); + + runWithCorrelationId(() => { + service.log('test message'); + }, 'cid-test-123'); + + expect(winstonSpy).toHaveBeenCalledWith('test message', expect.any(Object)); + }); +}); diff --git a/src/logging/logger.service.ts b/src/logging/logger.service.ts new file mode 100644 index 00000000..ccef4318 --- /dev/null +++ b/src/logging/logger.service.ts @@ -0,0 +1,107 @@ +import { Injectable, LoggerService } from '@nestjs/common'; +import { createLogger, format, transports, Logger } from 'winston'; +import DailyRotateFile from 'winston-daily-rotate-file'; +import { getCorrelationId } from '../common/utils/correlation.utils'; +import { maskSensitiveData } from './sensitive-data.masker'; + +function buildJsonFormat() { + return format.combine( + format.timestamp(), + format.errors({ stack: true }), + format.printf((info) => { + const correlationId = getCorrelationId(); + const entry: Record = { + timestamp: info.timestamp, + level: info.level, + service: process.env.SERVICE_NAME || 'teachlink-backend', + pid: process.pid, + ...(correlationId ? { correlationId } : {}), + message: info.message, + }; + + if (info.stack) entry.stack = info.stack; + + const skip = new Set(['timestamp', 'level', 'message', 'stack', 'service']); + const meta: Record = {}; + for (const [k, v] of Object.entries(info)) { + if (!skip.has(k)) meta[k] = v; + } + if (Object.keys(meta).length > 0) { + entry.meta = maskSensitiveData(meta); + } + + return JSON.stringify(entry); + }), + ); +} + +@Injectable() +export class AppLoggerService implements LoggerService { + private readonly winston: Logger; + + constructor() { + const logLevel = process.env.LOG_LEVEL || 'info'; + const logDir = process.env.LOG_DIR || 'logs'; + const enableFileLogging = + process.env.NODE_ENV === 'production' || process.env.LOG_TO_FILE === 'true'; + + const jsonFormat = buildJsonFormat(); + + const transportList: (transports.ConsoleTransportInstance | DailyRotateFile)[] = [ + new transports.Console({ format: jsonFormat }), + ]; + + if (enableFileLogging) { + transportList.push( + new DailyRotateFile({ + filename: `${logDir}/app-%DATE%.log`, + datePattern: 'YYYY-MM-DD', + maxSize: '20m', + maxFiles: '14d', + format: jsonFormat, + }), + ); + + transportList.push( + new DailyRotateFile({ + filename: `${logDir}/error-%DATE%.log`, + datePattern: 'YYYY-MM-DD', + level: 'error', + maxSize: '20m', + maxFiles: '30d', + format: jsonFormat, + }), + ); + } + + this.winston = createLogger({ level: logLevel, transports: transportList }); + } + + log(message: string, context?: string): void { + this.winston.info(message, { context }); + } + + error(message: string, trace?: string, context?: string): void { + this.winston.error(message, { context, stack: trace }); + } + + warn(message: string, context?: string): void { + this.winston.warn(message, { context }); + } + + debug(message: string, context?: string): void { + this.winston.debug(message, { context }); + } + + verbose(message: string, context?: string): void { + this.winston.verbose(message, { context }); + } + + logRequest(meta: Record): void { + this.winston.info('http_request', meta); + } + + logResponse(meta: Record): void { + this.winston.info('http_response', meta); + } +} diff --git a/src/logging/logging.module.ts b/src/logging/logging.module.ts new file mode 100644 index 00000000..071d971e --- /dev/null +++ b/src/logging/logging.module.ts @@ -0,0 +1,14 @@ +import { Global, Module } from '@nestjs/common'; +import { APP_INTERCEPTOR } from '@nestjs/core'; +import { AppLoggerService } from './logger.service'; +import { HttpLoggingInterceptor } from './http-logging.interceptor'; + +@Global() +@Module({ + providers: [ + AppLoggerService, + { provide: APP_INTERCEPTOR, useClass: HttpLoggingInterceptor }, + ], + exports: [AppLoggerService], +}) +export class LoggingModule {} diff --git a/src/logging/sensitive-data.masker.spec.ts b/src/logging/sensitive-data.masker.spec.ts new file mode 100644 index 00000000..dfe174ca --- /dev/null +++ b/src/logging/sensitive-data.masker.spec.ts @@ -0,0 +1,103 @@ +import { maskSensitiveData, maskHeaders, MASKED } from './sensitive-data.masker'; + +describe('maskSensitiveData', () => { + it('masks password field', () => { + const result = maskSensitiveData({ password: 'secret123', email: 'user@example.com' }); + expect((result as Record).password).toBe(MASKED); + expect((result as Record).email).toBe('user@example.com'); + }); + + it('masks token field', () => { + const result = maskSensitiveData({ token: 'abc123', name: 'John' }); + expect((result as Record).token).toBe(MASKED); + expect((result as Record).name).toBe('John'); + }); + + it('masks authorization field', () => { + const result = maskSensitiveData({ authorization: 'Bearer xyz' }); + expect((result as Record).authorization).toBe(MASKED); + }); + + it('masks secret field', () => { + const result = maskSensitiveData({ secret: 'mysecret' }); + expect((result as Record).secret).toBe(MASKED); + }); + + it('masks credit_card field', () => { + const result = maskSensitiveData({ credit_card: '4111111111111111', amount: 100 }); + expect((result as Record).credit_card).toBe(MASKED); + expect((result as Record).amount).toBe(100); + }); + + it('masks cvv field', () => { + const result = maskSensitiveData({ cvv: '123' }); + expect((result as Record).cvv).toBe(MASKED); + }); + + it('masks pin field', () => { + const result = maskSensitiveData({ pin: '1234' }); + expect((result as Record).pin).toBe(MASKED); + }); + + it('masks nested sensitive fields', () => { + const input = { + user: { + name: 'Alice', + password: 'pass123', + }, + }; + const result = maskSensitiveData(input) as { user: Record }; + expect(result.user.password).toBe(MASKED); + expect(result.user.name).toBe('Alice'); + }); + + it('handles arrays', () => { + const input = [{ password: 'p1' }, { token: 't1' }]; + const result = maskSensitiveData(input) as Record[]; + expect(result[0].password).toBe(MASKED); + expect(result[1].token).toBe(MASKED); + }); + + it('passes through null', () => { + expect(maskSensitiveData(null)).toBeNull(); + }); + + it('passes through undefined', () => { + expect(maskSensitiveData(undefined)).toBeUndefined(); + }); + + it('passes through primitive values', () => { + expect(maskSensitiveData('plain string')).toBe('plain string'); + expect(maskSensitiveData(42)).toBe(42); + expect(maskSensitiveData(true)).toBe(true); + }); + + it('handles empty object', () => { + expect(maskSensitiveData({})).toEqual({}); + }); + + it('is case-insensitive for key matching', () => { + const result = maskSensitiveData({ Password: 'p', TOKEN: 't', apiKey: 'k' }); + expect((result as Record).Password).toBe(MASKED); + expect((result as Record).TOKEN).toBe(MASKED); + expect((result as Record).apiKey).toBe(MASKED); + }); +}); + +describe('maskHeaders', () => { + it('masks authorization header', () => { + const result = maskHeaders({ authorization: 'Bearer token123', 'content-type': 'application/json' }); + expect(result.authorization).toBe(MASKED); + expect(result['content-type']).toBe('application/json'); + }); + + it('preserves non-sensitive headers', () => { + const result = maskHeaders({ 'x-correlation-id': 'cid-123', host: 'localhost' }); + expect(result['x-correlation-id']).toBe('cid-123'); + expect(result.host).toBe('localhost'); + }); + + it('handles empty headers', () => { + expect(maskHeaders({})).toEqual({}); + }); +}); diff --git a/src/logging/sensitive-data.masker.ts b/src/logging/sensitive-data.masker.ts new file mode 100644 index 00000000..ab456294 --- /dev/null +++ b/src/logging/sensitive-data.masker.ts @@ -0,0 +1,64 @@ +const MASKED = '***MASKED***'; + +const SENSITIVE_KEYS = new Set([ + 'password', + 'passwd', + 'pass', + 'secret', + 'token', + 'accesstoken', + 'access_token', + 'refreshtoken', + 'refresh_token', + 'apikey', + 'api_key', + 'apitoken', + 'api_token', + 'authorization', + 'auth', + 'key', + 'privatekey', + 'private_key', + 'clientsecret', + 'client_secret', + 'credit_card', + 'creditcard', + 'cardnumber', + 'card_number', + 'cvv', + 'cvc', + 'pin', + 'ssn', + 'socialsecuritynumber', + 'social_security_number', +]); + +function isSensitiveKey(key: string): boolean { + return SENSITIVE_KEYS.has(key.toLowerCase().replace(/[-\s]/g, '')); +} + +export function maskSensitiveData(data: unknown, depth = 0): unknown { + if (depth > 10 || data === null || data === undefined) return data; + + if (typeof data !== 'object') return data; + + if (Array.isArray(data)) { + return data.map((item) => maskSensitiveData(item, depth + 1)); + } + + const result: Record = {}; + for (const [key, value] of Object.entries(data as Record)) { + result[key] = isSensitiveKey(key) ? MASKED : maskSensitiveData(value, depth + 1); + } + return result; +} + +export function maskHeaders(headers: Record): Record { + const result: Record = {}; + for (const [key, value] of Object.entries(headers)) { + result[key] = isSensitiveKey(key) ? MASKED : value; + } + return result; +} + +export { MASKED, SENSITIVE_KEYS };