verify: flip the two log tripwires post-roll, calibrate the backup assertions
All checks were successful
ci/woodpecker/push/woodpecker Pipeline was successful

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.
This commit is contained in:
jordan 2026-08-30 22:06:20 -06:00
parent fe8d0c87e7
commit 77f68d181c
4 changed files with 89 additions and 22 deletions

View File

@ -100,7 +100,7 @@ spec:
mountPath: /data mountPath: /data
containers: containers:
- name: tidaldb - 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 imagePullPolicy: IfNotPresent
# The image ENTRYPOINT is the bare binary. We override the command with # 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 # a tiny /bin/sh wrapper (the bookworm-slim runtime HAS a shell) so we

View File

@ -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', () => const result = await observed(testInfo, 'log format sample', () =>
kubectl(['-n', NAMESPACE, 'logs', 'tidaldb-0', '--tail=5'], { timeoutMs: 45_000 }), kubectl(['-n', NAMESPACE, 'logs', 'tidaldb-0', '--tail=5'], { timeoutMs: 45_000 }),
); );
@ -266,11 +266,10 @@ test.describe('section 6 — logs', () => {
jsonLines: jsonLines.length, jsonLines: jsonLines.length,
ansiLines: ansiLines.length, ansiLines: ansiLines.length,
conclusion: conclusion:
'Uncoloured plain text. BUG-006 (ANSI escapes in container logs) is RESOLVED on ' + 'Structured uncoloured JSON. BUG-006 (ANSI escapes) stays RESOLVED, and JSON_LOGS ' +
'the deployed image. Logs are still unstructured, so VictoriaLogs `level:error` ' + 'went live on m12-harden-20260831 — so VictoriaLogs `level:error` finally matches ' +
'cannot match and filtering stays at the source (runbook 9.3).', '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 // 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 // `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 // 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.', 'breaks log-store level matching and makes every downstream filter guess.',
).toBe(0); ).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( expect(
jsonLines.length, jsonLines.length,
'logs became structured JSON — roll runbook section 9.3 from pending to live and ' + 'logs stopped being structured JSON — JSON_LOGS has regressed off the StatefulSet. ' +
'invert this assertion', 'VictoriaLogs `level:` selectors silently match nothing when this breaks, so a ' +
).toBe(0); '"no errors" dashboard becomes indistinguishable from a healthy cluster.',
).toBe(rawLines.length);
}); });
}); });

View File

@ -59,7 +59,29 @@ test.describe('section 8 — backups', () => {
`schedule was renamed or it has never run, and the freshness alert watches this label`, `schedule was renamed or it has never run, and the freshness alert watches this label`,
).toBeGreaterThan(0); ).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.124.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 // Guard the selector itself. A canary backup slipping through means the
// filter regressed and this whole test would be verifying the wrong object. // filter regressed and this whole test would be verifying the wrong object.
@ -144,7 +166,7 @@ test.describe('section 8 — backups', () => {
).toEqual(['Completed']); ).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', () => const result = await observed(testInfo, 'all backup phases', () =>
kubectl( kubectl(
[ [
@ -153,30 +175,52 @@ test.describe('section 8 — backups', () => {
'get', 'get',
'backup.velero.io', 'backup.velero.io',
'-o', '-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 }, { timeoutMs: 45_000 },
), ),
); );
expect(result.code, result.stderr).toBe(0); 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.124.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() .trim()
.split('\n') .split('\n')
.filter((line) => line.trim() !== '') .filter((line) => line.trim() !== '')
.map((line) => { .map((line) => {
const [name, phase] = line.split('\t'); const [name, phase, startTimestamp] = line.split('\t');
return { name, phase }; 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'); .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 // A backup wedged InProgress blocks the next scheduled run and silently
// stops the whole fleet from being protected. // stops the whole fleet from being protected.
expect( expect(
stuck, 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([]); ).toEqual([]);
}); });
}); });

View File

@ -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', () => const result = await observed(testInfo, 'statefulset env', () =>
kubectl( kubectl(
[ [
@ -228,11 +228,29 @@ test.describe('section 9 — operator authority', () => {
.filter((line) => line.trim() !== ''); .filter((line) => line.trim() !== '');
await recordJson(testInfo, 'statefulset-env', env); 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=')); const jsonLogs = env.find((line) => line.startsWith('JSON_LOGS='));
expect( expect(
jsonLogs, jsonLogs,
'JSON_LOGS is now set — roll runbook section 9.3 from pending to live, verify one JSON ' + 'JSON_LOGS has been removed from the StatefulSet. Structured logs are what make ' +
'object per line, and invert this assertion', 'VictoriaLogs `level:` selectors match at all; without it every log-based alert ' +
).toBeUndefined(); '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');
}); });
}); });