dashcaddy/dashcaddy-api/src/utils/logging.js

/**
 * DashCaddy Unified Logger
 *
 * Single logging system for the entire application.
 * - Structured JSON to stdout/stderr (pretty-printed in development)
 * - Human-readable errors to error.log with rotation
 * - Audit entries to audit-log.json
 * - All via log.info / log.warn / log.error / log.debug
 *
 * Usage:
 *   const { log } = require('./logger');
 *   log.info('server', 'Server started', { port: 3001 });
 *   log.error('container', 'Failed to start', err, { req });
 *   log.audit({ action: 'service.create', resource: 'nginx', outcome: 'success', ip, details });
 */

const fsp = require('fs').promises;
const path = require('path');
const crypto = require('crypto');
const EventEmitter = require('events');
const platformPaths = require('../../platform-paths');

// ─── Configuration ──────────────────────────────────────────────────────────

const LOG_DIR = process.env.LOG_DIR || platformPaths.dataDir;
const ERROR_LOG_FILE = process.env.ERROR_LOG_FILE || path.join(LOG_DIR, 'error.log');
const AUDIT_LOG_FILE = process.env.AUDIT_LOG_FILE || path.join(LOG_DIR, 'audit-log.json');
const MAX_ERROR_LOG_SIZE = 5 * 1024 * 1024; // 5 MB
const MAX_AUDIT_ENTRIES = 1000;
const AUDIT_MAX_FILE_SIZE = 10 * 1024 * 1024; // 10 MB

const NODE_ENV = process.env.NODE_ENV || 'development';
const IS_DEV = NODE_ENV !== 'production';

// ─── Log levels ───────────────────────────────────────────────────────────────

const LEVELS = { debug: 0, info: 1, warn: 2, error: 3 };

let GLOBAL_LEVEL = IS_DEV ? LEVELS.debug : LEVELS.info;

// ─── Console colours ─────────────────────────────────────────────────────────

const C = {
  reset: '\x1b[0m',
  dim: '\x1b[2m',
  red: '\x1b[31m',
  yellow: '\x1b[33m',
  green: '\x1b[32m',
  cyan: '\x1b[36m',
};

const LEVEL_PREFIX = {
  debug: `${C.dim}[DBG]${C.reset}`,
  info: `${C.green}[INF]${C.reset}`,
  warn: `${C.yellow}[WRN]${C.reset}`,
  error: `${C.red}[ERR]${C.reset}`,
};

// ─── Time formatter ───────────────────────────────────────────────────────────

function pad(n, len = 2) { return String(n).padStart(len, '0'); }
function formatTime() {
  const d = new Date();
  return `${d.getFullYear()}-${pad(d.getMonth()+1)}-${pad(d.getDate())} ${pad(d.getHours())}:${pad(d.getMinutes())}:${pad(d.getSeconds())}`;
}

// ─── Console output (dev = pretty, prod = JSON) ─────────────────────────────

function consoleWrite(level, ctx, msg, data) {
  if (GLOBAL_LEVEL > LEVELS[level]) return;
  if (IS_DEV) {
    const parts = [
      `${C.dim}${formatTime()}${C.reset}`,
      LEVEL_PREFIX[level],
      `${C.cyan}${ctx}${C.reset}`,
      `${msg}`,
    ];
    if (data && typeof data === 'object' && !(data instanceof Error)) {
      parts.push(`${C.dim}${JSON.stringify(data)}${C.reset}`);
    }
    let fn = console.log;
    if (level === 'error') fn = console.error;
    else if (level === 'warn') fn = console.warn;
    fn(parts.join(' '));
  } else {
    let extra;
    if (data instanceof Error) {
      extra = { error: { message: data.message, code: data.code, stack: data.stack } };
    } else if (data && typeof data === 'object') {
      extra = { data };
    } else {
      extra = {};
    }
    const entry = { t: new Date().toISOString(), level, ctx, msg, ...extra };
    (level === 'error' ? console.error : console.info)(JSON.stringify(entry));
  }
}

// ─── Error log file ──────────────────────────────────────────────────────────────

async function appendErrorLog(line) {
  try {
    const stats = await fsp.stat(ERROR_LOG_FILE).catch(() => null);
    if (stats && stats.size > MAX_ERROR_LOG_SIZE) {
      const rotated = ERROR_LOG_FILE + '.1';
      await fsp.unlink(rotated).catch(() => {});
      await fsp.rename(ERROR_LOG_FILE, rotated);
    }
    await fsp.appendFile(ERROR_LOG_FILE, line + '\n');
  } catch (e) {
    console.error('[logger] Failed to write error.log:', e.message);
  }
}

