/** * 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 = {}; 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 } > = {}; 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 = {}; 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); }); });