feat(security): activate caddy security-event pipeline — bounded first-start replay, self-noise filter, host fidelity (DC-113) [glm-grade=A]

The caddy tail worker (DC-112) was 100% dead in prod: no /var/log/caddy mount, no CADDY_ACCESS_LOG env, no global access log in the Caddyfile. Store census 45,912 events, 100% source_type 'api', ZERO 'caddy'. - createTail: firstStartMaxBytes (5 MiB) bounds first-ever-start replay against a long-lived access.log; multi-chunk partial-line discard on the jump; normal restarts resume at exact persisted offset (judge r1 fix-first fold) - worker: self-noise filter drops our own probe UAs (DashCaddy-Probe/1.0, DashCaddy-HealthCheck/1.0) from the derived store — raw log keeps everything; ~50-100 events/min of probe noise would otherwise bury perimeter signal in the 100k-cap store - worker: metadata.host reads request.host (real caddy JSON nests it; verified against live /var/log/caddy/seeds.log — the DC-112 read was always null on live lines); top-level fallback kept - worker: onAppear recovery log (DC-112 judge polish fold) - start.sh: -v /var/log/caddy:/var/log/caddy:ro + CADDY_ACCESS_LOG env - README: dead caddy-api/ dir refs -> dashcaddy-api/ (queue item e) - tests: +12 DC-113 pins (hermetic, real worker + store); DC-112 fixtures corrected to the real nested request.host shape 126 suites / 2841 tests green. Judge: GLM-5.3 round-1 B, round-2 A (SHIP). Verdict urn:ump:mccln523fptotuvrmddlqpf4zpkrxf273tg4kyytuyy3776rj3pq
2026-08-23 12:40:32 -07:00
parent a29a59a320
commit 65457ff8e0
5 changed files with 402 additions and 17 deletions
@@ -0,0 +1,314 @@
+/**
+ * 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);
+});