Request and Response Logging

Request and response logging provides visibility into API interactions. Learn to implement detailed request/response logging for debugging and auditing.

Challenge

Implement comprehensive request/response logging that captures essential information while protecting sensitive data and maintaining performance.

Explanation

What to Log

Request: Method, URL, headers, body
Response: Status code, headers, body
Timing: Duration, latency
Context: User ID, session, IP
Errors: Status codes >= 400

Logging Considerations

Avoid logging sensitive data
Balance verbosity with performance
Consider storage and retention
Implement sampling for high-volume

Code Examples

1. Basic Request/Response Logger

const express = require('express');
const morgan = require('morgan');

const app = express();

// Morgan middleware
app.use(morgan('combined'));

// Custom Morgan format
morgan.token('user-id', (req) => req.user?.id || 'anonymous');

app.use(morgan(':method :url :status - :user-id [:date[clf]] - :response-time ms'));

// Detailed custom logging
app.use((req, res, next) => {
  const startTime = Date.now();

  res.on('finish', () => {
    const duration = Date.now() - startTime;

    console.log({
      timestamp: new Date().toISOString(),
      method: req.method,
      url: req.originalUrl,
      status: res.statusCode,
      duration: `${duration}ms`,
      contentLength: res.get('content-length'),
      userAgent: req.get('user-agent'),
      ip: req.ip,
    });
  });

  next();
});

app.get('/api/users', (req, res) => {
  res.json({ users: [] });
});

app.listen(3000);

2. Detailed Request/Response Middleware

class RequestResponseLogger {
  constructor(options = {}) {
    this.logHeaders = options.logHeaders || false;
    this.logBody = options.logBody || false;
    this.excludeUrls = options.excludeUrls || ['/health'];
    this.sensitiveFields = options.sensitiveFields || ['password', 'token', 'apiKey'];
    this.maxBodySize = options.maxBodySize || 1000; // characters
  }

  middleware() {
    return (req, res, next) => {
      // Skip excluded URLs
      if (this.excludeUrls.some(url => req.path.includes(url))) {
        return next();
      }

      const startTime = process.hrtime.bigint();

      // Capture request body
      let requestBody = '';
      if (this.logBody && req.method !== 'GET') {
        req.on('data', (chunk) => {
          requestBody += chunk.toString();
        });
      }

      // Intercept response
      const originalJson = res.json;
      const originalSend = res.send;
      let responseBody = '';

      res.json = function(data) {
        responseBody = JSON.stringify(data);
        return originalJson.call(this, data);
      };

      res.send = function(data) {
        responseBody = data;
        return originalSend.call(this, data);
      };

      res.on('finish', () => {
        const duration = Number(process.hrtime.bigint() - startTime) / 1000000;

        const logEntry = {
          timestamp: new Date().toISOString(),
          method: req.method,
          path: req.path,
          query: req.query,
          status: res.statusCode,
          duration: `${duration.toFixed(2)}ms`,
          ip: req.ip,
          userAgent: req.get('user-agent'),
        };

        if (this.logHeaders) {
          logEntry.requestHeaders = this.sanitize(req.headers);
          logEntry.responseHeaders = this.sanitize(res.getHeaders());
        }

        if (this.logBody) {
          if (requestBody.length > 0) {
            logEntry.requestBody = this.sanitize(
              JSON.parse(requestBody || '{}')
            );
          }
          if (responseBody.length > 0 && responseBody.length < this.maxBodySize) {
            logEntry.responseBody = responseBody;
          }
        }

        console.log(JSON.stringify(logEntry));
      });

      next();
    };
  }

  sanitize(data) {
    if (typeof data !== 'object') return data;

    const sanitized = JSON.parse(JSON.stringify(data));

    const traverse = (obj) => {
      Object.keys(obj).forEach(key => {
        if (this.sensitiveFields.some(field =>
          key.toLowerCase().includes(field)
        )) {
          obj[key] = '***REDACTED***';
        } else if (typeof obj[key] === 'object' && obj[key] !== null) {
          traverse(obj[key]);
        }
      });
    };

    traverse(sanitized);
    return sanitized;
  }
}

// Usage
const logger = new RequestResponseLogger({
  logHeaders: true,
  logBody: true,
  sensitiveFields: ['password', 'token', 'apiKey', 'ssn'],
});

app.use(logger.middleware());

3. Request ID Tracking

const uuid = require('uuid');

