olp/lib/audit.mjs

/**
 * lib/audit.mjs — OLP audit ndjson append (Phase 2 / D45)
 *
 * Authority: ADR 0007 § 6.2 (audit append semantics) + § 8 (event schema).
 *
 * Behaviour:
 *   - One JSON event per line; newline-terminated; UTF-8.
 *   - Append to ~/.olp/logs/audit.ndjson (chmod 0600 file, 0700 dir).
 *   - On append failure: log a warn ('audit_append_failed_once') + retry
 *     once synchronously.
 *   - On second-failure: increment per-process drop counter + log warn
 *     ('audit_append_dropped'); NEVER throw to the caller (audit is
 *     observability, not authorization). Per § 6.2.
 *   - No memory buffer at Phase 2 (forward-path note in ADR § 13).
 *
 * Atomicity note: Node's `fs.appendFileSync` opens with O_APPEND which is
 * POSIX-atomic for writes <= PIPE_BUF (typically 4096 bytes). Our event
 * payloads (§ 8 schema with hash + shape fields, no PII / no message
 * content) are well under that limit, so concurrent in-process appends
 * are line-atomic without explicit locking.
 *
 * No PII: § 8 explicitly excludes request body, response body, and IR
 * message content. Hash + shape only.
 */

import { appendFileSync, mkdirSync, chmodSync, renameSync, existsSync, statSync, readFileSync } from 'node:fs';
import { join } from 'node:path';
import { homedir } from 'node:os';

const DEFAULT_OLP_HOME = join(homedir(), '.olp');
const OLP_HOME_ENV = 'OLP_HOME';
const RETRY_COUNT = 1; // § 6.2: warn + 1 retry
const LIVE_AUDIT_FILE = 'audit.ndjson';
const ROTATED_FILE_PREFIX = 'audit-';
const ROTATED_FILE_SUFFIX = '.ndjson';

let _dropCounter = 0;
let _rotateCounter = 0;       // observability + test assertion target
let _rotateFailCounter = 0;
// Module-cached "last UTC date we saw at append time" so we don't read
// disk metadata on every append just to check for rotation.
let _lastSeenUtcDate = _utcDateNow();

/**
 * Resolve OLP home dir (matches lib/keys.mjs precedence): opts.olpHome →
 * process.env.OLP_HOME → ~/.olp. Resolved per call so tests setting the
 * env mid-run take effect.
 */
function _resolveOlpHome(opts) {
  if (opts?.olpHome) return opts.olpHome;
  if (process.env[OLP_HOME_ENV]) return process.env[OLP_HOME_ENV];
  return DEFAULT_OLP_HOME;
}

/**
 * Current UTC date as YYYY-MM-DD. Module-private; reused by rotation logic.
 */
function _utcDateNow() {
  return new Date().toISOString().slice(0, 10);
}

/**
 * Read the first event's `ts` from the live audit file to discover the
 * date it was opened on (for stale-cache recovery when the process is
 * restarted and the in-memory `_lastSeenUtcDate` doesn't match). Returns
 * the YYYY-MM-DD string, or null if the file is missing / empty /
 * malformed.
 */
function _firstEventDateInLiveFile(livePath) {
  try {
    if (!existsSync(livePath)) return null;
    // Read the file + slice off the first ndjson line. For audit ndjson the
    // first line is at most a few hundred bytes; this is fine for the rare
    // "process restart with a stale live file" recovery path. (Family-scale
    // single-file audit is bounded; multi-MB scans are not a real concern
    // until Phase 4+ when Option 3 SQLite migration would kick in anyway.)
    const raw = readFileSync(livePath, 'utf-8');
    const nl = raw.indexOf('\n');
    const firstLine = nl === -1 ? raw : raw.slice(0, nl);
    if (!firstLine) return null;
    const obj = JSON.parse(firstLine);
    if (typeof obj?.ts !== 'string') return null;
    return obj.ts.slice(0, 10);
  } catch {
    return null;
  }
}