// Flatten an error chain into readable lines so error.log records why a
// request failed, not just that it did. Handle AggregateError (`.errors[]`,
// common from lookups/DNS-fetch timeouts) and the modern `.cause` chain —
// both common in Node 18+ networking. Always returns at least one line
// (a head line with `name [code]: message`), and appends cause lines for
// any `.errors` / `.cause` chains present.
//
// Defensive against:
//  - Circular `.cause` references (a pathological error payload pointing
//    `err.cause = err` would otherwise infinite-recurse and crash the
//    error-path). Visited set carries forward via parameter.
//  - Excessively deep chains (> MAX_CHAIN_DEPTH): truncated with a marker
//    so the operator can see something IS coming from underneath.
const MAX_CHAIN_DEPTH = 16;
function describeErrorChain(err, depth = 0, seen = new WeakSet()) {
  const out = [];
  if (depth > MAX_CHAIN_DEPTH) {
    out.push(`${'  '.repeat(depth)}  ... (chain truncated at depth ${MAX_CHAIN_DEPTH})`);
    return out;
  }
  if (!(err instanceof Error)) {
    out.push(`${'  '.repeat(depth)}${String(err)}`);
    return out;
  }
  // Cycle guard — same Error instance already on the chain.
  if (seen.has(err)) {
    out.push(`${'  '.repeat(depth)}  ... (cycle: same Error instance seen earlier)`);
    return out;
  }
  seen.add(err);
  const indent = '  '.repeat(depth);
  const code = err.code ? ` [${err.code}]` : '';
  const msg = err.message ? `: ${err.message}` : '';
  // For every error (including AggregateError), render the head line; an
  // empty `.message` simply produces `Name [code]:` which is still useful.
  out.push(`${indent}${err.name || 'Error'}${code}${msg}`);
  if (Array.isArray(err.errors) && err.errors.length) {
    err.errors.forEach((sub, i) => {
      out.push(`${indent}  cause #${i + 1}:`);
      out.push(...describeErrorChain(sub, depth + 2, seen));
    });
  }
  if (err.cause instanceof Error) {
    out.push(`${indent}  cause:`);
    out.push(...describeErrorChain(err.cause, depth + 2, seen));
  }
  return out;
}

async function writeErrorLog(ctx, error, req, extra) {
  const ts = new Date().toISOString();
  const errStack = error instanceof Error ? error.stack : '';
  // Build the head line AND a tail diagnostic from the same describeErrorChain,
  // so plain errors with .code get `[CODE]` formatted into the head (regression)
  // and AggregateError with empty `.message` gets a diagnostic block listing
  // every cause (the actual bug fix).
  let headLine;
  let diagLines = [];
  if (error instanceof Error) {
    const chain = describeErrorChain(error);
    // The chain head is always the error itself (now including AggregateError),
    // so chain[0] is what we want in the headline and chain[1..] is the rest.
    headLine = chain[0] || `${error.name || 'Error'}`;
    diagLines = chain.slice(1);
  } else {
    headLine = String(error);
  }
  // Preserve the historical `ctx: <head>` shape so log scrapers don't break.
  // The head now carries `name [code]: message` instead of bare `.message`.
  const parts = [`[${ts}] [ERR] ${ctx}: ${headLine.replace(/^\s+/, '')}`];
  if (errStack) parts.push(errStack);
  if (diagLines.length) parts.push('  diagnostic: ' + diagLines.join('\n  diagnostic: '));
  if (req) {
    const ip = req.ip || req.socket?.remoteAddress || '';
    const ua = req.get ? req.get('user-agent') : '';
    parts.push(`  request: ${req.method || ''} ${req.path || ''} | ip: ${ip} | ua: ${ua}${req.id ? ' | id: ' + req.id : ''}`);
  }
  if (extra && Object.keys(extra).length) {
    parts.push(`  context: ${JSON.stringify(extra)}`);
  }
  parts.push('─'.repeat(72));
  await appendErrorLog(parts.join('\n'));
}

// ─── Audit log ─────────────────────────────────────────────────────────────────

const AUDIT_SKIP_PATHS = [
  '/api/v1/totp/verify',
  '/api/v1/totp/check-session',
  '/api/v1/auth/gate/',
  '/api/v1/auth/app-token/',
  '/api/v1/audit-logs',
  '/api/v1/health',
  '/health',
  '/api/v1/notifications/test',
  '/api/v1/notifications/health-check',
];

