logging redact pii

Author: henrypeters

backend/src/common/middleware/logging.middleware.spec.ts

@@ -41,7 +41,16 @@ describe('LoggingMiddleware', () => {
         listeners[event] = listeners[event] ?? [];
         listeners[event].push(cb);
       }) as unknown as Response['on'],
-    } as Partial<Response>;
+      getEventListeners: () => listeners,
+      json: jest.fn(function (data: any) {
+        this.json = jest.fn(function (d) { return this; });
+        return this;
+      }),
+      send: jest.fn(function (data: any) {
+        this.send = jest.fn(function (d) { return this; });
+        return this;
+      }),
+    } as any;
   }
 
   it('should be defined', () => {
@@ -114,4 +123,94 @@ describe('LoggingMiddleware', () => {
 
     expect(next).toHaveBeenCalled();
   });
+
+  it('logs response body with redaction on finish', () => {
+    const errorSpy = jest.spyOn(Logger.prototype, 'error').mockImplementation(() => {});
+    const req = makeReq();
+    const res = makeRes() as any;
+    const next: NextFunction = jest.fn();
+
+    middleware.use(req as Request, res as Response, next);
+
+    // Capture and use the json method
+    res.json({ token: 'secret_token', userId: 'user123' });
+
+    // Trigger finish event
+    const listeners = res.getEventListeners();
+    if (listeners['finish']) {
+      listeners['finish'].forEach((cb: () => void) => cb());
+    }
+
+    // Response should be logged but with redacted token
+    const loggedMessages = [...logSpy.mock.calls, ...errorSpy.mock.calls];
+    const finishLogCall = loggedMessages.find((call: any[]) => call[0]?.includes('Outgoing Response'));
+    expect(finishLogCall).toBeDefined();
+    expect(finishLogCall?.[0]).toContain(REDACTED);
+    expect(finishLogCall?.[0]).toContain('user123');
+  });
+
+  it('redacts sensitive fields in response body', () => {
+    const req = makeReq();
+    const res = makeRes() as any;
+    const next: NextFunction = jest.fn();
+
+    middleware.use(req as Request, res as Response, next);
+
+    // Send a response with sensitive data
+    res.json({ email: 'user@example.com', name: 'Alice', password: 'secret' });
+
+    // Trigger finish event
+    const listeners = res.getEventListeners();
+    if (listeners['finish']) {
+      listeners['finish'].forEach((cb: () => void) => cb());
+    }
+
+    const loggedMessages = [...logSpy.mock.calls];
+    const finishLogCall = loggedMessages.find((call: any[]) => call[0]?.includes('Outgoing Response'));
+    expect(finishLogCall?.[0]).not.toContain('user@example.com');
+    expect(finishLogCall?.[0]).not.toContain('secret');
+    expect(finishLogCall?.[0]).toContain(REDACTED);
+    expect(finishLogCall?.[0]).toContain('Alice');
+  });
+
+  it('logs (no body) when response has no body', () => {
+    const req = makeReq({ method: 'GET' });
+    const res = makeRes() as any;
+    const next: NextFunction = jest.fn();
+
+    middleware.use(req as Request, res as Response, next);
+
+    // Don't call json or send, so responseBody stays undefined
+    // Trigger finish event
+    const listeners = res.getEventListeners();
+    if (listeners['finish']) {
+      listeners['finish'].forEach((cb: () => void) => cb());
+    }
+
+    const loggedMessages = [...logSpy.mock.calls];
+    const finishLogCall = loggedMessages.find((call: any[]) => call[0]?.includes('Outgoing Response'));
+    expect(finishLogCall?.[0]).toContain('(no body)');
+  });
+
+  it('handles stale context gracefully when finish event fires', () => {
+    const req = makeReq();
+    const res = makeRes() as any;
+    const next: NextFunction = jest.fn();
+
+    middleware.use(req as Request, res as Response, next);
+
+    // Manually clear context to simulate stale state
+    const requestContextService = new RequestContextService();
+    // requestContextService.clearContext();  // This is a no-op, so context remains
+
+    res.json({ userId: 'user123' });
+
+    // Trigger finish event - should not throw
+    const listeners = res.getEventListeners();
+    expect(() => {
+      if (listeners['finish']) {
+        listeners['finish'].forEach((cb: () => void) => cb());
+      }
+    }).not.toThrow();
+  });
 });