/**
 * Rotate the live audit file (if any) to its UTC-date suffix. Idempotent:
 * if a rotated file with that name already exists (e.g., cron beat us to
 * it), this skips the rename.
 *
 * Per ADR 0008 § 5.1 + § 5.3. SYNCHRONOUS so callers (appendAuditEvent +
 * external cron) can rely on it completing before the next IO operation.
 * Sync rotation eliminates the race that an async wrapper would create
 * between the date-change-detection and the append (where the append could
 * land in the old un-rotated file).
 *
 * Concurrent in-process invocations: Node's single-threaded event loop
 * serializes synchronous calls within a tick. Cross-tick concurrency
 * uses the `_lastSeenUtcDate` cache as the gate — once set, subsequent
 * appends short-circuit the rotation check.
 *
 * @param {object} args - { olpHome, logEvent, _nowFn (test injection) }
 * @returns {{ rotated: boolean, fromPath?: string, toPath?: string, dateUsed?: string }}
 */
export function _maybeRotateAudit(args = {}) {
  const olpHome = _resolveOlpHome(args);
  const logEvent = args.logEvent ?? ((level, ev, data) => {
    const entry = { ts: new Date().toISOString(), level, event: ev, ...(data ?? {}) };
    process.stderr.write(JSON.stringify(entry) + '\n');
  });
  const nowFn = args._nowFn ?? (() => new Date());

  const logsDir = join(olpHome, 'logs');
  const livePath = join(logsDir, LIVE_AUDIT_FILE);
  if (!existsSync(livePath)) {
    // No live file yet (first append ever); no rotation needed.
    _lastSeenUtcDate = nowFn().toISOString().slice(0, 10);
    return { rotated: false };
  }
  // Determine the "date the live file holds" — use the first event's ts.
  // Fall back to file mtime if events absent (corrupt / empty file edge).
  let fileDate = _firstEventDateInLiveFile(livePath);
  if (fileDate === null) {
    try {
      fileDate = statSync(livePath).mtime.toISOString().slice(0, 10);
    } catch {
      return { rotated: false };
    }
  }
  const today = nowFn().toISOString().slice(0, 10);
  if (fileDate === today) {
    _lastSeenUtcDate = today;
    return { rotated: false };
  }

  // Rotate: rename live → audit-<fileDate>.ndjson.
  const rotatedName = `${ROTATED_FILE_PREFIX}${fileDate}${ROTATED_FILE_SUFFIX}`;
  const rotatedPath = join(logsDir, rotatedName);
  if (existsSync(rotatedPath)) {
    // Cron or another writer beat us; the live file holding fileDate's
    // events must be merged manually. Per ADR 0008 § 5.3 we log + skip.
    logEvent('warn', 'audit_rotate_target_exists', {
      livePath, rotatedPath,
      message: 'rotation target exists — concurrent rotator beat in-process check; manual merge required if events overlap',
    });
    _lastSeenUtcDate = today;
    return { rotated: false };
  }
  try {
    renameSync(livePath, rotatedPath);
    _rotateCounter++;
    _lastSeenUtcDate = today;
    logEvent('info', 'audit_rotated', { fromPath: livePath, toPath: rotatedPath, dateUsed: fileDate });
    return { rotated: true, fromPath: livePath, toPath: rotatedPath, dateUsed: fileDate };
  } catch (err) {
    _rotateFailCounter++;
    logEvent('warn', 'audit_rotate_failed', {
      livePath, rotatedPath,
      error: err?.message ?? String(err),
    });
    // Don't update _lastSeenUtcDate so the next append retries.
    return { rotated: false };
  }
}

/**
 * Append a single audit event to ~/.olp/logs/audit.ndjson.
 *
 * @param {object} event - § 8 schema fields (ts, key_id, owner_tier,
 *   method, path, provider, model, status_code, latency_ms, cache_status,
 *   fallback_hops, tried_providers, error_code, ir_request_hash, chain_id).
 *   Caller is responsible for populating fields; missing fields are
 *   serialized as undefined → omitted by JSON.stringify.
 *
 *   cache_status enum (free-form string; not schema-validated at append):
 *     'hit'                 — served from cache (buffered-replay or streaming
 *                              cache_hit role from ADR 0005 Amendment 8 §1).
 *     'miss'                — buffered or streaming source path; provider
 *                              spawn fired for this request.
 *     'bypass'              — D2 cache_control bypass (no cache read/write).
 *     'streaming_attached'  — D58 / ADR 0005 Amendment 8 §11: client joined
 *                              an in-flight streaming source spawn from
 *                              another caller; this request did NOT spawn a
 *                              provider but also did NOT hit the cache (the
 *                              cache was empty at the inflight Map check).
 *     null                  — pre-chain error paths (the cache layer was
 *                              never consulted; e.g. 401, 415, 400 IR).
 * @param {object} [opts]
 * @param {string} [opts.olpHome] - test override; defaults to ~/.olp
 * @param {(level: string, event: string, data?: object) => void} [opts.logEvent]
 *   - injectable structured logger; defaults to console.warn with JSON line
 */