const AUDIT_ACTION_MAP = {
  'POST /api/v1/services/update': 'service.reorder',
  'POST /api/v1/services': 'service.create',
  'PUT /api/v1/services': 'service.update',
  'DELETE /api/v1/services/': 'service.delete',
  'POST /api/v1/site': 'caddy.add-site',
  'POST /api/v1/site/external': 'caddy.add-external',
  'DELETE /api/v1/site/': 'caddy.remove-site',
  'POST /api/v1/caddy/reload': 'caddy.reload',
  'POST /api/v1/dns/record': 'dns.add-record',
  'DELETE /api/v1/dns/record': 'dns.delete-record',
  'POST /api/v1/dns/credentials': 'dns.save-credentials',
  'DELETE /api/v1/dns/credentials': 'dns.delete-credentials',
  'POST /api/v1/dns/refresh-token': 'dns.refresh-token',
  'POST /api/v1/dns/update': 'dns.update-server',
  'POST /api/v1/containers/': 'container.action',
  'DELETE /api/v1/containers/': 'container.delete',
  'POST /api/v1/apps/deploy': 'container.deploy',
  'DELETE /api/v1/apps/': 'container.undeploy',
  'POST /api/v1/backups/execute': 'backup.execute',
  'POST /api/v1/backups/restore/': 'backup.restore',
  'POST /api/v1/backups/config': 'backup.config',
  'POST /api/v1/config': 'config.update',
  'DELETE /api/v1/config': 'config.reset',
  'POST /api/v1/notifications/config': 'config.notifications',
  'POST /api/v1/totp/setup': 'auth.totp-setup',
  'POST /api/v1/totp/verify-setup': 'auth.totp-activate',
  'POST /api/v1/totp/disable': 'auth.totp-disable',
  'POST /api/v1/totp/config': 'auth.totp-config',
  'POST /api/v1/credentials/rotate-key': 'config.rotate-key',
  'POST /api/v1/updates/update/': 'container.update',
  'POST /api/v1/updates/rollback/': 'container.rollback',
  'POST /api/v1/updates/auto-update/': 'container.auto-update',
  'POST /api/v1/updates/check': 'container.check-updates',
  'POST /api/v1/health-checks/': 'config.health-check',
  'DELETE /api/v1/health-checks/': 'config.health-check-delete',
  'POST /api/v1/monitoring/alerts/': 'config.monitoring-alert',
  'DELETE /api/v1/monitoring/alerts/': 'config.monitoring-alert-delete',
  'POST /api/v1/arr/smart-connect': 'service.arr-connect',
  'POST /api/v1/arr/credentials': 'config.arr-credentials',
  'DELETE /api/v1/arr/credentials/': 'config.arr-credentials-delete',
  'POST /api/v1/logo': 'config.logo-upload',
  'DELETE /api/v1/logo': 'config.logo-delete',
  'POST /api/v1/favicon': 'config.favicon-upload',
  'DELETE /api/v1/favicon': 'config.favicon-delete',
  'POST /api/v1/tailscale/config': 'config.tailscale',
  'POST /api/v1/tailscale/protect-service': 'config.tailscale-protect',
};

const SENSITIVE_KEYS = ['password', 'token', 'secret', 'apikey', 'encryptionKey', 'code', 'secretKey', 'authToken'];

function sanitize(obj) {
  if (!obj || typeof obj !== 'object') return obj;
  const clean = Array.isArray(obj) ? [] : {};
  for (const [k, v] of Object.entries(obj)) {
    if (SENSITIVE_KEYS.includes(k)) {
      clean[k] = '***';
    } else if (v && typeof v === 'object') {
      clean[k] = sanitize(v);
    } else {
      clean[k] = v;
    }
  }
  return clean;
}

async function appendAuditLog(entries) {
  try {
    let existing = [];
    try {
      const raw = await fsp.readFile(AUDIT_LOG_FILE, 'utf8');
      existing = JSON.parse(raw);
      if (!Array.isArray(existing)) existing = [];
    } catch (_) { /* start fresh */ }

    const merged = [...entries, ...existing].slice(0, MAX_AUDIT_ENTRIES);
    const stats = await fsp.stat(AUDIT_LOG_FILE).catch(() => null);
    if (stats && stats.size > AUDIT_MAX_FILE_SIZE) {
      await fsp.writeFile(AUDIT_LOG_FILE, JSON.stringify(merged.slice(0, Math.floor(MAX_AUDIT_ENTRIES / 2)), null, 2));
    } else {
      await fsp.writeFile(AUDIT_LOG_FILE, JSON.stringify(merged, null, 2));
    }
  } catch (e) {
    console.error('[logger] Failed to write audit log:', e.message);
  }
}

