dashcaddy/dashcaddy-api/__tests__/caddy-worker-pipeline-dc113.test.js

/**
 * DC-113 regression pins — caddy security-event pipeline activation.
 *
 * Background (queue item h, 2026-08-23): the caddy tail worker was fully
 * wired (DC-112 named the gate events) but 100% DEAD in production — no
 * /var/log/caddy mount in the container, no CADDY_ACCESS_LOG env, and no
 * global access log in the Caddyfile. Store census: 45,912 events, 100%
 * source_type 'api', ZERO 'caddy'. DC-113 wires the pipeline:
 *   - global Caddyfile logger `dashcaddy-access` (file /var/log/caddy/
 *     access.log, roll 50MiB keep 5) + `log dashcaddy-access` in every
 *     site block (via caddy-apply, host-side — NOT pinned here)
 *   - start.sh: -v /var/log/caddy:/var/log/caddy:ro + CADDY_ACCESS_LOG env
 *   - worker fixes pinned in THIS file:
 *       1. real caddy JSON nests `host` inside `request` — the top-level
 *          read (DC-112, fixture-shaped) always produced null on live lines
 *       2. self-noise filter: the API's own probes (DashCaddy-Probe/1.0,
 *          DashCaddy-HealthCheck/1.0) hit Caddy every 10-30s per service
 *          and would bury real perimeter signal in the 100k-event store
 *       3. recovered-log visibility (DC-112 judge polish fold): when the
 *          access log appears after startup, one info line is logged
 *
 * All tests use the REAL worker: temp access log, real tail, real event
 * store, hermetic sinks. No mocks of the module under test.
 */

const path = require('path');
const fs = require('fs');
const os = require('os');

// Hermetic sinks (same pattern as caddy-worker-naming-dc112.test.js)
const TMP_DIR = fs.mkdtempSync(path.join(os.tmpdir(), 'dc113-caddy-'));
process.env.SECURITY_EVENT_LOG_FILE = path.join(TMP_DIR, 'security-events.jsonl');
process.env.CADDY_ACCESS_LOG = path.join(TMP_DIR, 'access.log');
process.env.DATA_DIR = TMP_DIR;

const { startCaddyWorker } = require('../src/security/event-workers');
const { getStore } = require('../src/security/event-store');

let capturedWarns = [];
let capturedInfos = [];
const fakeLogger = {
  warn: (ctx, msg, extra) => capturedWarns.push({ ctx, msg, extra }),
  info: (ctx, msg, extra) => capturedInfos.push({ ctx, msg, extra }),
  error: () => {},
};

const ACCESS_LOG = process.env.CADDY_ACCESS_LOG;
const STORE_FILE = process.env.SECURITY_EVENT_LOG_FILE;

function readStored() {
  try {
    return fs.readFileSync(STORE_FILE, 'utf8').trim().split('\n')
      .filter(Boolean).map(l => JSON.parse(l));
  } catch { return []; }
}

async function waitForEvents(n, { timeoutMs = 5000 } = {}) {
  const deadline = Date.now() + timeoutMs;
  while (Date.now() < deadline) {
    const events = readStored().filter(e => e.source_type === 'caddy');
    if (events.length >= n) return events;
    await new Promise(r => setTimeout(r, 50));
  }
  throw new Error(`timed out waiting for ${n} caddy events (got ${readStored().filter(e => e.source_type === 'caddy').length})`);
}

beforeEach(() => {
  fs.writeFileSync(STORE_FILE, '', 'utf8');
  fs.writeFileSync(ACCESS_LOG, '', 'utf8');
  // Reset the tail's persisted offset (same flake lesson as DC-112).
  fs.writeFileSync(path.join(TMP_DIR, '.caddy-tail-offset'), '0', 'utf8');
  capturedWarns = [];
  capturedInfos = [];
  getStore({ log: fakeLogger }); // fresh singleton pointed at the temp store file
});

afterAll(() => {
  try { fs.rmSync(TMP_DIR, { recursive: true, force: true }); } catch {}
});