export function appendAuditEvent(event, opts = {}) {
  const olpHome = _resolveOlpHome(opts);
  const logsDir = join(olpHome, 'logs');
  const path = join(logsDir, LIVE_AUDIT_FILE);
  const line = JSON.stringify(event) + '\n';
  const logEvent = opts.logEvent ?? ((level, ev, data) => {
    const entry = { ts: new Date().toISOString(), level, event: ev, ...(data ?? {}) };
    process.stderr.write(JSON.stringify(entry) + '\n');
  });

  // D52: cheap fast-path date check. If the module-cached date matches the
  // current UTC date, skip the rotation probe entirely (no disk I/O). If
  // the date has changed, synchronously rotate BEFORE the append so the
  // append lands in the (post-rotation) new live file rather than the
  // about-to-rotate-away old one.
  // Per ADR 0008 § 5.1: rotation fires "on the first append after a UTC
  // date change." Synchronous rotation ensures no append straddles the
  // boundary — old-date events land in the rotated file; new-date events
  // land in the fresh live file. The cache flip happens INSIDE
  // _maybeRotateAudit so concurrent in-process re-triggers short-circuit.
  const today = _utcDateNow();
  if (today !== _lastSeenUtcDate) {
    _maybeRotateAudit({ olpHome, logEvent });
  }

  for (let attempt = 0; attempt <= RETRY_COUNT; attempt++) {
    try {
      mkdirSync(logsDir, { recursive: true, mode: 0o700 });
      // Tighten dir mode in case it already existed with broader permissions.
      try { chmodSync(logsDir, 0o700); } catch { /* tolerate EPERM */ }
      appendFileSync(path, line, { mode: 0o600 });
      return;
    } catch (err) {
      if (attempt < RETRY_COUNT) {
        logEvent('warn', 'audit_append_failed_once', {
          path,
          error: err?.message ?? String(err),
        });
        continue;
      }
      _dropCounter++;
      logEvent('warn', 'audit_append_dropped', {
        path,
        error: err?.message ?? String(err),
        drop_count: _dropCounter,
      });
      return;
    }
  }
}

/**
 * Per-process count of audit events dropped due to repeated append failure.
 * Useful for /health observability surface (D46).
 */
export function getAuditDropCount() {
  return _dropCounter;
}

/**
 * Test-only: reset the drop counter to zero. Suite 20 uses this between
 * cases to assert independent failure-handling counts.
 */
export function __resetAuditDropCount() {
  _dropCounter = 0;
}

/**
 * Per-process count of successful rotations performed. Test + future
 * observability surface.
 */
export function getAuditRotateCount() {
  return _rotateCounter;
}

/**
 * Per-process count of failed rotation attempts (rename threw, target
 * existed, etc.). Test + future observability surface.
 */
export function getAuditRotateFailCount() {
  return _rotateFailCounter;
}

/**
 * Test-only: reset the rotation counters + the in-process "last seen UTC
 * date" cache so each test exercises a fresh code path.
 */
export function __resetAuditRotateState() {
  _rotateCounter = 0;
  _rotateFailCounter = 0;
  _lastSeenUtcDate = _utcDateNow();
}

/**
 * Test-only: force the cached "last seen UTC date" to a specific value
 * so the next appendAuditEvent observes a date change and triggers
 * rotation deterministically.
 */
export function __setLastSeenUtcDateForTesting(dateStr) {
  _lastSeenUtcDate = dateStr;
}