// ─── Main Logger class ──────────────────────────────────────────────────────────

class Logger extends EventEmitter {
  constructor() {
    super();
    this._level = GLOBAL_LEVEL;
  }

  _should(level) {
    return LEVELS[level] >= this._level;
  }

  debug(ctx, msg, data) { this._log('debug', ctx, msg, data); }
  info(ctx, msg, data) { this._log('info', ctx, msg, data); }
  warn(ctx, msg, data) { this._log('warn', ctx, msg, data); }

  /**
   * Log an error — always writes to error.log and console.
   * @param {string} ctx — context label (e.g. 'container', 'dns')
   * @param {Error|string} err — the error
   * @param {object} req — optional request for request context
   * @param {object} extra — extra context data (not the error itself)
   */
  error(ctx, err, req, extra) {
    const errObj = err instanceof Error ? err : new Error(String(err));
    const payload = extra && Object.keys(extra).length ? extra : undefined;
    // Return the promise from _log so callers that `await log.error(...)` /
    // `await logError(...)` actually wait for the error.log write to flush.
    // _log returns the writeErrorLog(...) promise for level === 'error'.
    return this._log('error', ctx, errObj.message, errObj, { req, payload });
  }

  _log(level, ctx, msg, data, { req, payload } = {}) {
    if (LEVELS[level] < this._level) return;

    const entry = {
      t: new Date().toISOString(), level, ctx, msg,
      ...(data instanceof Error ? { error: { message: data.message, code: data.code, stack: data.stack } } : {}),
      ...(payload ? { data: payload } : {}),
    };
    if (req && (req.id || req.ip || req.path)) {
      entry.requestId = req.id || null;
      entry.ip = req.ip || req.socket?.remoteAddress || null;
      entry.method = req.method || null;
      entry.path = req.path || null;
    }
    this.emit('entry', entry);
    consoleWrite(level, ctx, msg, data);

    if (level === 'error') {
      let errObj;
      if (data instanceof Error) {
        errObj = data;
      } else if (data && data.message) {
        errObj = new Error(data.message);
      } else {
        errObj = new Error(msg);
      }
      // Await the error log write so callers using await on log.error()
      // can rely on the file being flushed before proceeding.
      return writeErrorLog(ctx, errObj, req, payload);
    }
  }

  /**
   * Emit an audit entry directly
   */
  async audit({ action, resource, details, outcome, ip }) {
    const entry = {
      id: crypto.randomUUID(),
      timestamp: new Date().toISOString(),
      ip: ip || '',
      action: action || '',
      resource: resource || '',
      details: details ? sanitize(details) : {},
      outcome: outcome || 'unknown',
    };
    await appendAuditLog([entry]);
    return entry;
  }

  /**
   * Express audit middleware — call app.use(log.auditMiddleware()) once
   */
  auditMiddleware() {
    return (req, res, next) => {
      if (req.method === 'GET') return next();
      if (AUDIT_SKIP_PATHS.some(p => req.path.startsWith(p))) return next();

      const originalJson = res.json.bind(res);
      res.json = (body) => {
        const action = this._resolveAuditAction(req.method, req.path);
        const resource = this._resolveAuditResource(req.path);
        const outcome = body && body.success === false ? 'failure' : 'success';
        const ip = req.ip || req.socket?.remoteAddress || '';
        const details = {};
        if (req.params && Object.keys(req.params).length) details.params = req.params;
        if (req.body) details.body = sanitize(req.body);

        this.audit({ action, resource, details, outcome, ip });
        return originalJson(body);
      };
      next();
    };
  }

  _resolveAuditAction(method, urlPath) {
    const key = `${method} ${urlPath}`;
    if (AUDIT_ACTION_MAP[key]) return AUDIT_ACTION_MAP[key];
    for (const [pattern, action] of Object.entries(AUDIT_ACTION_MAP)) {
      if (key.startsWith(pattern)) return action;
    }
    const parts = urlPath.replace('/api/v1/', '').split('/');
    return `${parts[0] || 'unknown'}.${method.toLowerCase()}`;
  }

