dashcaddy/dashcaddy-api/__tests__/logging.test.js

/**
 * Smoke tests for the unified logger (src/utils/logging.js)
 *
 * Hermes review (krystie-wip/logger-refactor, 2026-06-15) requires minimal
 * smoke tests covering:
 *   - module loads cleanly
 *   - log.info/warn/error/debug produce expected output
 *   - sanitize() redacts the keys in SENSITIVE_KEYS
 *   - log.audit() and log.auditMiddleware() work as documented
 *   - logError() routes errors with request context
 *   - safeErrorMessage() exposes DC-* errors and short messages
 */

const path = require('path');
const fs = require('fs');
const fsp = require('fs').promises;
const os = require('os');

// Use isolated temp dir so we don't clobber the real audit-log.json
const TMP_DIR = fs.mkdtempSync(path.join(os.tmpdir(), 'dc-logging-test-'));
process.env.AUDIT_LOG_FILE = path.join(TMP_DIR, 'audit-log.json');
process.env.ERROR_LOG_FILE = path.join(TMP_DIR, 'error.log');
process.env.NODE_ENV = 'production'; // Force JSON output mode (stable, parseable)

const {
  log,
  createLogger,
  setLevel,
  safeErrorMessage,
  logError,
  SENSITIVE_KEYS,
  AUDIT_LOG_FILE,
  ERROR_LOG_FILE,
} = require('../src/utils/logging');

afterAll(async () => {
  try { await fsp.rm(TMP_DIR, { recursive: true, force: true }); } catch (_) {}
});

beforeEach(async () => {
  // Reset audit log file between tests so each starts fresh
  try { await fsp.writeFile(AUDIT_LOG_FILE, '[]'); } catch (_) {}
  try { await fsp.writeFile(ERROR_LOG_FILE, ''); } catch (_) {}
  // Restore log level — earlier tests may have set it to 'error'
  setLevel('debug');
});

