redlight/server/middleware/logging.js

import util from 'util';

const SENSITIVE_KEYS = [/pass/i, /pwd/i, /password/i, /token/i, /jwt/i, /secret/i, /authorization/i, /auth/i, /api[_-]?key/i];
const MAX_LOG_BODY_LENGTH = 200000; // 200 KB

function isSensitiveKey(key) {
  return SENSITIVE_KEYS.some(rx => rx.test(key));
}

function filterValue(key, value, depth = 0) {
  if (depth > 5) return '[MAX_DEPTH]';
  if (key && isSensitiveKey(key)) return '[FILTERED]';
  if (value === null || value === undefined) return value;
  if (typeof value === 'string') {
    if (value.length > MAX_LOG_BODY_LENGTH) return '[TOO_LARGE]';
    return value;
  }
  if (typeof value === 'number' || typeof value === 'boolean') return value;
  if (Array.isArray(value)) return value.map(v => filterValue(null, v, depth + 1));
  if (typeof value === 'object') {
    const out = {};
    for (const k of Object.keys(value)) {
      out[k] = filterValue(k, value[k], depth + 1);
    }
    return out;
  }
  return typeof value;
}

function filterHeaders(headers) {
  const out = {};
  for (const k of Object.keys(headers || {})) {
    if (/^authorization$/i.test(k) || /^cookie$/i.test(k)) {
      out[k] = '[FILTERED]';
      continue;
    }
    if (isSensitiveKey(k)) {
      out[k] = '[FILTERED]';
      continue;
    }
    out[k] = headers[k];
  }
  return out;
}

function formatUTC(d) {
  const pad = n => String(n).padStart(2, '0');
  const Y = d.getUTCFullYear();
  const M = pad(d.getUTCMonth() + 1);
  const D = pad(d.getUTCDate());
  const h = pad(d.getUTCHours());
  const m = pad(d.getUTCMinutes());
  const s = pad(d.getUTCSeconds());
  return `${Y}-${M}-${D} ${h}:${m}:${s} UTC`;
}

export default function requestResponseLogger(req, res, next) {
  try {
    const start = Date.now();
    const { method, originalUrl } = req;
    const ip = req.ip || req.headers['x-forwarded-for'] || req.socket.remoteAddress;

    const reqHeaders = filterHeaders(req.headers);

    let reqBody = '[not-logged]';
    const contentType = (req.headers['content-type'] || '').toLowerCase();
    if (contentType.includes('multipart/form-data')) {
      reqBody = '[multipart/form-data]';
    } else if (req.body) {
      try {
        reqBody = filterValue(null, req.body);
      } catch (e) {
        reqBody = '[unserializable]';
      }
    }

    // Capture response body by wrapping res.send
    const oldSend = res.send.bind(res);
    let responseBody = undefined;
    res.send = function sendOverWrite(body) {
      responseBody = body;
      return oldSend(body);
    };

    res.on('finish', () => {
      try {
        const duration = Date.now() - start; // ms
        const resContentType = (res.getHeader && (res.getHeader('content-type') || '')).toString().toLowerCase();

        // Compact key=value log (no bodies, sensitive data filtered)
        const tokens = [];
        tokens.push(`time=${formatUTC(new Date())}`);
        tokens.push(`method=${method}`);
        tokens.push(`path=${originalUrl.replace(/\s/g, '%20')}`);
        const fmt = resContentType.includes('json') ? 'json' : (resContentType.includes('html') ? 'html' : 'other');
        tokens.push(`format=${fmt}`);
        tokens.push(`status=${res.statusCode}`);
        tokens.push(`duration=${(duration).toFixed(2)}`);

        // Optional: content-length if available
        try {
          const cl = res.getHeader && (res.getHeader('content-length') || res.getHeader('Content-Length'));
          if (cl) tokens.push(`length=${String(cl)}`);
        } catch (e) {
          // ignore
        }

        console.info(tokens.join(' '));
      } catch (e) {
        console.error('RequestLogger error:', e);
      }
    });
  } catch (e) {
    console.error('RequestLogger setup failure:', e);
  }

  return next();
}