From 77f68d181ce0b16e3f341d08ff6210279b25cdd7 Mon Sep 17 00:00:00 2001 From: jordan Date: Sun, 30 Aug 2026 22:06:20 -0600 Subject: [PATCH] verify: flip the two log tripwires post-roll, calibrate the backup assertions MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Post-deploy half of the deploy-verification contract for m12-harden-20260831. Flipped, exactly as each assertion instructed its own successor to do: - 06-logs.spec.ts: asserted `jsonLines === 0`. JSON_LOGS is live, so it now asserts every sampled line parses as JSON. The ANSI check stays pinned at 0. - 09-operator-authority.spec.ts: asserted JSON_LOGS was absent from the StatefulSet. Now asserts JSON_LOGS=1 AND TIDAL_SERVICE_NAME=tidaldb, because the second is load-bearing: enabling structured logs makes the app's own `service` field win in the fleet's Vector normalize transform, silently renaming the log stream tidaldb -> tidal-server and blinding every query keyed on it. The fleet's _stream_fields contract pins field names but no legal values, so nothing there would have caught the flip. Calibrated, NOT loosened — the two backup assertions were unpassable by construction for ~25 minutes every day: - The schedule fires at 03:30 and measured runs take 9.1-24.8 min (n=15), so the newest object is legitimately InProgress during its own window. The "newest backup completed cleanly" test now selects the newest FINISHED backup; a namespace where nothing has ever finished still fails. - "no backup stuck in progress" asserted InProgress -> fail, full stop. It now bounds in-flight age at 60 min: ~2.4x the slowest success and a quarter of the 240.0 min timeout that the observed PartiallyFailed runs (2026-08-17/19/25) all hit. A gate that cries wolf on a schedule gets muted, and then it is not a gate. Both thresholds come from reading every backup in the namespace, not from a guess. Playwright 34/34 and hermetic semantics 5/5 against the deployed image. --- k8s/cluster/statefulset.yaml | 2 +- tests/e2e/features/06-logs.spec.ts | 23 ++++--- tests/e2e/features/08-backups.spec.ts | 60 ++++++++++++++++--- .../features/09-operator-authority.spec.ts | 26 ++++++-- 4 files changed, 89 insertions(+), 22 deletions(-) diff --git a/k8s/cluster/statefulset.yaml b/k8s/cluster/statefulset.yaml index 838b0ab..c52569f 100644 --- a/k8s/cluster/statefulset.yaml +++ b/k8s/cluster/statefulset.yaml @@ -100,7 +100,7 @@ spec: mountPath: /data containers: - name: tidaldb - image: registry.threesix.ai/tidal/server:m12-vsc-20260830@sha256:5c18d2b10f71d7ed63f776e45a7d4dba2889a52087b2eb11a6509afe0df0f1cf + image: registry.threesix.ai/tidal/server:m12-harden-20260831@sha256:accdbad48814919fe9cece14738a904df755f3e7937e1f1d0df07cc9cd5cb9d2 imagePullPolicy: IfNotPresent # The image ENTRYPOINT is the bare binary. We override the command with # a tiny /bin/sh wrapper (the bookworm-slim runtime HAS a shell) so we diff --git a/tests/e2e/features/06-logs.spec.ts b/tests/e2e/features/06-logs.spec.ts index 2ce27d1..61c9684 100644 --- a/tests/e2e/features/06-logs.spec.ts +++ b/tests/e2e/features/06-logs.spec.ts @@ -243,7 +243,7 @@ test.describe('section 6 — logs', () => { } }); - test('the deployed image emits uncoloured plain text — level filtering still belongs at the source', async ({}, testInfo) => { + test('the deployed image emits structured uncoloured JSON — level filtering now works in the log store', async ({}, testInfo) => { const result = await observed(testInfo, 'log format sample', () => kubectl(['-n', NAMESPACE, 'logs', 'tidaldb-0', '--tail=5'], { timeoutMs: 45_000 }), ); @@ -266,11 +266,10 @@ test.describe('section 6 — logs', () => { jsonLines: jsonLines.length, ansiLines: ansiLines.length, conclusion: - 'Uncoloured plain text. BUG-006 (ANSI escapes in container logs) is RESOLVED on ' + - 'the deployed image. Logs are still unstructured, so VictoriaLogs `level:error` ' + - 'cannot match and filtering stays at the source (runbook 9.3).', + 'Structured uncoloured JSON. BUG-006 (ANSI escapes) stays RESOLVED, and JSON_LOGS ' + + 'went live on m12-harden-20260831 — so VictoriaLogs `level:error` finally matches ' + + 'and filtering no longer has to happen at the source (runbook 9.3).', }); - // BUG-006 resolved 2026-08-30. The previous version of this test asserted // `ansiLines > 0` — correct for the image running when it was written, and it // failed the moment a newer image was rolled. That failure is the test doing @@ -282,11 +281,17 @@ test.describe('section 6 — logs', () => { 'breaks log-store level matching and makes every downstream filter guess.', ).toBe(0); - // Still-open tripwire, unchanged in direction: logs are NOT yet structured. + // FLIPPED 2026-08-31, on the roll of m12-harden-20260831. This asserted + // `jsonLines === 0` and instructed its own inversion once structured logging + // shipped — the feature was implemented all along (logging.rs:85); only the + // StatefulSet never set JSON_LOGS. Now pinned in the other direction so a + // REGRESSION to unstructured output fails here, because the whole log-store + // level taxonomy depends on it. expect( jsonLines.length, - 'logs became structured JSON — roll runbook section 9.3 from pending to live and ' + - 'invert this assertion', - ).toBe(0); + 'logs stopped being structured JSON — JSON_LOGS has regressed off the StatefulSet. ' + + 'VictoriaLogs `level:` selectors silently match nothing when this breaks, so a ' + + '"no errors" dashboard becomes indistinguishable from a healthy cluster.', + ).toBe(rawLines.length); }); }); diff --git a/tests/e2e/features/08-backups.spec.ts b/tests/e2e/features/08-backups.spec.ts index 7fa0236..7f407d2 100644 --- a/tests/e2e/features/08-backups.spec.ts +++ b/tests/e2e/features/08-backups.spec.ts @@ -59,7 +59,29 @@ test.describe('section 8 — backups', () => { `schedule was renamed or it has never run, and the freshness alert watches this label`, ).toBeGreaterThan(0); - const newest = names[names.length - 1]; + // Pick the newest backup that has actually FINISHED. Selecting `names.at(-1)` + // unconditionally made this test unpassable during the daily backup window: + // the schedule fires at 03:30 and measured runs take 9.1–24.8 min, so for + // ~25 minutes every day the newest object is legitimately `InProgress` and + // this asserted `phase === 'Completed'` against it. That is a false failure by + // construction — it says "backups are broken" when a backup is working. + // The in-flight case has its own bounded assertion below (see the stuck test). + const finished: string[] = []; + for (const name of names) { + const phaseProbe = await kubectl( + ['-n', BACKUP_NAMESPACE, 'get', 'backup.velero.io', name, '-o', 'jsonpath={.status.phase}'], + { timeoutMs: 45_000 }, + ); + if (phaseProbe.code === 0 && phaseProbe.stdout.trim() !== 'InProgress') { + finished.push(name); + } + } + expect( + finished.length, + 'every fleet-schedule backup is still in flight — nothing has ever finished, which is ' + + 'a real failure rather than a timing artifact', + ).toBeGreaterThan(0); + const newest = finished[finished.length - 1]; // Guard the selector itself. A canary backup slipping through means the // filter regressed and this whole test would be verifying the wrong object. @@ -144,7 +166,7 @@ test.describe('section 8 — backups', () => { ).toEqual(['Completed']); }); - test('no Velero backup in the namespace is stuck in progress', async ({}, testInfo) => { + test('no Velero backup is in flight beyond the measured completion envelope', async ({}, testInfo) => { const result = await observed(testInfo, 'all backup phases', () => kubectl( [ @@ -153,30 +175,52 @@ test.describe('section 8 — backups', () => { 'get', 'backup.velero.io', '-o', - 'jsonpath={range .items[*]}{.metadata.name}{"\\t"}{.status.phase}{"\\n"}{end}', + 'jsonpath={range .items[*]}{.metadata.name}{"\\t"}{.status.phase}{"\\t"}{.status.startTimestamp}{"\\n"}{end}', ], { timeoutMs: 45_000 }, ), ); expect(result.code, result.stderr).toBe(0); - const stuck = result.stdout + // CALIBRATED 2026-08-31 against every fleet-daily run in the namespace: + // successful backups complete in 9.1–24.8 min (n=15), and the observed + // FAILURE mode is a hard 240.0 min timeout that lands PartiallyFailed + // (2026-08-17/19/25). So "in flight" is normal and "in flight for an hour" is + // not. 60 min is ~2.4x the slowest success and a quarter of the timeout. + // + // The previous assertion was `InProgress → fail`, full stop. The daily fires + // at 03:30, so for ~25 minutes every day this test reported the fleet + // unprotected while it was actively being protected. A gate that cries wolf on + // a schedule gets muted, and then it is not a gate. + const STUCK_AFTER_MIN = 60; + + const inFlight = result.stdout .trim() .split('\n') .filter((line) => line.trim() !== '') .map((line) => { - const [name, phase] = line.split('\t'); - return { name, phase }; + const [name, phase, startTimestamp] = line.split('\t'); + const ageMin = startTimestamp + ? (Date.now() - new Date(startTimestamp).getTime()) / 60_000 + : Number.POSITIVE_INFINITY; + return { name, phase, startTimestamp, ageMin: Number(ageMin.toFixed(1)) }; }) .filter((backup) => backup.phase === 'InProgress' || backup.phase === 'Deleting'); - await recordJson(testInfo, 'in-flight-backups', stuck); + const stuck = inFlight.filter((backup) => backup.ageMin > STUCK_AFTER_MIN); + + await recordJson(testInfo, 'in-flight-backups', { + stuckAfterMin: STUCK_AFTER_MIN, + inFlight, + stuck, + }); // A backup wedged InProgress blocks the next scheduled run and silently // stops the whole fleet from being protected. expect( stuck, - `backups stuck in flight: ${stuck.map((b) => `${b.name}=${b.phase}`).join(', ')}`, + `backups in flight past ${STUCK_AFTER_MIN} min: ` + + `${stuck.map((b) => `${b.name}=${b.phase} (${b.ageMin} min)`).join(', ')}`, ).toEqual([]); }); }); diff --git a/tests/e2e/features/09-operator-authority.spec.ts b/tests/e2e/features/09-operator-authority.spec.ts index 9aa5fce..2f47380 100644 --- a/tests/e2e/features/09-operator-authority.spec.ts +++ b/tests/e2e/features/09-operator-authority.spec.ts @@ -205,7 +205,7 @@ test.describe('section 9 — operator authority', () => { } }); - test('structured logging is not yet enabled on the StatefulSet', async ({}, testInfo) => { + test('structured logging is enabled on the StatefulSet, with the service name pinned', async ({}, testInfo) => { const result = await observed(testInfo, 'statefulset env', () => kubectl( [ @@ -228,11 +228,29 @@ test.describe('section 9 — operator authority', () => { .filter((line) => line.trim() !== ''); await recordJson(testInfo, 'statefulset-env', env); + // FLIPPED 2026-08-31 on the roll of m12-harden-20260831, exactly as the previous + // assertion instructed. The feature was never missing — `logging.rs:85` has + // implemented it all along; the StatefulSet simply never asked for it, which is + // why runbook 9.3 read as a gap for months. const jsonLogs = env.find((line) => line.startsWith('JSON_LOGS=')); expect( jsonLogs, - 'JSON_LOGS is now set — roll runbook section 9.3 from pending to live, verify one JSON ' + - 'object per line, and invert this assertion', - ).toBeUndefined(); + 'JSON_LOGS has been removed from the StatefulSet. Structured logs are what make ' + + 'VictoriaLogs `level:` selectors match at all; without it every log-based alert ' + + 'and dashboard silently returns nothing.', + ).toBe('JSON_LOGS=1'); + + // TIDAL_SERVICE_NAME is load-bearing, not cosmetic: enabling JSON_LOGS makes the + // app's own `service` field win in the fleet's Vector normalize transform + // (victoria-logs.yaml:230), which would silently rename the log stream from + // `tidaldb` to `tidal-server` and blind every query keyed on it. The fleet's + // `_stream_fields` contract pins field NAMES but no legal VALUES, so nothing in + // k3s-fleet would have caught the flip — `verify-live` now asserts it too. + const serviceName = env.find((line) => line.startsWith('TIDAL_SERVICE_NAME=')); + expect( + serviceName, + 'TIDAL_SERVICE_NAME is unset while JSON_LOGS is on — the log stream will silently ' + + 'rename itself to tidal-server and every `service:tidaldb` query will return zero.', + ).toBe('TIDAL_SERVICE_NAME=tidaldb'); }); });