  _resolveAuditResource(urlPath) {
    const parts = urlPath.replace('/api/v1/', '').split('/');
    if (parts.length >= 2) return parts.slice(1).join('/');
    return parts[0] || '';
  }

  /**
   * Query audit log entries
   */
  async queryAudit({ limit = 50, offset = 0, action } = {}) {
    try {
      let entries = JSON.parse(await fsp.readFile(AUDIT_LOG_FILE, 'utf8'));
      if (!Array.isArray(entries)) entries = [];
      if (action) entries = entries.filter(e => e.action && e.action.startsWith(action));
      return entries.slice(offset, offset + limit);
    } catch (_) {
      return [];
    }
  }

  clearAuditLog() {
    return fsp.writeFile(AUDIT_LOG_FILE, JSON.stringify([])).catch(() => {});
  }

  /**
   * Read error log (raw lines from error.log + error.log.1)
   */
  async readErrorLog(tail = 100) {
    const results = [];
    for (const file of [ERROR_LOG_FILE, ERROR_LOG_FILE + '.1']) {
      try {
        const lines = (await fsp.readFile(file, 'utf8')).split('\n').filter(Boolean);
        results.push(...lines.map(l => ({ file: path.basename(file), text: l })));
      } catch (_) { /* missing */ }
    }
    return results.slice(-tail);
  }

  setLevel(lvl) {
    if (lvl in LEVELS) this._level = LEVELS[lvl];
  }

  getLevel() {
    return Object.entries(LEVELS).find(([, v]) => v === this._level)?.[0] ?? 'debug';
  }
}

// ─── Global singleton ──────────────────────────────────────────────────────────

const log = new Logger();

// ─── Safe error messages ─────────────────────────────────────────────────────────

function safeErrorMessage(error) {
  if (!error) return 'An internal error occurred';
  const msg = error.message || String(error);
  const portMatch = msg.match(/exposing port TCP [^:]*:(\d+)/);
  if (portMatch || msg.includes('port is already allocated') || msg.includes('ports are not available')) {
    return `[DC-200] Port ${portMatch ? portMatch[1] : 'requested'} is already in use. Try a different port or stop the service using that port first.`;
  }
  if (msg.includes('No such container')) return 'Container not found';
  if (msg.includes('ECONNREFUSED') || msg.includes('ETIMEDOUT')) return 'Service unavailable';
  if (msg.length < 200 && !msg.includes('/') && !msg.includes('\\') && !msg.includes(' at ')) return msg;
  return 'An internal error occurred';
}

// ─── Convenience wrapper compatible with the old logError(logDir)() signature ──────
// Supports: logError(context, error, extra) → existing route call pattern

async function logErrorWrapper(ctx, err, extra) {
  // Guard against legacy call shapes that used to corrupt error.log:
  // the old 5-arg form logError(file, maxSize, path, err, meta) made ctx
  // a file path and turned maxSize (a number) into the "error". Detect and
  // normalize so the real error always reaches error.log.
  if (typeof ctx === 'string' && /^\/.*\.(log|json)$/.test(ctx) && typeof err === 'number') {
    // Legacy shape: (file, size, reqPath, error, meta) → shift args.
    [ctx, err, extra] = [arguments[2], arguments[3], { ...arguments[4], req: undefined }];
  }
  const req = extra?.req;
  const payload = extra ? { ...extra } : {};
  if (payload.req) delete payload.req;
  await log.error(ctx, err instanceof Error ? err : new Error(String(err)), req, payload);
}

// ─── Exports ─────────────────────────────────────────────────────────────────────

module.exports = {
  log,
  setLevel: (lvl) => {
    if (lvl in LEVELS) {
      GLOBAL_LEVEL = LEVELS[lvl];
      log.setLevel(lvl);  // also update the singleton instance
    }
  },
  // Backwards-compatible alias: older callers (src/app.js) use createLogger(LOG_LEVEL)
  // and expect a `log.info/warn/error/debug` function back. The unified logger is
  // a single global instance, so we set the level and return it.
  createLogger: (level) => { if (level in LEVELS) GLOBAL_LEVEL = LEVELS[level]; return log; },
  safeErrorMessage,
  logError: logErrorWrapper,
  AUDIT_LOG_FILE,
  ERROR_LOG_FILE,
  MAX_ERROR_LOG_SIZE,
  MAX_AUDIT_ENTRIES,
  AUDIT_SKIP_PATHS,
  AUDIT_ACTION_MAP,
  SENSITIVE_KEYS,
};