describe('DC-113: real caddy JSON shape — host nested inside request', () => {
  let worker;
  afterEach(() => { if (worker) { worker.stop(); worker = null; } });

  test('metadata.host reads request.host on live caddy lines (was null pre-DC-113)', async () => {
    // Exact shape from /var/log/caddy/seeds.log on DNS2 (2026-08-23):
    // host is nested in request; headers are arrays.
    fs.appendFileSync(ACCESS_LOG, JSON.stringify({
      level: 'info',
      ts: 1787461432.8595521,
      logger: 'http.log.access.dashcaddy-access',
      msg: 'handled request',
      request: {
        remote_ip: '162.243.83.227',
        remote_port: '57446',
        client_ip: '162.243.83.227',
        proto: 'HTTP/1.1',
        method: 'TRACE',
        host: 'seeds.cryptographic-triangles.org',
        uri: '/',
        headers: { Connection: ['close'], 'User-Agent': ['Mozilla/5.0'] },
        tls: { resumed: false, version: 772, cipher_suite: 4865, proto: 'http/1.1', server_name: 'seeds.cryptographic-triangles.org', ech: false },
      },
      bytes_read: 0,
      user_id: '',
      duration: 0.000070446,
      size: 0,
      status: 404,
    }) + '\n');

    worker = startCaddyWorker({ log: fakeLogger });
    const [ev] = await waitForEvents(1);
    expect(ev.metadata.host).toBe('seeds.cryptographic-triangles.org');
    expect(ev.actor).toBe('162.243.83.227');
    expect(ev.metadata.user_agent).toBe('Mozilla/5.0');
    expect(ev.action).toBe('http.404');
  });

  test('top-level host (DC-112 fixture shape) still parses — backwards compat', async () => {
    fs.appendFileSync(ACCESS_LOG, JSON.stringify({
      ts: 1787500800,
      host: 'plex.sami',
      request: { remote_ip: '10.9.9.9', method: 'GET', uri: '/api/auth/gate/plex', proto: 'HTTP/1.1', headers: { 'User-Agent': ['PlexDBRoulette/1.0'] } },
      status: 401,
      duration: 0.007,
    }) + '\n');
    worker = startCaddyWorker({ log: fakeLogger });
    const [ev] = await waitForEvents(1);
    expect(ev.metadata.host).toBe('plex.sami');
  });
});

describe('DC-113: self-noise filter — probe UAs do not flood the store', () => {
  let worker;
  afterEach(() => { if (worker) { worker.stop(); worker = null; } });

  test('DashCaddy-Probe/1.0 and DashCaddy-HealthCheck/1.0 lines are dropped', async () => {
    const mk = (ua, uri) => JSON.stringify({
      ts: Date.now() / 1000,
      request: { remote_ip: '172.17.0.2', method: 'GET', uri, host: 'plex.sami', headers: { 'User-Agent': [ua] } },
      status: 200,
    });
    fs.appendFileSync(ACCESS_LOG, mk('DashCaddy-Probe/1.0', '/api/health') + '\n');
    fs.appendFileSync(ACCESS_LOG, mk('DashCaddy-HealthCheck/1.0', '/') + '\n');
    fs.appendFileSync(ACCESS_LOG, mk('Mozilla/5.0', '/wp-login.php') + '\n');

    worker = startCaddyWorker({ log: fakeLogger });
    const events = await waitForEvents(1); // only the external line survives
    expect(events.length).toBe(1);
    expect(events[0].metadata.user_agent).toBe('Mozilla/5.0');
    expect(events[0].target).toBe('GET /wp-login.php');
    expect(events[0].actor).toBe('172.17.0.2');
  });

  test('probe-like prefix UA (DashCaddy-Probe/1.1-future) is also filtered', async () => {
    fs.appendFileSync(ACCESS_LOG, JSON.stringify({
      ts: Date.now() / 1000,
      request: { remote_ip: '10.1.1.1', method: 'GET', uri: '/', host: 'x.sami', headers: { 'User-Agent': ['DashCaddy-Probe/1.1-future'] } },
      status: 200,
    }) + '\n');
    worker = startCaddyWorker({ log: fakeLogger });
    await new Promise(r => setTimeout(r, 700)); // tail poll settles
    expect(readStored().filter(e => e.source_type === 'caddy').length).toBe(0);
  });

  test('null/absent UA is NOT filtered (unknown clients stay visible)', async () => {
    fs.appendFileSync(ACCESS_LOG, JSON.stringify({
      ts: Date.now() / 1000,
      request: { remote_ip: '203.0.113.9', method: 'GET', uri: '/admin', host: 'x.sami', headers: {} },
      status: 403,
    }) + '\n');
    worker = startCaddyWorker({ log: fakeLogger });
    const [ev] = await waitForEvents(1);
    expect(ev.metadata.user_agent).toBeNull();
    expect(ev.severity).toBe('warn'); // 403 → warn
  });
});