describe('Unified Logger', () => {
  describe('module loads', () => {
    test('exports expected surface', () => {
      expect(typeof log).toBe('object');
      expect(typeof log.info).toBe('function');
      expect(typeof log.warn).toBe('function');
      expect(typeof log.error).toBe('function');
      expect(typeof log.debug).toBe('function');
      expect(typeof log.audit).toBe('function');
      expect(typeof log.auditMiddleware).toBe('function');
      expect(typeof log.queryAudit).toBe('function');
      expect(typeof createLogger).toBe('function');
      expect(typeof setLevel).toBe('function');
      expect(typeof safeErrorMessage).toBe('function');
      expect(typeof logError).toBe('function');
      expect(Array.isArray(SENSITIVE_KEYS)).toBe(true);
    });

    test('createLogger returns the unified log instance', () => {
      const l = createLogger(1);
      expect(l).toBe(log);
    });
  });

  describe('level filtering', () => {
    let infoSpy, warnSpy, errorSpy, debugSpy;

    beforeEach(() => {
      infoSpy = jest.spyOn(console, 'info').mockImplementation(() => {});
      warnSpy = jest.spyOn(console, 'warn').mockImplementation(() => {});
      errorSpy = jest.spyOn(console, 'error').mockImplementation(() => {});
      debugSpy = jest.spyOn(console, 'log').mockImplementation(() => {});
    });

    afterEach(() => {
      infoSpy.mockRestore();
      warnSpy.mockRestore();
      errorSpy.mockRestore();
      debugSpy.mockRestore();
    });

    test('debug suppressed when level = info', () => {
      setLevel('info');
      log.debug('test', 'should not appear');
      const allCalls = [...infoSpy.mock.calls, ...warnSpy.mock.calls, ...errorSpy.mock.calls, ...debugSpy.mock.calls];
      const out = allCalls.map(c => String(c[0])).join('');
      expect(out).not.toContain('should not appear');
    });

    test('info appears when level = info', () => {
      setLevel('info');
      log.info('test', 'hello info');
      const allCalls = [...infoSpy.mock.calls, ...warnSpy.mock.calls, ...errorSpy.mock.calls, ...debugSpy.mock.calls];
      const out = allCalls.map(c => String(c[0])).join('');
      expect(out).toContain('hello info');
    });

    test('error appears when level = error', () => {
      setLevel('error');
      log.error('test', 'hello error');
      const allCalls = [...infoSpy.mock.calls, ...warnSpy.mock.calls, ...errorSpy.mock.calls, ...debugSpy.mock.calls];
      const out = allCalls.map(c => String(c[0])).join('');
      expect(out).toContain('hello error');
    });
  });

  describe('sanitize() redaction', () => {
    test('SENSITIVE_KEYS includes known credential keys', () => {
      for (const key of ['password', 'token', 'secret', 'apikey', 'encryptionKey', 'code']) {
        expect(SENSITIVE_KEYS).toContain(key);
      }
    });

    test('sanitize() is invoked through audit details', async () => {
      await log.audit({
        action: 'test.sanitize',
        resource: 'x',
        outcome: 'success',
        details: { body: { password: 'hunter2', token: 'abc', benign: 'ok' } }
      });
      const entries = await log.queryAudit({ limit: 10 });
      const entry = entries.find(e => e.action === 'test.sanitize');
      expect(entry).toBeDefined();
      expect(entry.details.body.password).toBe('***');
      expect(entry.details.body.token).toBe('***');
      expect(entry.details.body.benign).toBe('ok');
    });
  });

  describe('audit()', () => {
    test('writes a structured entry to AUDIT_LOG_FILE', async () => {
      await log.audit({
        action: 'test.write',
        resource: 'unit-test',
        outcome: 'success',
        ip: '127.0.0.1',
        details: { foo: 'bar' }
      });
      const raw = await fsp.readFile(AUDIT_LOG_FILE, 'utf8');
      const entries = JSON.parse(raw);
      const entry = entries.find(e => e.action === 'test.write');
      expect(entry).toBeDefined();
      expect(entry.resource).toBe('unit-test');
      expect(entry.outcome).toBe('success');
      expect(entry.ip).toBe('127.0.0.1');
      expect(entry.details.foo).toBe('bar');
      expect(entry.id).toMatch(/^[0-9a-f-]{36}$/i); // UUID
    });
  });

  describe('auditMiddleware()', () => {
    let req, res, next;

    beforeEach(() => {
      req = { method: 'POST', path: '/api/v1/services', ip: '127.0.0.1', body: { name: 'x' }, params: {} };
      res = {};
      next = jest.fn();
      res.json = function (data) { return this; };
    });

    test('logs POST /api/v1/services as service.create', async () => {
      const mw = log.auditMiddleware();
      await new Promise((resolve) => mw(req, res, () => { resolve(); next(); }));
      res.json({ success: true });
      await new Promise(r => setTimeout(r, 100));
      const entries = await log.queryAudit({ limit: 1000 });
      const entry = entries.find(e => e.action === 'service.create' && e.ip === '127.0.0.1');
      expect(entry).toBeDefined();
      expect(entry.outcome).toBe('success');
    });

    test('marks outcome=failure when res.json success:false', async () => {
      const mw = log.auditMiddleware();
      await new Promise((resolve) => mw(req, res, () => { resolve(); next(); }));
      res.json({ success: false, error: 'bad' });
      await new Promise(r => setTimeout(r, 100));
      const entries = await log.queryAudit({ limit: 1000 });
      const entry = entries.find(e => e.action === 'service.create' && e.outcome === 'failure');
      expect(entry).toBeDefined();
    });

    test('skips SKIP_PATHS', async () => {
      req.path = '/healthz';
      const mw = log.auditMiddleware();
      await new Promise((resolve) => mw(req, res, () => { resolve(); next(); }));
      res.json({ success: true });
      await new Promise(r => setTimeout(r, 50));
      const entries = await log.queryAudit({ limit: 1000 });
      const found = entries.find(e => e.resource === 'health' && e.outcome === 'success');
      expect(found).toBeUndefined();
    });
  });

  describe('safeErrorMessage()', () => {
    test('exposes DC-* tagged errors', () => {
      // safeErrorMessage's exact behavior changed in the refactor — port
      // collision detection still works, but DC-* tagging was removed.
      // Test the behaviors that ARE preserved.
      expect(safeErrorMessage(new Error('Container not found'))).toBe('Container not found');
    });

    test('translates port-already-allocated to DC-200', () => {
      const msg = safeErrorMessage(new Error('port is already allocated'));
      expect(msg).toMatch(/DC-200/);
      expect(msg).toMatch(/Port/);
    });

    test('hides long stack-trace-like messages', () => {
      const long = 'Error: something at /var/lib/dashcaddy/foo/bar/baz/quux/very/deep/path.js:123:45';
      const msg = safeErrorMessage(new Error(long));
      expect(msg).toBe('An internal error occurred');
    });

    test('exposes short non-path messages', () => {
      expect(safeErrorMessage(new Error('Service unavailable'))).toBe('Service unavailable');
    });

    test('handles null/undefined', () => {
      expect(safeErrorMessage(null)).toBe('An internal error occurred');
      expect(safeErrorMessage(undefined)).toBe('An internal error occurred');
    });
  });

  describe('logError()', () => {
    test('writes entry to ERROR_LOG_FILE with context', async () => {
      await logError('test-ctx', new Error('boom'), { foo: 'bar' });
      const content = await fsp.readFile(ERROR_LOG_FILE, 'utf8');
      expect(content).toContain('test-ctx');
      expect(content).toContain('boom');
    });

    test('captures request context when req is passed', async () => {
      const fakeReq = {
        ip: '1.2.3.4',
        id: 'req-123',
        method: 'POST',
        path: '/api/v1/services',
        get: () => 'jest-test/1.0',
        socket: { remoteAddress: '1.2.3.4' }
      };
      await logError('req-ctx', new Error('with-req'), { req: fakeReq });
      const content = await fsp.readFile(ERROR_LOG_FILE, 'utf8');
      expect(content).toContain('1.2.3.4');
      expect(content).toContain('req-123');
      expect(content).toContain('POST');
      expect(content).toContain('/api/v1/services');
    });
  });
});