Files
fusion/scripts/pg-loaded-failure-census.mjs
gsxdsm fb77eef7a9 FN-9150: Capture abandoned PostgreSQL timeout boundaries
Capture elapsed and join evidence for PostgreSQL test boundaries that Vitest abandons before settlement.

- emit unique boundary join keys, progress ladders, terminal records, and payload-free watchdog breaches
- classify ladder-only, breach, and unobservable lifecycle evidence in the loaded-failure census
- cover abandoned and superseded body windows and document the corrective campaign findings

Files changed:
 ...res-loaded-lane-unrelated-failure-population.md |  33 ++++++-
 docs/testing.md                                    |  14 ++-
 .../__test-utils__/pg-timeout-boundary-observer.ts | 108 ++++++++++++++++++---
 .../__tests__/pg-timeout-boundary-observer.test.ts |  98 ++++++++++++++++++-
 .../__tests__/pg-loaded-failure-census.test.mjs    |  30 ++++++
 scripts/pg-loaded-failure-census.mjs               |  71 ++++++++++++--
 6 files changed, 327 insertions(+), 27 deletions(-)

Fusion-Task-Id: FN-9150

Fusion-Task-Lineage: fc2e9f99-7739-4d86-99f4-713a78f53e57

Co-authored-by: Fusion (runfusion.ai) <noreply@runfusion.ai>
2026-08-19 10:10:39 -07:00

