Files
dashcaddy/dashcaddy-api/src/utils/logging.js
T
Krystie e99413150e
CI / Test & Lint (push) Canceled after 0s
CI / Security audit (push) Canceled after 0s
[glm-grade=B] fix: dead dashboard WS, corrupted error.log, auth-polling storm, re-auth freeze + CVE bumps
Adversarial audit 2026-08-16 (GLM-5.3 delegate, 2 rounds, 141 tool calls):

P0-1: Dashboard WebSocket (/api/v1/ws) dead on EVERY boot since DC-076.
server.js passed module exports (DependencyManager class, {AutoRestartManager}
namespace, SSLMonitor class) instead of createApp()'s live instances — first
.on() threw ERR_INVALID_ARG_TYPE, catch swallowed it. Fix: app.locals.ctx
exposed in src/app.js; server.js passes all 8 real EventEmitter instances.

P0-2: error.log corrupted since 2026-07-14. errorMiddleware called
logError(FILE, SIZE, path, err, meta) — 5 args into a 3-arg wrapper —
logging 'Error: 5242880' garbage every ~60s and DISCARDING the real error
object. Fix: correct 3-arg call + legacy-shape guard in logErrorWrapper +
~74 log.error sites swept to pass real error objects (AST-verified scope-
safe 71/71, 29/29 modules load clean).

P0-3: auth-polling storm (stranded grade=B commit never landed in prod):
401/403 behind TOTP gate hammered /api/v1/services/status + SSE reconnect
every 2-8s, with misleading direct-probe fallback marking services 'up'.
Fix landed + B-round MEDIUM follow-up: TOTP re-auth success now clears
_dcAuthLost, resumes SSE (new _sseResume clears the latch), and refreshes.

Also: eslintignore static-sites/ (33→0 errors); nodemailer 8→9.0.5 and
sharp 0.33→0.35.3 (3 high CVEs killed; jest green on new majors);
dockerode@5/uuid deferred (semver-major, Docker API surface).

Verification: 80/80 suites, 1837/1837 tests; ESLint 0 errors/743 warnings;
node --check all changed files; bundles rebuilt + SW cache bumped.

Judges: Codex quota-dead until Aug 19 (verified live) — GLM adversarial
delegate per operator directive 2026-08-07. Round 1: 98-call mechanical
verification (timed out pre-verdict). Round 2 (this grade): B, one MEDIUM
(re-auth freeze) — fixed in this commit as prescribed.
2026-08-16 04:18:07 -07:00

458 lines
18 KiB
JavaScript

/**
* 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);
}
}
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)) {
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,
};