FN-9148: add PostgreSQL loaded-failure census

Add retained-log census tooling and evidence for PostgreSQL loaded-lane timeout investigations.

- Parse complete Vitest logs and optional diagnostics without opening PostgreSQL or running tests.
- Classify failing files, lifecycle positions, failure shapes, backend headroom, waits, and watchdog data.
- Cover high-failure, healthy, malformed-diagnostics, and truncated-log cases with fixtures.
- Document the reproduced population, unsupported remedies, and successor measurement requirements.

Files changed:
 ...res-loaded-lane-unrelated-failure-population.md |  80 ++++++++++
 docs/testing.md                                    |   8 +
 .../fixtures/pg-loaded-failure-census/high-run.txt |  77 +++++++++
 .../fixtures/pg-loaded-failure-census/high.jsonl   |   4 +
 .../fixtures/pg-loaded-failure-census/low-run.txt  |   4 +
 .../pg-loaded-failure-census/truncated-run.txt     |   2 +
 .../__tests__/pg-loaded-failure-census.test.mjs    |  65 ++++++++
 scripts/pg-loaded-failure-census.mjs               | 172 +++++++++++++++++++++
 8 files changed, 412 insertions(+)

Fusion-Task-Id: FN-9148

Fusion-Task-Lineage: c632a9d0-b823-4416-ab46-0d834e850007

Co-authored-by: Fusion (runfusion.ai) <noreply@runfusion.ai>
This commit is contained in:
gsxdsm
2026-08-19 06:24:01 -07:00
parent 687990c0a6
commit 161edaa694
8 changed files with 412 additions and 0 deletions

View File

@@ -0,0 +1,80 @@
---
category: test-failures
module: testing
problem_type: loaded_postgresql_timeout_population
applies_when:
- "The 27-worker core PostgreSQL directory lane reports unrelated hook or test timeouts"
- "A PostgreSQL loaded-lane remedy is proposed from runner-log impressions"
tags:
- postgres
- vitest
- diagnostics
- timeout
- census
---
# PostgreSQL loaded-lane unrelated failure population
## Verdict: reproduced but unattributed
FN-9148 reproduced the unrelated population in three of five pre-registered,
diagnostics-enabled 27-worker directory runs. A03/A04/A05 reported 45, 35, and
32 failed files respectively, while their observed peaks were 63, 75, and 71
backends below the 97 ordinary-slot ceiling. This establishes the fan-out
symptom; it does not establish a cause or authorize a harness remedy.
## Method
`scripts/pg-loaded-failure-census.mjs` is a cluster-free parser. It reads a
retained Vitest runner log and teardown-diagnostics JSONL, then reports every
failing file, its lifecycle position and shape, snapshot peak/headroom, waits,
phase-duration statistics, and watchdog/probe-degradation counts. It labels
campaign subjects rather than excluding them. A missing `Test Files` summary
is `insufficient-data`; a complete passing summary is a measured zero-failure
run.
The host had 28 CPUs, so requested 27 workers resolved to 27. PostgreSQL was
15.15 with `max_connections=100`, three reserved connections, 128MB
`shared_buffers`, a five-minute checkpoint timeout, and 1GB maximum WAL. Test
databases were enumerated and explicitly reset between primary samples.
| lane | outcome |
|---|---|
| 27-worker directory A01–A05 | red: 13, 24, 45, 35, 32 failed files; peaks 73, 61, 63, 75, 71 |
| 12-worker directory | green, measured zero failures |
| isolated `project-identity.test.ts` | green, measured zero failures |
| configured four-fork PG gate | green, measured zero failures |
| default core lane | green, measured zero failures |
The reproduced runs mixed setup/teardown and body timeouts. A03, for example,
had four beforeAll, 19 afterEach, five afterAll, and 17 body failures; its
watchdog snapshots included checkpoint, ProcSignalBarrier, and object-lock
waits. The checkpointed task document `evidence` is the detailed durable
record.
## Discrimination table
| mechanism | verdict | evidence / missing discriminator |
|---|---|---|
| M1 ordinary backend exhaustion | undecided; generic version contradicted | Peaks stay 22–36 below 97, but watchdog-only snapshots cannot rule out a per-user/per-database limit or a missed transient peak. |
| M2 DDL serialization | undecided | Hook concentration and checkpoint/catalog/object waits are observations, not per-failed-hook DDL correlation. |
| M3 golden-template/advisory convoy | undecided | No template-owner/lock-wait timeline was captured. |
| M4 host CPU/event-loop starvation | undecided | Host load was material, but teardown-only probes cannot show PostgreSQL idle versus in-flight at setup/body timeout time. |
| M5 dirty-cluster carryover | undecided | Clean resets still reproduced, but no controlled clean/dirty covariation measurement was run. |
## Remedies disqualified by this evidence
Do not raise timeouts, add retries or skips, alter worker caps, quarantine core
PostgreSQL files, wire the retained connection-budget/admission primitives, or
change DDL paths. Reducing generic connection demand is specifically unsupported:
the reproduced peaks are below ordinary capacity. A green comparison lane is
not a resolution.
## Successor measurement seam
The successor must design a separately reviewed, default-off observer that can
join a setup/body or teardown timeout to host pressure, the active SQL/lock
state, and template ownership without changing harness execution. It must run
three instrumented reproductions and an unset-environment control before
attribution. A controlled dirty-cluster arm is also required for M5. Reuse the
census tool and retain all logs/JSONL; do not return to impression-based claims.