backend/src/common/middleware/logging.middleware.ts

@@ -24,14 +24,45 @@ export class LoggingMiddleware implements NestMiddleware {
       `[${correlationId}] [${requestId}] Incoming Request: ${method} ${originalUrl} - IP: ${ip ?? ''} - Headers: ${JSON.stringify(redactedHeaders)} - Body: ${JSON.stringify(redactedBody)}`,
     );
 
+    // Store response data by intercepting json() and send() methods
+    let responseBody: unknown = undefined;
+    const originalJson = res.json.bind(res);
+    const originalSend = res.send.bind(res);
+
+    res.json = function (data: any) {
+      responseBody = data;
+      return originalJson(data);
+    };
+
+    res.send = function (data: any) {
+      // Try to parse if string looks like JSON
+      if (typeof data === 'string' && data.startsWith('{')) {
+        try {
+          responseBody = JSON.parse(data);
+        } catch {
+          responseBody = data;
+        }
+      } else {
+        responseBody = data;
+      }
+      return originalSend(data);
+    };
+
     // Set up cleanup on response finish
     res.on('finish', () => {
       const { statusCode } = res;
       const duration = Date.now() - startTime;
       const user = (req as Request & { user?: { id?: string } }).user;
       const userId = user?.id ?? 'anonymous';
 
-      const message = `[${correlationId}] [${requestId}] Outgoing Response: ${method} ${originalUrl} - Status: ${statusCode} - Duration: ${duration}ms - User: ${userId}`;
+      // Redact response body if available
+      const redactedResponse = responseBody !== undefined ? redact(responseBody) : undefined;
+      const responseLog =
+        redactedResponse !== undefined
+          ? `${JSON.stringify(redactedResponse)}`
+          : '(no body)';
+
+      const message = `[${correlationId}] [${requestId}] Outgoing Response: ${method} ${originalUrl} - Status: ${statusCode} - Duration: ${duration}ms - User: ${userId} - Body: ${responseLog}`;
 
       if (statusCode >= 500) {
         this.logger.error(message);

backend/src/common/services/logger.service.spec.ts

@@ -115,4 +115,72 @@ describe('LoggerService', () => {
     service.log({ foo: 'bar' });
     expect(mockWinston.info).toHaveBeenCalledWith('{"foo":"bar"}', expect.any(Object));
   });
+
+  it('redacts sensitive fields in object messages', () => {
+    service.log({ password: 'secret123', username: 'alice' }, 'TestCtx');
+    expect(mockWinston.info).toHaveBeenCalledWith(
+      expect.stringContaining('[REDACTED]'),
+      expect.objectContaining({ context: 'TestCtx' }),
+    );
+    // Verify secret is not in the logged message
+    const [loggedMessage] = mockWinston.info.mock.calls[0];
+    expect(loggedMessage).not.toContain('secret123');
+    expect(loggedMessage).toContain('alice');
+  });
+
+  it('redacts sensitive fields in error messages with objects', () => {
+    service.error({ authorization: 'Bearer token', action: 'login' }, undefined, 'TestCtx');
+    const [loggedMessage] = mockWinston.error.mock.calls[0];
+    expect(loggedMessage).toContain('[REDACTED]');
+    expect(loggedMessage).not.toContain('Bearer token');
+    expect(loggedMessage).toContain('login');
+  });
+
+  it('redacts sensitive fields in warn messages', () => {
+    service.warn({ api_key: 'key-123', status: 'warning' }, 'TestCtx');
+    const [loggedMessage] = mockWinston.warn.mock.calls[0];
+    expect(loggedMessage).toContain('[REDACTED]');
+    expect(loggedMessage).not.toContain('key-123');
+  });
+
+  it('redacts sensitive fields in debug messages', () => {
+    service.debug({ email: 'user@example.com', userId: '123' }, 'TestCtx');
+    const [loggedMessage] = mockWinston.debug.mock.calls[0];
+    expect(loggedMessage).toContain('[REDACTED]');
+    expect(loggedMessage).not.toContain('user@example.com');
+  });
+
+  it('redacts nested sensitive data in objects', () => {
+    service.log(
+      { user: { email: 'secret@example.com', name: 'Bob', wallet_address: 'GAB123' } },
+      'TestCtx',
+    );
+    const [loggedMessage] = mockWinston.info.mock.calls[0];
+    expect(loggedMessage).toContain('[REDACTED]');
+    expect(loggedMessage).not.toContain('secret@example.com');
+    expect(loggedMessage).not.toContain('GAB123');
+    expect(loggedMessage).toContain('Bob');
+  });
+
+  it('does not redact string messages (trusted by caller)', () => {
+    const message = 'User logged in successfully';
+    service.log(message, 'TestCtx');
+    expect(mockWinston.info).toHaveBeenCalledWith(message, expect.any(Object));
+  });
+
+  it('handles arrays of objects with sensitive fields', () => {
+    service.log(
+      [
+        { password: 'p1', name: 'a' },
+        { password: 'p2', name: 'b' },
+      ],
+      'TestCtx',
+    );
+    const [loggedMessage] = mockWinston.info.mock.calls[0];
+    expect(loggedMessage).toContain('[REDACTED]');
+    expect(loggedMessage).not.toContain('p1');
+    expect(loggedMessage).not.toContain('p2');
+    expect(loggedMessage).toContain('a');
+    expect(loggedMessage).toContain('b');
+  });
 });

backend/src/common/services/logger.service.ts

@@ -15,24 +15,37 @@ export class LoggerService implements NestLoggerService {
     return { context: context ?? 'Application', ...this.requestContextService.getLogContext() };
   }
 
+  /**
+   * Convert a message to string, redacting sensitive data if it's an object.
+   * Strings are logged as-is (assumed to be safe by caller).
+   * Objects are redacted before JSON stringification to prevent PII/secrets leakage.
+   */
+  private sanitizeMessage(message: any): string {
+    if (typeof message === 'string') {
+      return message;
+    }
+    const redactedMessage = redact(message);
+    return JSON.stringify(redactedMessage);
+  }
+
   log(message: any, context?: string) {
-    this.logger.info(typeof message === 'string' ? message : JSON.stringify(message), this.meta(context));
+    this.logger.info(this.sanitizeMessage(message), this.meta(context));
   }
 
   error(message: any, trace?: string, context?: string) {
-    this.logger.error(typeof message === 'string' ? message : JSON.stringify(message), { ...this.meta(context), ...(trace ? { trace } : {}) });
+    this.logger.error(this.sanitizeMessage(message), { ...this.meta(context), ...(trace ? { trace } : {}) });
   }
 
   warn(message: any, context?: string) {
-    this.logger.warn(typeof message === 'string' ? message : JSON.stringify(message), this.meta(context));
+    this.logger.warn(this.sanitizeMessage(message), this.meta(context));
   }
 
   debug(message: any, context?: string) {
-    this.logger.debug(typeof message === 'string' ? message : JSON.stringify(message), this.meta(context));
+    this.logger.debug(this.sanitizeMessage(message), this.meta(context));
   }
 
   verbose(message: any, context?: string) {
-    this.logger.verbose(typeof message === 'string' ? message : JSON.stringify(message), this.meta(context));
+    this.logger.verbose(this.sanitizeMessage(message), this.meta(context));
   }
 
   // Method for structured logging