Add API request/response logging with correlation IDs

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(),

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<string, unknown>;
+  headers: Record<string, unknown>;
+}> = {}): 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();
+  });
+});

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<unknown> {
+    if (context.getType() !== 'http') {
+      return next.handle();
+    }
+
+    const req = context.switchToHttp().getRequest<Request>();
+    const res = context.switchToHttp().getResponse<Response>();
+    const correlationId = getCorrelationId() || 'unknown';
+    const startTime = Date.now();
+
+    const requestLog: Record<string, unknown> = {
+      event: 'http_request',
+      correlationId,
+      method: req.method,
+      url: req.originalUrl || req.url,
+      headers: maskHeaders(req.headers as Record<string, unknown>),
+      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),
+            }),
+          );
+        },
+      }),
+    );
+  }
+}

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));
+  });
+});