325 lines
19 KiB
JavaScript
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
#!/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 };
}
export function normalizeFile(value) {
const normalized = String(value).replaceAll("\\", "/");
// Vitest diagnostics use absolute paths while runner failures use repo paths.
// Canonicalize at the test-root segment before any key-based observer join.
const testRoot = normalized.indexOf("src/__tests__/");
if (testRoot >= 0) return normalized.slice(testRoot);
const match = normalized.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 parseBoundaryObserverJsonl(text) {
return parseDiagnosticsJsonl(text);
}
/** Vitest JSON exposes test durations; hook duration is not available in v4 output. */
export function parseVitestJson(text) {
try {
const report = JSON.parse(String(text));
const rows = Array.isArray(report?.testResults) ? report.testResults : [];
return {
rows: rows.flatMap((file) => (Array.isArray(file?.assertionResults) ? file.assertionResults : []).map((test) => ({
testFile: normalizeFile(file?.name),
position: classifyLifecyclePosition([test?.fullName, ...(test?.failureMessages ?? [])].join("\n")),
durationMs: Number.isFinite(test?.duration) ? test.duration : null,
status: test?.status ?? null,
}))),
malformed: false,
};
} catch {
return { rows: [], malformed: true };
}
}
function boundaryForLifecycle(lifecyclePosition) {
if (lifecyclePosition === "beforeAll hook" || lifecyclePosition === "in-test setup") return "setup";
if (lifecyclePosition === "afterEach" || lifecyclePosition === "afterAll hook" || lifecyclePosition === "global setup-teardown") return "teardown";
return "body";
}
function observerFile(record) {
return normalizeFile(record?.testFile);
}
/**
* FNXC:PgTimeoutBoundaryObserver 2026-08-19-13:51:
* Watchdog payloads win because they are the only records carrying a cluster
* snapshot. Completion-only and suppressed records may support host evidence,
* but must never be promoted to cluster causation by inference.
*/
export function classifyBoundaryAttribution(failure, observerRecords, bodyUnobservableFiles = [], fullyUnobservableFiles = []) {
const boundary = boundaryForLifecycle(failure.lifecyclePosition);
const sameFile = observerRecords.filter((record) => observerFile(record) === failure.file && record.boundary === boundary);
if (fullyUnobservableFiles.includes(failure.file)) {
// These files never enter a harness-owned boundary, so their missing join
// is an explicit coverage limit rather than a failed observer correlation.
return { classification: "unjoined", boundary, record: null, hostOnly: false, fullyUnobservable: true };
}
if (boundary === "body" && bodyUnobservableFiles.includes(failure.file)) {
return { classification: "body-unobservable", boundary, record: null, hostOnly: false, fullyUnobservable: false };
}
// Shared-harness afterEach only closes the body bracket; consumer afterEach
// hooks are outside it, so an absent record is an explicit position limit.
if (failure.lifecyclePosition === "afterEach") {
return { classification: "position-unobservable", boundary, record: null, hostOnly: false, fullyUnobservable: false };
}
// A settled boundary can legitimately have earlier checkpoints. Only a key
// with progress and no terminal record is an abandoned-boundary lower bound.
const terminalKeys = new Set(sameFile.filter((record) => record.kind === "terminal" && typeof record.joinKey === "string").map((record) => record.joinKey));
const abandonedProgress = sameFile.filter((record) => record.kind === "progress" && typeof record.joinKey === "string" && !terminalKeys.has(record.joinKey));
if (abandonedProgress.length > 0) {
const withElapsed = abandonedProgress.map((record) => ({ record, elapsedMs: Number(record.elapsedMs) })).filter(({ elapsedMs }) => Number.isFinite(elapsedMs));
const latestBound = withElapsed.length > 0 ? withElapsed.reduce((latest, candidate) => candidate.elapsedMs > latest.elapsedMs ? candidate : latest) : null;
return { classification: "attributed-by-ladder", boundary, record: latestBound?.record ?? abandonedProgress[0], hostOnly: true, elapsedLowerBoundMs: latestBound?.elapsedMs ?? null };
}
const watchdog = sameFile.filter((record) => record.trigger === "boundary-watchdog");
const record = watchdog.find((candidate) => !candidate.probeSuppressed && candidate.cluster && candidate.template)
?? watchdog.find((candidate) => candidate.kind === "watchdog")
?? watchdog[0]
?? sameFile[0]
?? null;
if (!record) return { classification: "unjoined", boundary, record: null, hostOnly: false };
const hostOnly = record.trigger !== "boundary-watchdog" || Boolean(record.probeSuppressed) || !record.cluster;
if (hostOnly) {
const load = Number(record?.host?.loadavg1);
const cpus = Number(record?.host?.cpuCount);
const lag = Number(record?.host?.eventLoopLagMs);
if ((Number.isFinite(load) && Number.isFinite(cpus) && load >= cpus) || lag >= 100) {
return { classification: "host-implicated", boundary, record, hostOnly: true };
}
// A two-phase breach is a real boundary join even when it has no cluster
// payload. Keep it visible as coverage rather than misreporting no record.
if (record?.kind === "breach" && record?.payloadFree === true) {
return { classification: "joined", boundary, record, hostOnly: true };
}
return { classification: "unjoined", boundary, record, hostOnly: true };
}
const template = record.template ?? {};
// A holder alone is not a convoy: only a non-owner waiter proves the
// timed-out boundary was queued behind the golden template advisory lock.
if (Array.isArray(template.advisoryWaiters) && template.advisoryWaiters.length > 0 && template.isOwner === false) {
return { classification: "template-convoy", boundary, record, hostOnly: false, fullyUnobservable: false };
}
const cluster = record.cluster ?? {};
const active = Array.isArray(cluster.activity) && cluster.activity.some((row) => row?.state === "active" || row?.wait_event || row?.blockingPids?.length);
const blocked = Array.isArray(cluster.locks) && cluster.locks.some((lock) => lock?.granted === false || lock?.blockingPids?.length);
if (active || blocked) return { classification: "cluster-implicated", boundary, record, hostOnly: false };
const load = Number(record?.host?.loadavg1);
const cpus = Number(record?.host?.cpuCount);
const lag = Number(record?.host?.eventLoopLagMs);
if ((Number.isFinite(load) && Number.isFinite(cpus) && load >= cpus) || lag >= 100) return { classification: "host-implicated", boundary, record, hostOnly: false };
return { classification: "unjoined", boundary, record, hostOnly: false };
}
export function summarizeBoundaryObserver(records, failures, bodyUnobservableFiles = [], fullyUnobservableFiles = []) {
const rows = Array.isArray(records) ? records : [];
const attributions = failures.map((failure) => ({ ...failure, boundaryAttribution: classifyBoundaryAttribution(failure, rows, bodyUnobservableFiles, fullyUnobservableFiles) }));
const suppression = {};
for (const row of rows) {
const reason = row?.probeSuppressed === "single-flight" ? "concurrency" : row?.probeSuppressed;
if (reason) suppression[reason] = (suppression[reason] ?? 0) + 1;
}
const attributionCounts = Object.fromEntries(Object.entries(Object.groupBy(attributions, (row) => row.boundaryAttribution.classification)).map(([key, values]) => [key, values.length]));
return {
boundaryObserver: rows.length ? "present" : "absent",
boundaryAttributionHistogram: attributionCounts,
joinedCoverageYield: {
joined: (attributionCounts.joined ?? 0) + (attributionCounts["cluster-implicated"] ?? 0) + (attributionCounts["host-implicated"] ?? 0) + (attributionCounts["template-convoy"] ?? 0),
attributedByLadder: attributionCounts["attributed-by-ladder"] ?? 0,
bodyUnobservable: attributionCounts["body-unobservable"] ?? 0,
positionUnobservable: attributionCounts["position-unobservable"] ?? 0,
unjoined: attributionCounts.unjoined ?? 0,
},
observerProbeSuppression: suppression,
settledDuringProbeCount: rows.filter((row) => row?.settledDuringProbe === true).length,
fullyUnobservableFailingFiles: attributions.filter((row) => row.boundaryAttribution.fullyUnobservable).map((row) => row.file),
fullyUnobservableFailingFileCount: attributions.filter((row) => row.boundaryAttribution.fullyUnobservable).length,
attributions,
};
}
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 = [], boundaryObserver = [], vitestJson = [], bodyUnobservableFiles = [], fullyUnobservableFiles = [], 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 observerSummary = summarizeBoundaryObserver(boundaryObserver, failingFiles, bodyUnobservableFiles, fullyUnobservableFiles);
const reporterFiles = new Set(vitestJson.map((row) => row.testFile).filter(Boolean));
const observerFiles = new Set(boundaryObserver.map(observerFile).filter(Boolean));
const reporterJoin = {
observerFilesWithoutReporter: [...observerFiles].filter((file) => !reporterFiles.has(file)),
reporterFilesWithoutObserver: [...reporterFiles].filter((file) => !observerFiles.has(file)),
};
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,
...observerSummary,
reporterJoin,
};
}
function parseArgs(args) {
const result = { log: undefined, diagnostics: undefined, boundaryObserver: undefined, vitestJson: undefined, bodyUnobservableFiles: undefined, fullyUnobservableFiles: 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 === "--boundary-observer") result.boundaryObserver = args[++index];
else if (argument === "--vitest-json") result.vitestJson = args[++index];
else if (argument === "--body-unobservable-files") result.bodyUnobservableFiles = args[++index];
else if (argument === "--fully-unobservable-files") result.fullyUnobservableFiles = 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 };
const observer = args.boundaryObserver ? parseBoundaryObserverJsonl(readFileSync(args.boundaryObserver, "utf8")) : { rows: [], malformedLines: 0 };
const reporter = args.vitestJson ? parseVitestJson(readFileSync(args.vitestJson, "utf8")) : { rows: [], malformed: false };
const bodyUnobservableFiles = args.bodyUnobservableFiles ? readFileSync(args.bodyUnobservableFiles, "utf8").split(/\\r?\\n/).map(normalizeFile).filter(Boolean) : [];
const fullyUnobservableFiles = args.fullyUnobservableFiles ? readFileSync(args.fullyUnobservableFiles, "utf8").split(/\\r?\\n/).map(normalizeFile).filter(Boolean) : [];
console.log(JSON.stringify({ ...buildCensus({ log: readFileSync(args.log, "utf8"), diagnostics: parsed.rows, boundaryObserver: observer.rows, vitestJson: reporter.rows, bodyUnobservableFiles, fullyUnobservableFiles, ordinarySlotCeiling: args.ordinarySlotCeiling, subjects: args.subjects }), malformedDiagnosticLines: parsed.malformedLines, malformedBoundaryObserverLines: observer.malformedLines, malformedVitestJson: reporter.malformed }, null, 2));
}