View File

@@ -537,6 +537,14 @@ For a pre-registered loaded-flake campaign, record PostgreSQL version, `max_conn
<!-- FNXC:PgDdlLaneMetric 2026-08-17-00:59: FN-9134 requires a pre-registered end-to-end band because teardown watchdogs become structurally meaningless when cleanup leaves the hook. The parser is intentionally report-only and the alternating samples are campaign observations, never Vitest retries. -->
<!-- FNXC:PgLoadedFailureCensus 2026-08-19-12:41: FN-9148 requires a retained loaded-lane failure population to be classified without contacting PostgreSQL, so a complete green log remains evidence rather than being conflated with a truncated capture. -->
### PostgreSQL loaded-failure census
Use `scripts/pg-loaded-failure-census.mjs` to inspect an already-retained Vitest runner log and its optional teardown-diagnostics JSONL. The script never opens a cluster or runs tests. Supply `--log`, `--diagnostics`, and the recorded `--ordinary-slot-ceiling`; repeat `--subject` to label campaign files without dropping them. Its output contains total and failing files, lifecycle and failure-shape breakdowns, observed backend peak/headroom, wait histogram, phase-duration order statistics, and watchdog/probe-degradation counts.
A run is `insufficient-data` when its runner log lacks a complete `Test Files` summary or when the reported failed-file count cannot be reconciled to parsed failure blocks. A complete passing summary instead produces `status: "measured"` with `failingFileCount: 0`; never treat that zero as missing evidence or coerce incomplete input to a healthy result.
### PostgreSQL DDL loaded-lane acceptance metric
Use `scripts/pg-ddl-lane-metric.mjs` before judging a PostgreSQL DDL structural candidate. Run at least seven **interleaved** control/candidate pairs at `VITEST_MAX_WORKERS=12`; preserve one diagnostics JSONL sink and complete runner log per invocation. The exact lane is:

View File

@@ -0,0 +1,77 @@
FAIL src/__tests__/postgres/case-00.test.ts > case 00
Error: beforeAll hook timed out in 15000ms.
FAIL src/__tests__/postgres/case-01.test.ts > case 01
Error: Test timed out in 15000ms.
FAIL src/__tests__/postgres/case-02.test.ts > case 02
AssertionError: expected 1 to be 2
FAIL src/__tests__/postgres/case-03.test.ts > case 03
Error: afterEach hook failed during loaded run
FAIL src/__tests__/postgres/case-04.test.ts > case 04
Error: test body failed during loaded run
FAIL src/__tests__/postgres/case-05.test.ts > case 05
Error: beforeAll hook failed during loaded run
FAIL src/__tests__/postgres/case-06.test.ts > case 06
Error: afterAll hook failed during loaded run
FAIL src/__tests__/postgres/case-07.test.ts > case 07
Error: beforeEach hook failed during loaded run
FAIL src/__tests__/postgres/case-08.test.ts > case 08
Error: afterEach hook failed during loaded run
FAIL src/__tests__/postgres/case-09.test.ts > case 09
Error: test body failed during loaded run
FAIL src/__tests__/postgres/case-10.test.ts > case 10
Error: beforeAll hook failed during loaded run
FAIL src/__tests__/postgres/case-11.test.ts > case 11
Error: afterAll hook failed during loaded run
FAIL src/__tests__/postgres/case-12.test.ts > case 12
Error: beforeEach hook failed during loaded run
FAIL src/__tests__/postgres/case-13.test.ts > case 13
Error: afterEach hook failed during loaded run
FAIL src/__tests__/postgres/case-14.test.ts > case 14
Error: test body failed during loaded run
FAIL src/__tests__/postgres/case-15.test.ts > case 15
Error: beforeAll hook failed during loaded run
FAIL src/__tests__/postgres/case-16.test.ts > case 16
Error: afterAll hook failed during loaded run
FAIL src/__tests__/postgres/case-17.test.ts > case 17
Error: beforeEach hook failed during loaded run
FAIL src/__tests__/postgres/case-18.test.ts > case 18
Error: afterEach hook failed during loaded run
FAIL src/__tests__/postgres/case-19.test.ts > case 19
Error: test body failed during loaded run
FAIL src/__tests__/postgres/case-20.test.ts > case 20
Error: beforeAll hook failed during loaded run
FAIL src/__tests__/postgres/case-21.test.ts > case 21
Error: afterAll hook failed during loaded run
FAIL src/__tests__/postgres/case-22.test.ts > case 22
Error: beforeEach hook failed during loaded run
FAIL src/__tests__/postgres/case-23.test.ts > case 23
Error: afterEach hook failed during loaded run
FAIL src/__tests__/postgres/case-24.test.ts > case 24
Error: test body failed during loaded run
Test Files 25 failed | 150 passed | 1 skipped (176)
Tests 25 failed | 1360 passed

View File

@@ -0,0 +1,4 @@
{"trigger":"phase-watchdog","phase":"dropDatabase","phaseDurationsMs":{"dropDatabase":2100},"probeRan":true,"snapshotRows":[{"total_backends":73,"wait_event_type":"IPC","wait_event":"CheckpointDone"},{"total_backends":73,"wait_event_type":"Lock","wait_event":"relation"}]}
{"trigger":"snapshot","phaseDurationsMs":{"dropDatabase":3000},"probeRan":true,"snapshotRows":[{"total_backends":62,"wait_event_type":"IPC","wait_event":"CheckpointDone"}]}
{not json}
{"trigger":"teardown-watchdog","phaseDurationsMs":{},"probeRan":false,"probeSuppressed":"cap"}

View File

@@ -0,0 +1,4 @@
✓ src/__tests__/postgres/healthy.test.ts (2 tests)
Test Files 1 passed (1)
Tests 2 passed (2)

View File

@@ -0,0 +1,2 @@
FAIL src/__tests__/postgres/partial.test.ts > partial
Error: beforeAll hook timed out in 15000ms.

View File

@@ -0,0 +1,65 @@
import assert from "node:assert/strict";
import { readFileSync } from "node:fs";
import { URL } from "node:url";
import test from "node:test";
import {
buildCensus,
classifyFailureShape,
classifyLifecyclePosition,
extractFailingFiles,
parseDiagnosticsJsonl,
stripAnsi,
} from "../pg-loaded-failure-census.mjs";
const fixture = (name) => readFileSync(new URL(`./fixtures/pg-loaded-failure-census/${name}`, import.meta.url), "utf8");
test("strips ANSI and classifies failure lifecycle positions and shapes", () => {
assert.equal(stripAnsi("\u001b[31mFAIL\u001b[0m"), "FAIL");
assert.equal(classifyLifecyclePosition("Error: beforeAll hook timed out"), "beforeAll hook");
assert.equal(classifyLifecyclePosition("Error: afterEach hook failed"), "afterEach");
assert.equal(classifyLifecyclePosition("global teardown failure"), "global setup-teardown");
assert.equal(classifyFailureShape("beforeAll hook timed out in 15000ms"), "hook timeout");
assert.equal(classifyFailureShape("Test timed out in 15000ms"), "test timeout");
assert.equal(classifyFailureShape("AssertionError: expected 1 to be 2"), "assertion");
});
test("censuses every high-failure file and joins snapshot diagnostics", () => {
const parsed = parseDiagnosticsJsonl(fixture("high.jsonl"));
assert.equal(parsed.malformedLines, 1);
const census = buildCensus({
log: fixture("high-run.txt"),
diagnostics: parsed.rows,
ordinarySlotCeiling: 97,
subjects: ["src/__tests__/postgres/case-00.test.ts"],
});
assert.equal(census.status, "measured");
assert.equal(census.totalFiles, 176);
assert.equal(census.failingFileCount, 25);
assert.equal(census.failingFileBand, "high (>=25)");
assert.equal(census.peakBackends, 73);
assert.equal(census.backendHeadroom, 24);
assert.equal(census.lifecyclePositionHistogram["beforeAll hook"], 5);
assert.equal(census.failureShapeHistogram["hook timeout"], 1);
assert.equal(census.failureShapeHistogram["test timeout"], 1);
assert.equal(census.failureShapeHistogram.assertion, 1);
assert.equal(census.waitEventHistogram["IPC/CheckpointDone"], 2);
assert.equal(census.watchdogCount, 2);
assert.equal(census.probeDegradationCount, 1);
assert.equal(census.failingFiles[0].campaignSubject, true);
assert.equal(extractFailingFiles(fixture("high-run.txt")).length, 25);
});
test("reports a complete healthy run as measured zero rather than insufficient data", () => {
const census = buildCensus({ log: fixture("low-run.txt"), diagnostics: [], ordinarySlotCeiling: 97 });
assert.equal(census.status, "measured");
assert.equal(census.failingFileCount, 0);
assert.equal(census.failingFileBand, "zero");
assert.equal(census.peakBackends, null);
});
test("rejects a truncated runner log instead of manufacturing a zero-failure census", () => {
const census = buildCensus({ log: fixture("truncated-run.txt") });
assert.equal(census.status, "insufficient-data");
assert.match(census.reason, /missing Test Files summary/);
assert.notEqual(census.failingFileCount, 0);
});

View File

@@ -0,0 +1,172 @@
#!/usr/bin/env node
import { readFileSync } from "node:fs";
import { pathToFileURL } from "node:url";
/*
FNXC:PgLoadedFailureCensus 2026-08-19-12:41:
FN-9148 requires a report-only census because earlier PostgreSQL loaded-lane
owners had to reason from runner-log impressions. Peaks of 62–73 below 97
ordinary slots already contradict ordinary connection exhaustion, while a
non-reproducing run is evidence only when it remains distinguishable from a
missing or truncated capture. This parser never opens PostgreSQL, runs tests,
or changes harness behavior.
*/
export function stripAnsi(text) {
return String(text).replace(new RegExp(`${String.fromCharCode(27)}\\[[0-?]*[ -/]*[@-~]`, "g"), "");
}
export function parseDiagnosticsJsonl(text) {
const rows = [];
let malformedLines = 0;
for (const line of String(text).split(/\r?\n/)) {
if (!line.trim()) continue;
try {
const row = JSON.parse(line);
if (row && typeof row === "object" && !Array.isArray(row)) rows.push(row);
else malformedLines += 1;
} catch {
malformedLines += 1;
}
}
return { rows, malformedLines };
}
function normalizeFile(value) {
const match = String(value).replaceAll("\\", "/").match(/(?:[\w@.-]+\/)*[\w@.-]+(?:\.pg)?\.test\.[cm]?[jt]sx?/i);
return match?.[0] ?? null;
}
export function classifyLifecyclePosition(text) {
const value = String(text).toLowerCase();
if (/\bglobal (?:setup|teardown)\b|\bglobalSetup\b|\bglobalTeardown\b/i.test(text)) return "global setup-teardown";
if (/\bafterall\b|\bafter all\b/i.test(text)) return "afterAll hook";
if (/\baftereach\b|\bafter each\b/i.test(text)) return "afterEach";
if (/\bbeforeall\b|\bbefore all\b/i.test(text)) return "beforeAll hook";
if (/\bbeforeeach\b|\bbefore each\b|\bin-test setup\b|\btest setup\b/i.test(text)) return "in-test setup";
return "test body";
}
export function classifyFailureShape(text) {
const value = String(text).toLowerCase();
if (/\b(?:hook|beforeall|beforeeach|afterall|aftereach|global setup|global teardown)\b[\s\S]{0,120}\btimed out\b|\btimed out\b[\s\S]{0,120}\b(?:hook|beforeall|beforeeach|afterall|aftereach)\b/.test(value)) return "hook timeout";
if (/\btest timed out\b|\btimed out\b/.test(value)) return "test timeout";
if (/assertionerror|\bexpected\b[\s\S]{0,80}\b(?:to be|to equal|to deeply equal|received)\b/i.test(text)) return "assertion";
return "error";
}
export function extractFailingFiles(log) {
const clean = stripAnsi(log);
const headings = [...clean.matchAll(/^\s*(?:FAIL|❯)\s+(.+?\.test\.[cm]?[jt]sx?)(?:\s|$)/gim)];
const failures = new Map();
for (let index = 0; index < headings.length; index += 1) {
const file = normalizeFile(headings[index][1]);
if (!file) continue;
const start = headings[index].index ?? 0;
const end = headings[index + 1]?.index ?? clean.length;
const detail = clean.slice(start, end);
const prior = failures.get(file);
if (!prior || detail.length > prior.detail.length) {
failures.set(file, { file, lifecyclePosition: classifyLifecyclePosition(detail), failureShape: classifyFailureShape(detail), detail });
}
}
return [...failures.values()].map(({ detail: _detail, ...failure }) => failure);
}
function parseCount(value) {
const parsed = Number(value);
return Number.isSafeInteger(parsed) && parsed >= 0 ? parsed : null;
}
export function parseFileSummary(log) {
const line = stripAnsi(log).split(/\r?\n/).find((candidate) => /^\s*Test Files\s+/i.test(candidate));
if (!line) return { complete: false, totalFiles: null, reportedFailedFiles: null };
const count = (word) => {
const match = line.match(new RegExp(`(\\d+)\\s+${word}\\b`, "i"));
return match ? parseCount(match[1]) : 0;
};
const failed = count("failed");
const passed = count("passed");
const skipped = count("skipped");
if ([failed, passed, skipped].some((value) => value == null)) return { complete: false, totalFiles: null, reportedFailedFiles: null };
return { complete: true, totalFiles: failed + passed + skipped, reportedFailedFiles: failed };
}
export function summarizeDiagnostics(diagnostics) {
const input = Array.isArray(diagnostics) ? diagnostics : [];
const waits = new Map();
const peaks = [];
const phaseDurations = new Map();
let watchdogCount = 0;
let probeDegradationCount = 0;
for (const row of input) {
if (row?.trigger === "phase-watchdog" || row?.trigger === "teardown-watchdog") watchdogCount += 1;
if (row?.probeSuppressed || (row?.trigger?.includes("watchdog") && row?.probeRan === false)) probeDegradationCount += 1;
for (const duration of Object.values(row?.phaseDurationsMs ?? {})) {
if (Number.isFinite(duration)) phaseDurations.set("all", [...(phaseDurations.get("all") ?? []), duration]);
}
for (const activity of row?.snapshotRows ?? []) {
if (Number.isFinite(activity?.total_backends)) peaks.push(activity.total_backends);
const type = activity?.wait_event_type ?? "none";
const event = activity?.wait_event ?? "none";
const key = `${type}/${event}`;
waits.set(key, (waits.get(key) ?? 0) + 1);
}
}
const values = phaseDurations.get("all") ?? [];
const sorted = values.toSorted((a, b) => a - b);
const percentile = (fraction) => sorted.length === 0 ? null : sorted[Math.min(sorted.length - 1, Math.ceil(sorted.length * fraction) - 1)];
return {
peakBackends: peaks.length ? Math.max(...peaks) : null,
waitEventHistogram: Object.fromEntries([...waits.entries()].sort(([a], [b]) => a.localeCompare(b))),
phaseDurationMs: { count: sorted.length, median: percentile(0.5), p95: percentile(0.95), max: sorted.at(-1) ?? null },
watchdogCount,
probeDegradationCount,
};
}
export function buildCensus({ log, diagnostics = [], ordinarySlotCeiling = null, subjects = [] }) {
const summary = parseFileSummary(log);
if (!summary.complete) {
return { status: "insufficient-data", reason: "missing Test Files summary", totalFiles: null, failingFiles: [], failingFileCount: null };
}
const failingFiles = extractFailingFiles(log).map((failure) => ({ ...failure, campaignSubject: subjects.includes(failure.file) }));
if (summary.reportedFailedFiles !== failingFiles.length) {
return { status: "insufficient-data", reason: `summary reports ${summary.reportedFailedFiles} failed files but ${failingFiles.length} failure blocks were parsed`, totalFiles: summary.totalFiles, failingFiles, failingFileCount: null };
}
const diagnosticSummary = summarizeDiagnostics(diagnostics);
const ceiling = Number.isFinite(ordinarySlotCeiling) && ordinarySlotCeiling >= 0 ? ordinarySlotCeiling : null;
return {
status: "measured",
totalFiles: summary.totalFiles,
failingFiles,
failingFileCount: failingFiles.length,
failingFileBand: failingFiles.length >= 25 ? "high (>=25)" : failingFiles.length === 0 ? "zero" : "low (1-24)",
lifecyclePositionHistogram: Object.fromEntries(Object.entries(Object.groupBy(failingFiles, (failure) => failure.lifecyclePosition)).map(([key, values]) => [key, values.length])),
failureShapeHistogram: Object.fromEntries(Object.entries(Object.groupBy(failingFiles, (failure) => failure.failureShape)).map(([key, values]) => [key, values.length])),
ordinarySlotCeiling: ceiling,
backendHeadroom: ceiling != null && diagnosticSummary.peakBackends != null ? ceiling - diagnosticSummary.peakBackends : null,
...diagnosticSummary,
};
}
function parseArgs(args) {
const result = { log: undefined, diagnostics: undefined, ordinarySlotCeiling: null, subjects: [] };
for (let index = 0; index < args.length; index += 1) {
const argument = args[index];
if (argument === "--log") result.log = args[++index];
else if (argument === "--diagnostics") result.diagnostics = args[++index];
else if (argument === "--ordinary-slot-ceiling") result.ordinarySlotCeiling = Number(args[++index]);
else if (argument === "--subject") result.subjects.push(args[++index]);
else throw new Error(`Unknown argument: ${argument}`);
}
if (!result.log) throw new Error("Supply --log <runner.log>");
return result;
}
if (process.argv[1] && import.meta.url === pathToFileURL(process.argv[1]).href) {
const args = parseArgs(process.argv.slice(2));
const parsed = args.diagnostics ? parseDiagnosticsJsonl(readFileSync(args.diagnostics, "utf8")) : { rows: [], malformedLines: 0 };
console.log(JSON.stringify({ ...buildCensus({ log: readFileSync(args.log, "utf8"), diagnostics: parsed.rows, ordinarySlotCeiling: args.ordinarySlotCeiling, subjects: args.subjects }), malformedDiagnosticLines: parsed.malformedLines }, null, 2));
}