class RequestIDMiddleware {
  middleware() {
    return (req, res, next) => {
      // Use provided request ID or generate new one
      req.id = req.headers['x-request-id'] || uuid.v4();

      // Set response header
      res.setHeader('X-Request-ID', req.id);

      // Add to context for all logs
      req.logger = {
        info: (msg, meta) => console.log({
          requestId: req.id,
          message: msg,
          ...meta,
        }),
        error: (msg, meta) => console.error({
          requestId: req.id,
          message: msg,
          ...meta,
        }),
      };

      next();
    };
  }
}

// Usage
app.use(new RequestIDMiddleware().middleware());

app.post('/api/process', (req, res) => {
  req.logger.info('Processing request', { userId: req.user?.id });
  // ... process
  res.json({ success: true });
});

4. Performance Monitoring Logging

class PerformanceLogger {
  constructor(threshold = 1000) {
    this.threshold = threshold; // ms
    this.metrics = [];
  }

  middleware() {
    return (req, res, next) => {
      const startTime = process.hrtime.bigint();
      const startMemory = process.memoryUsage().heapUsed;

      res.on('finish', () => {
        const duration = Number(process.hrtime.bigint() - startTime) / 1000000;
        const memoryUsed = process.memoryUsage().heapUsed - startMemory;

        const metric = {
          timestamp: new Date().toISOString(),
          method: req.method,
          path: req.path,
          status: res.statusCode,
          duration,
          memory: memoryUsed,
        };

        this.metrics.push(metric);

        if (duration > this.threshold) {
          console.warn('Slow request detected', {
            ...metric,
            threshold: this.threshold,
          });
        }

        // Keep only recent metrics
        if (this.metrics.length > 1000) {
          this.metrics = this.metrics.slice(-1000);
        }
      });

      next();
    };
  }

  getAverageResponseTime(path) {
    const metrics = this.metrics.filter(m => m.path === path);
    if (metrics.length === 0) return 0;

    const sum = metrics.reduce((total, m) => total + m.duration, 0);
    return sum / metrics.length;
  }

  getSlowEndpoints(limit = 10) {
    const grouped = {};

    this.metrics.forEach(m => {
      if (!grouped[m.path]) {
        grouped[m.path] = [];
      }
      grouped[m.path].push(m);
    });

    return Object.entries(grouped)
      .map(([path, metrics]) => ({
        path,
        avgDuration: metrics.reduce((sum, m) => sum + m.duration, 0) / metrics.length,
        maxDuration: Math.max(...metrics.map(m => m.duration)),
        count: metrics.length,
      }))
      .sort((a, b) => b.avgDuration - a.avgDuration)
      .slice(0, limit);
  }
}

// Usage
const perfLogger = new PerformanceLogger(500); // 500ms threshold
app.use(perfLogger.middleware());

app.get('/admin/performance', (req, res) => {
  res.json({
    slowEndpoints: perfLogger.getSlowEndpoints(),
    allMetrics: perfLogger.metrics,
  });
});

5. Structured Request/Response Logging

const pino = require('pino');

const logger = pino({
  serializers: {
    req: (req) => ({
      id: req.id,
      method: req.method,
      url: req.url,
      headers: req.headers,
      remoteAddress: req.socket.remoteAddress,
      remotePort: req.socket.remotePort,
    }),
    res: (res) => ({
      statusCode: res.statusCode,
      headers: res.getHeaders(),
    }),
  },
});

app.use((req, res, next) => {
  req.id = require('uuid').v4();

  res.on('finish', () => {
    logger.info(
      {
        req,
        res,
        duration: Date.now() - res.startTime,
      },
      'Request completed'
    );
  });

  res.startTime = Date.now();
  next();
});

Best Practices

Data Protection
- Redact sensitive information
- Don’t log passwords or tokens
- Protect PII
- Use encryption for storage
Performance
- Use asynchronous logging
- Implement sampling for high volume
- Rotate log files
- Archive old logs
Usefulness
- Include request ID for tracing
- Log meaningful information
- Include error details
- Document logging format
Compliance
- Follow data retention policies
- Respect user privacy
- Maintain audit trails
- Comply with regulations
Maintenance
- Monitor log size
- Clean up old logs
- Document logging standards
- Review log queries

Real-World Applications

Debugging: Trace request flow
Auditing: Track user actions
Performance Analysis: Identify bottlenecks
Security: Detect suspicious activity
Compliance: Maintain audit trails