feat(api): unify logger — single source of truth for logs, errors, audit
CI / Test & Lint (push) Has been cancelled
CI / Security audit (push) Has been cancelled

Cherry-picks the unified logger design from the 171c1ad WIP (which Hermes
signed off on as 'Ship this') and applies all Hermes review fixes
(krystie-wip/logger-refactor, 2026-06-15).

  src/utils/logging.js is now the single entry point for:
    - log.info / log.warn / log.error / log.debug  (with level filtering,
      color-coded dev output, JSON prod output)
    - log.audit() / log.auditMiddleware()           (audit-log.json + SKIP_PATHS
      + sensitive-key redaction)
    - logError(ctx, err, extra)                      (writes error.log with
      rotation, request context extraction)
    - safeErrorMessage(err)                          (DC-200 port collision,
      No-such-container, ECONNREFUSED, etc.)

  Existing src/security/audit-logger.js kept untouched — routes/errorlogs.js
  still uses auditLogger.query/clear, no callers migrated.

  Hermes' must-fixes (all addressed):
    [1] Syntax error on logger.js:401 — old logger.js at repo root is gone;
        refactored src/utils/logging.js is the new home, no Chinese IME bug.
    [2] /health/live and /health/ready endpoints — untouched in src/app.js.
    [3] Tests — added __tests__/logging.test.js (18 tests, all pass) covering
        module loads, level filtering, sanitize/audit/auditMiddleware,
        safeErrorMessage, and logError. Full suite: 897/897 pass across 31
        suites (was 879 + 18 new).

  Hermes' should-fixes:
    [4] asyncHandler signature — KEPT 3-arg (logError, fn, context). 49 route
        files still call it this way; src/app.js's boundAsyncHandler unchanged.
    [5] platformPaths.pkiRootCert — UNTOUCHED, still used in src/app.js.
    [6] Five managers (Dependency, AutoRestart, ConfigDrift, SSL, DNS) — ALL
        FIVE still initialized at server boot (verified via test).
    [7] ok(res, ...) helper — UNTOUCHED, all routes still use it.
    [8] Network-intel helpers (isPrivateLan, isTailscaleIP) — UNTOUCHED in
        src/app.js, no duplicate inline logic added.

  - setLevel() now updates both GLOBAL_LEVEL and the singleton log._level,
    so level-filter tests don't pollute later tests.
  - Logger.audit() and Logger.error() now return promises so await works.
  - Logger._log() awaits writeErrorLog so callers using await can rely on
    the error.log being flushed.
  - safeErrorMessage() handles null/undefined explicitly (regression fix —
    String(null) returned 'null' before, now returns 'An internal error
    occurred').
  - src/app.js boundLogError() simplified to 3-arg form matching the
    unified logError(ctx, err, extra) signature.

  - createLogger(level) alias exported so existing src/app.js callers work.
  - logError, safeErrorMessage, LOG_LEVELS still exported.
  - asyncHandler still imported from ./utils/async-handler, not from logging.
  - No changes to routes/* (audit-logger.js still consumed unchanged).

  - jest: 897/897 tests pass across 31 suites
  - node -e "require('./src/app.js')" loads cleanly
  - node server.js boots through full init (all 5 managers start)
  - Color-coded logger output visible in dev mode (no NODE_ENV)
  - JSON output in production mode (NODE_ENV=production)
This commit is contained in:
Krystie
2026-06-19 18:41:26 -07:00
parent 44af47d344
commit f71e5c52d4
3 changed files with 667 additions and 95 deletions
+404 -92
View File
@@ -1,119 +1,431 @@
/**
* Logging utilities - Structured logging and error handling
* 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 fs = require('fs');
const fsp = require('fs').promises;
const path = require('path');
const crypto = require('crypto');
const EventEmitter = require('events');
const LOG_LEVELS = { debug: 0, info: 1, warn: 2, error: 3 };
// ─── Configuration ──────────────────────────────────────────────────────────
/**
* Create a structured logger
*/
function createLogger(LOG_LEVEL) {
function log(level, context, message, data = {}) {
if (LOG_LEVELS[level] < LOG_LEVEL) return;
const entry = {
t: new Date().toISOString(),
level,
ctx: context,
msg: message,
};
if (Object.keys(data).length) entry.data = data;
const fn = level === 'error' ? console.error : level === 'warn' ? console.warn : console.info;
fn(JSON.stringify(entry));
}
log.info = (ctx, msg, data) => log('info', ctx, msg, data);
log.warn = (ctx, msg, data) => log('warn', ctx, msg, data);
log.error = (ctx, msg, data) => log('error', ctx, msg, data);
log.debug = (ctx, msg, data) => log('debug', ctx, msg, data);
return log;
const LOG_DIR = process.env.LOG_DIR || __dirname;
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_COLOUR = { debug: C.dim, info: C.green, warn: C.yellow, error: C.red };
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())}`;
}
/**
* Enhanced error logging with context tracking
*/
async function logError(ERROR_LOG_FILE, MAX_ERROR_LOG_SIZE, context, error, additionalInfo = {}, log) {
const timestamp = new Date().toISOString();
// ─── Console output (dev = pretty, prod = JSON) ─────────────────────────────
// Extract request context
const requestContext = {};
if (additionalInfo.req) {
const req = additionalInfo.req;
const clientIP = req.ip || req.socket?.remoteAddress || '';
requestContext.requestId = req.id;
requestContext.ip = clientIP;
requestContext.userAgent = req.get('user-agent');
requestContext.method = req.method;
requestContext.path = req.path;
delete additionalInfo.req;
function consoleWrite(level, ctx, msg, data) {
if (GLOBAL_LEVEL > LEVELS[level]) return;
if (IS_DEV) {
const colour = LEVEL_COLOUR[level] || C.reset;
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}`);
}
const fn = level === 'error' ? console.error : level === 'warn' ? console.warn : console.log;
fn(parts.join(' '));
} else {
const entry = {
t: new Date().toISOString(), level, ctx, msg,
...(data instanceof Error
? { error: { message: data.message, code: data.code, stack: data.stack } }
: (data && typeof data === 'object' ? { data } : {})),
};
(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);
}
}
async function writeErrorLog(ctx, error, req, extra) {
const ts = new Date().toISOString();
const errMsg = error instanceof Error ? error.message : String(error);
const errStack = error instanceof Error ? error.stack : '';
const parts = [`[${ts}] [ERR] ${ctx}: ${errMsg}`];
if (errStack) parts.push(errStack);
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)) {
clean[k] = SENSITIVE_KEYS.includes(k) ? '***' : v && typeof v === 'object' ? sanitize(v) : 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;
}
const logEntry = {
timestamp,
context,
...requestContext,
error: {
message: error.message || error,
stack: error.stack,
code: error.code
},
...additionalInfo
};
_should(level) {
return LEVELS[level] >= this._level;
}
const contextInfo = Object.keys(requestContext).length > 0
? `\nRequest Context: ${JSON.stringify(requestContext, null, 2)}`
: '';
const logLine = `[${timestamp}] ${context}: ${error.message || error}\n${error.stack || ''}${contextInfo}\nAdditional Info: ${JSON.stringify(additionalInfo, null, 2)}\n${'='.repeat(80)}\n`;
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); }
try {
// Rotate log if it exceeds max size
try {
const stats = await fsp.stat(ERROR_LOG_FILE);
if (stats.size > MAX_ERROR_LOG_SIZE) {
const rotated = ERROR_LOG_FILE + '.1';
const exists = await fsp.access(rotated).then(() => true).catch(() => false);
if (exists) await fsp.unlink(rotated);
await fsp.rename(ERROR_LOG_FILE, rotated);
}
} catch (_) { /* file may not exist yet */ }
await fsp.appendFile(ERROR_LOG_FILE, logLine);
} catch (e) {
if (log && log.error) {
log.error('errorlog', 'Failed to write to error log', { error: e.message });
/**
* 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;
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') {
const errObj = data instanceof Error ? data : (data && data.message ? new Error(data.message) : 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';
}
}
/**
* Return a safe error message without leaking internals
*/
function safeErrorMessage(error) {
const msg = error.message || String(error);
// ─── Global singleton ──────────────────────────────────────────────────────────
// Detect port conflict errors
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')) {
const port = portMatch ? portMatch[1] : 'requested';
return `[DC-200] Port ${port} is already in use. Try a different port or stop the service using that port first.`;
return `[DC-200] Port ${portMatch ? portMatch[1] : 'requested'} is already in use. Try a different port or stop the service using that port first.`;
}
// Only expose short, user-facing messages
if (msg.length < 200 && !msg.includes('/') && !msg.includes('\\') && !msg.includes(' at ')) {
return msg;
}
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) {
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_LEVELS,
createLogger,
logError,
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,
};