describe('DC-113: recovered-log visibility (DC-112 judge polish fold)', () => {
  let worker;
  afterEach(() => { if (worker) { worker.stop(); worker = null; } });

  test('info line when the access log appears after startup (missing → present)', async () => {
    // Start with NO access log file at all.
    fs.rmSync(ACCESS_LOG);
    worker = startCaddyWorker({ log: fakeLogger });

    // Wait past one missing-poll cycle (pollMs * 5 = 5s default → but the
    // initial tick is pollMs=1s; give it 1.5s to hit the missing branch).
    await new Promise(r => setTimeout(r, 1500));

    // The file appears (the infra wiring this test models: caddy reload
    // creates /var/log/caddy/access.log; the container mount lands).
    fs.writeFileSync(ACCESS_LOG, '', 'utf8');
    fs.appendFileSync(ACCESS_LOG, JSON.stringify({
      ts: Date.now() / 1000,
      request: { remote_ip: '198.51.100.7', method: 'GET', uri: '/', host: 'status.sami', headers: { 'User-Agent': ['curl/8.0'] } },
      status: 200,
    }) + '\n');

    await waitForEvents(1);
    const infos = capturedInfos.filter(i => /caddy access log active/.test(i.msg));
    expect(infos.length).toBeGreaterThanOrEqual(1);
    expect(infos[0].msg).toContain(ACCESS_LOG);
  });

  test('info line also fires on first poll when the log exists at startup', async () => {
    fs.writeFileSync(ACCESS_LOG, JSON.stringify({
      ts: Date.now() / 1000,
      request: { remote_ip: '198.51.100.8', method: 'GET', uri: '/x', host: 'status.sami', headers: { 'User-Agent': ['curl/8.0'] } },
      status: 200,
    }) + '\n');
    worker = startCaddyWorker({ log: fakeLogger });
    await waitForEvents(1);
    expect(capturedInfos.filter(i => /caddy access log active/.test(i.msg)).length).toBe(1);
  });

  test('onAppear fires once per appearance, not per poll', async () => {
    fs.writeFileSync(ACCESS_LOG, JSON.stringify({
      ts: Date.now() / 1000,
      request: { remote_ip: '198.51.100.9', method: 'GET', uri: '/y', host: 'status.sami', headers: { 'User-Agent': ['curl/8.0'] } },
      status: 200,
    }) + '\n');
    worker = startCaddyWorker({ log: fakeLogger });
    await waitForEvents(1);
    // Extra polls with the file still present must not re-fire.
    await new Promise(r => setTimeout(r, 1500));
    expect(capturedInfos.filter(i => /caddy access log active/.test(i.msg)).length).toBe(1);
  });
});

