tidaldb/tests/e2e/features/06-logs.spec.ts

/**
 * Runbook section 6 — logs are readable and replication is currently healthy.
 *
 * CAP-011 container logs are readable and free of unexpected errors
 *
 * Design note. An earlier draft of this spec allowlisted every WARN it found,
 * which would have permanently hidden `batch ship failing … transport channel
 * closed` — a real replication failure that ran for 115 consecutive seconds
 * after an election. A blanket allowlist is a mute button.
 *
 * So this spec splits the question in two:
 *   1. Is replication healthy RIGHT NOW?  → asserted against a recent window.
 *   2. What has the pod been saying?      → recorded as evidence, and only
 *      genuinely benign, explained lines are tolerated.
 */

import { expect, test } from '@playwright/test';
import { kubectl } from '../support/cluster';
import { observed, recordJson } from '../support/evidence';
import { NAMESPACE, POD_NAMES } from '../support/env';

/** Window that must be quiet for replication to count as currently healthy. */
const HEALTH_WINDOW = '5m';

/** Longer window recorded as evidence, not asserted clean. */
const HISTORY_WINDOW = '30m';

/** Strip ANSI so patterns match; the deployed image colours its output. */
function decolour(text: string): string {
  return text.replace(/\x1b\[[0-9;]*m/g, '');
}

/**
 * Warnings that are genuinely benign on this deployment, each with the reason.
 * An allowlist entry without a rationale is not allowed — if the reason cannot
 * be written down, the line is not understood and must not be silenced.
 */
const BENIGN_WARNINGS: { match: RegExp; why: string }[] = [
  {
    match: /TIDAL_ADMIN_KEY is not set/i,
    why:
      'Stale boot-time WARN. kubelet materialized the projected secret at 05:51:43, after the ' +
      'pod started at 05:41, and the credential poller hot-loaded it. The gate IS live — ' +
      'proven behaviourally in 09-operator-authority.spec.ts. See BUG-003.',
  },
  {
    match: /reading credential file failed.*admin-key/i,
    why:
      'Same cause: the admin-key volume is mounted optional:true, so each poller pass logged a ' +
      'miss until the key existed.',
  },
  {
    match: /TIDAL_CLUSTER_KEY not set/i,
    why: 'Peer authentication uses the internal CA; the shared cluster key is unused here.',
  },
  {
    match: /Multi-process cluster mode enabled/i,
    why: 'Informational notice on every cluster-mode boot — this IS the production HA shape.',
  },
  {
    match: /metrics server bound to non-loopback address/i,
    why:
      'Intentional: :9091 must be reachable by the vmagent scraper. Exposure is contained by ' +
      'the NetworkPolicy, which 04-network-isolation.spec.ts proves refuses foreign pods.',
  },
  {
    match: /catch-up stream open failed; will retry/i,
    why:
      'Self-healing by design — the stream reopens on the next detected gap or retry timer. ' +
      'Tolerated only in the history window; the health window must be clean.',
  },
];

/** Replication distress that must be absent in the health window. */
const REPLICATION_DISTRESS = /batch ship failing|transport channel closed|quarantin/i;

test.describe('section 6 — logs', () => {
  test('replication is quiet right now on every pod', async ({}, testInfo) => {
    const perPod: Record<string, { distressLines: string[]; sampled: number }> = {};

    for (const pod of POD_NAMES) {
      const result = await observed(testInfo, `recent logs ${pod}`, () =>
        kubectl(['-n', NAMESPACE, 'logs', pod, `--since=${HEALTH_WINDOW}`], {
          timeoutMs: 60_000,
        }),
      );
      expect(result.code, `could not read ${pod} logs: ${result.stderr}`).toBe(0);

      const lines = decolour(result.stdout)
        .split('\n')
        .filter((line) => line.trim() !== '');
      perPod[pod] = {
        sampled: lines.length,
        distressLines: lines.filter((line) => REPLICATION_DISTRESS.test(line)).slice(0, 5),
      };
    }

    await recordJson(testInfo, 'replication-health-window', { window: HEALTH_WINDOW, perPod });

    for (const pod of POD_NAMES) {
      // A pod shipping batches into a closed transport channel is not
      // replicating, even while /cluster/status/local still reports lag=0
      // because the leader has not yet advanced past the stuck position.
      expect(
        perPod[pod].distressLines,
        `${pod} is reporting replication distress in the last ${HEALTH_WINDOW}: ` +
          `${perPod[pod].distressLines.join(' | ')}`,
      ).toEqual([]);
    }
  });

  test('no pod logged an ERROR, and every WARN is explained', async ({}, testInfo) => {
    const perPod: Record<
      string,
      { lines: number; errors: string[]; unexplained: string[]; benignCounts: Record<string, number> }
    > = {};

    for (const pod of POD_NAMES) {
      const result = await observed(testInfo, `history logs ${pod}`, () =>
        kubectl(['-n', NAMESPACE, 'logs', pod, `--since=${HISTORY_WINDOW}`, '--tail=400'], {
          timeoutMs: 60_000,
        }),
      );
      expect(result.code, `could not read ${pod} logs: ${result.stderr}`).toBe(0);

      const lines = decolour(result.stdout)
        .split('\n')
        .filter((line) => line.trim() !== '');
      const warnings = lines.filter((line) => /\bWARN\b/.test(line));

      const benignCounts: Record<string, number> = {};
      const unexplained: string[] = [];
      for (const line of warnings) {
        const matched = BENIGN_WARNINGS.find((entry) => entry.match.test(line));
        if (matched) {
          benignCounts[matched.match.source] = (benignCounts[matched.match.source] ?? 0) + 1;
        } else if (REPLICATION_DISTRESS.test(line)) {
          // Recorded, not failed: the previous test owns the health verdict and
          // a historical, recovered episode is legitimate history.
          benignCounts['recovered-replication-episode'] =
            (benignCounts['recovered-replication-episode'] ?? 0) + 1;
        } else {
          unexplained.push(line.slice(0, 200));
        }
      }

      perPod[pod] = {
        lines: lines.length,
        errors: lines.filter((line) => /\bERROR\b/.test(line)).slice(0, 10),
        unexplained: unexplained.slice(0, 10),
        benignCounts,
      };
    }

    await recordJson(testInfo, 'log-classification', {
      window: HISTORY_WINDOW,
      allowlist: BENIGN_WARNINGS.map((entry) => ({ pattern: entry.match.source, why: entry.why })),
      perPod,
    });

    for (const pod of POD_NAMES) {
      expect(perPod[pod].lines, `${pod} should be logging at all`).toBeGreaterThan(0);
      expect(
        perPod[pod].errors,
        `${pod} logged ERROR lines: ${perPod[pod].errors.join(' | ')}`,
      ).toEqual([]);
      expect(
        perPod[pod].unexplained,
        `${pod} logged WARNs with no recorded rationale — investigate and either fix or ` +
          `add an explained allowlist entry: ${perPod[pod].unexplained.join(' | ')}`,
      ).toEqual([]);
    }
  });

  test('the deployed image still emits coloured plain text, so level filtering must happen at the source', async ({}, testInfo) => {
    const result = await observed(testInfo, 'log format sample', () =>
      kubectl(['-n', NAMESPACE, 'logs', 'tidaldb-0', '--tail=5'], { timeoutMs: 45_000 }),
    );
    expect(result.code, result.stderr).toBe(0);

    const rawLines = result.stdout.split('\n').filter((line) => line.trim() !== '');
    expect(rawLines.length, 'expected log lines to classify').toBeGreaterThan(0);

    const jsonLines = rawLines.filter((line) => {
      try {
        return typeof JSON.parse(decolour(line)) === 'object';
      } catch {
        return false;
      }
    });
    const ansiLines = rawLines.filter((line) => /\x1b\[/.test(line));

    await recordJson(testInfo, 'log-format', {
      sampled: rawLines.length,
      jsonLines: jsonLines.length,
      ansiLines: ansiLines.length,
      conclusion:
        'Coloured plain text. VictoriaLogs level:error cannot match, so filter with ' +
        'kubectl logs | grep until the observability image is rolled (runbook 9.3).',
    });

    // Two tripwires in the honest direction. Both are CORRECT for the running
    // image, and both fail the day the observability image lands — which is
    // when the runbook needs updating. That is the drift that made section 9.2
    // stale in the first place.
    expect(
      jsonLines.length,
      'logs became structured JSON — roll runbook section 9.3 from pending to live and ' +
        'invert this assertion',
    ).toBe(0);
    expect(
      ansiLines.length,
      'ANSI escapes are gone — the observability image has been rolled; mark BUG-006 ' +
        'verified and invert this assertion',
    ).toBeGreaterThan(0);
  });
});