describe('DC-113 r2: bounded first-start replay (judge fix-first fold)', () => {
  let worker;
  afterEach(() => { if (worker) { worker.stop(); worker = null; } });

  // NOTE: trailing \n is REQUIRED — these lines are join('')ed into the
  // access log; without it the whole tail becomes one unterminated line
  // that never flushes from the tail buffer.
  const mkLine = (ip, path) => JSON.stringify({
    ts: Date.now() / 1000,
    request: { remote_ip: ip, method: 'GET', uri: path, host: 'status.sami', headers: { 'User-Agent': ['curl/8.0'] } },
    status: 200,
  }) + '\n';

  test('first-ever start skips the backlog beyond the 5 MiB cap and drops the partial line', async () => {
    // No persisted offset state file for this scenario.
    fs.rmSync(path.join(TMP_DIR, '.caddy-tail-offset'), { force: true });
    // Build a file beyond the 5 MiB cap WITHOUT flooding the store's write
    // queue: ONE huge filler line (6 MiB of padding) + a normal backlog +
    // the two live tail lines. The cap jump lands inside the huge line —
    // the partial-line discard must skip it entirely, then the backlog
    // lines (post-jump window) and the live tail lines emit.
    const mkFiller = (bytes) => JSON.stringify({
      ts: 1787000000, request: { remote_ip: '10.0.0.1', method: 'GET', uri: '/huge-' + 'x'.repeat(bytes), host: 'status.sami', headers: { 'User-Agent': ['curl/8.0'] } }, status: 200,
    }) + '\n';
    const backlog = [];
    for (let i = 0; i < 40; i++) backlog.push(mkLine('10.0.0.2', '/backlog-' + i));
    const big = [mkFiller(6 * 1024 * 1024), ...backlog, mkLine('203.0.113.101', '/live-1'), mkLine('203.0.113.102', '/live-2')];
    fs.writeFileSync(ACCESS_LOG, big.join(''), 'utf8');
    expect(fs.statSync(ACCESS_LOG).size).toBeGreaterThan(5 * 1024 * 1024 + 1024);

    worker = startCaddyWorker({ log: fakeLogger });

    // Poll until BOTH live tail lines land (cap window = last 5 MiB, which
    // contains the whole normal backlog + tail lines; drains in <2s).
    const deadline = Date.now() + 30000;
    let all = [];
    while (Date.now() < deadline) {
      all = readStored().filter(e => e.source_type === 'caddy');
      const uris = new Set(all.map(e => e.target));
      if (uris.has('GET /live-1') && uris.has('GET /live-2')) break;
      await new Promise(r => setTimeout(r, 150));
    }
    const uris = new Set(all.map(e => e.target));
    expect(uris.has('GET /live-1')).toBe(true);
    expect(uris.has('GET /live-2')).toBe(true);
    // Cap engaged: the huge pre-cap line is GONE (jumped past + partial
    // discard), and the backlog window landed.
    expect(all.length).toBe(42); // 40 backlog + 2 live
    expect(all.some(e => e.target && e.target.includes('/huge-'))).toBe(false);
    // Persisted offset now exists — restart resumes from live.
    expect(fs.existsSync(path.join(TMP_DIR, '.caddy-tail-offset'))).toBe(true);
  }, 45000);

  test('restart with persisted offset replays nothing (no re-emit, no gap)', async () => {
    fs.rmSync(path.join(TMP_DIR, '.caddy-tail-offset'), { force: true });
    fs.writeFileSync(ACCESS_LOG, mkLine('203.0.113.201', '/first') + '\n', 'utf8');
    worker = startCaddyWorker({ log: fakeLogger });
    // Wait for the offset to persist (stream 'end' handler), not just the
    // event to appear — waitForEvents can return before 'end' fires.
    const deadline = Date.now() + 5000;
    while (Date.now() < deadline) {
      if (fs.existsSync(path.join(TMP_DIR, '.caddy-tail-offset'))
          && fs.readFileSync(path.join(TMP_DIR, '.caddy-tail-offset'), 'utf8').trim() !== '0') break;
      await new Promise(r => setTimeout(r, 50));
    }
    worker.stop();
    await new Promise(r => setTimeout(r, 200));

    // New content after the stop. Do NOT truncate the store file: the
    // singleton's memory still holds w1's events and would flush them on
    // the next append, making file line-count useless as a replay oracle.
    // Instead: a replay would append '/first' a SECOND time.
    fs.appendFileSync(ACCESS_LOG, mkLine('203.0.113.202', '/second') + '\n', 'utf8');
    worker = startCaddyWorker({ log: fakeLogger });
    await waitForEvents(2);
    await new Promise(r => setTimeout(r, 300)); // settle
    const all = readStored().filter(e => e.source_type === 'caddy');
    const firsts = all.filter(e => e.target === 'GET /first');
    const seconds = all.filter(e => e.target === 'GET /second');
    expect(firsts.length).toBe(1);  // exactly once — no replay on restart
    expect(seconds.length).toBe(1); // and no gap — new line processed
  }, 15000);
});