FN-9127: instrument PostgreSQL teardown diagnostics
Add opt-in evidence capture for loaded PostgreSQL teardown stalls without changing teardown behavior. - Add bounded phase and hook watchdogs with capped pg_stat_activity snapshots. - Instrument the shared PostgreSQL test harness and cover diagnostic behavior with focused tests. - Document the diagnostic workflow, measured flake campaign, and corrected mission-store gate scope. Files changed: .../suite-only-flakes-observed-register.md | 12 ++ docs/testing.md | 19 ++ .../src/__test-utils__/pg-teardown-diagnostics.ts | 237 +++++++++++++++++++++ .../core/src/__test-utils__/pg-test-harness.ts | 120 ++++++++--- .../src/__tests__/pg-teardown-diagnostics.test.ts | 162 ++++++++++++++ .../__tests__/postgres/mission-store.pg.test.ts | 8 +- 6 files changed, 526 insertions(+), 32 deletions(-) Fusion-Task-Id: FN-9127 Fusion-Task-Lineage: 2488b7c0-f12f-4560-9a99-41aaca9d1526 Co-authored-by: Fusion (runfusion.ai) <noreply@runfusion.ai>
This commit is contained in:
gsxdsm
@@ -174,6 +174,18 @@ The timeout occurred after all test assertions and is unrelated to FN-8979's can
|
||||
| targeted dot reporter ×3 | 61 tests passed; afterAll passed |
|
||||
| full core ×3, 6 workers | subject passed; unrelated settings-revision-attribution failure |
|
||||
|
||||
**Instrumented outcome 2026-08-16 (FN-9127): entry 7 remains unreproduced and is now self-diagnosing.** The default-off teardown recorder was measured on `beb8ae67dba1ed122cab94a4641e875ccebd21f1` against PostgreSQL 15.15 (`max_connections=100`, 97 ordinary slots). It writes synchronous JSONL records and its in-flight phase/teardown watchdogs fire before the inherited 15s hook is aborted, so a phase that never settles still leaves timing plus `pg_stat_activity` evidence. The durable campaign tables and full snapshot rows are retained in task document `FN-9127/evidence`; `/tmp/fn-9127-*.log` and `/tmp/fn-9127-diag-*.jsonl` are scratch copies only.
|
||||
|
||||
| instrumented shape | result | measured worst phase | watchdog / snapshot |
|
||||
|---|---|---:|---|
|
||||
| subject dot ×3 | all passed | `dropDatabase` 154ms | no / none |
|
||||
| full core, 4 workers | unrelated settings attribution failure | 1,439ms globally | no / none |
|
||||
| full core, 6 workers | unrelated settings attribution failure | 1,576ms globally | no / none |
|
||||
| full core, 8 workers | unrelated settings attribution failure | 1,905ms globally | no / none |
|
||||
| full core, 12 workers | unrelated settings attribution + schema-applier timeout | `dropDatabase` 3,582ms globally | 30 / 30 |
|
||||
|
||||
The 12-worker snapshots show 21 backends and concurrent template `CREATE DATABASE`/`DROP DATABASE WITH (FORCE)` work, including `IPC/CheckpointDone` and `IPC/ProcSignalBarrier`; they do not implicate this mission-store suite. That separately-scoped loaded-DDL finding is tracked by FN-9130. No teardown behavior was changed: there is no evidence-backed cause for this entry's historical 15s afterAll abort. Re-run a loaded lane with `FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS=1 FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_LOG=/tmp/fn-9127-diag-core.jsonl VITEST_MAX_WORKERS=12 pnpm --filter @fusion/core test 2>&1 | tee /tmp/fn-9127-core.log`; retain full output and checkpoint parsed JSONL to a durable task document immediately. This first-sighting record remains retained; a second sighting follows the normal escalation. Core PostgreSQL files cannot be quarantined inline because the gate-policy assertion requires `quarantinedCoreTests` to remain empty; that is an owner-escalated decision.
|
||||
|
||||
## 8. Planning Mode duplicate-response generation reconciliation
|
||||
|
||||
- **File:** `packages/dashboard/app/components/__tests__/PlanningModeModal.planning-flow.test.tsx`
|
||||
|
||||
@@ -468,6 +468,25 @@ Legitimate legacy exceptions must be recorded in `scripts/lib/test-timeout-appea
|
||||
|
||||
**2026-08-16 PostgreSQL first-sighting diagnosis (FN-9125):** First classify each file by its real dependency path, not nearby failure timing. Retain complete `tee` output for repeated package lanes and record fan-out, server capacity, and target identities. If a current run cannot link a PostgreSQL test assertion to golden-template, DDL, pool, or teardown evidence, do not add timeouts/retries or infer a harness change: obtain CI/host activity and phase timings. A core PostgreSQL file is escalated rather than quarantined because `quarantinedCoreTests` remains policy-pinned empty; a non-PG engine file follows normal ledger-plus-exclude lockstep.
|
||||
|
||||
<!-- FNXC:PgTestHarnessTeardownDiagnostics 2026-08-16-19:32: FN-9127 requires a 15s PostgreSQL afterAll abort to preserve evidence before a hook can be killed. Diagnostics therefore observe pending teardown work with unref'd watchdogs, synchronously flush evidence, and cap a separate short-lived activity probe rather than extending or perturbing the teardown. -->
|
||||
|
||||
### PostgreSQL teardown diagnostics
|
||||
|
||||
Set `FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS=1` only while investigating an integration-test teardown. The default is off: no timer, probe connection, query, or sink file is created. When enabled, the shared PG harness records `store.close`, `layer.close`, `adminSql.end`, `dropDatabase`, and `rmRootDir` timings. `FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_THRESHOLD_MS` (default `2000`) arms each phase watchdog; `FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_HOOK_WATCHDOG_MS` (default `12000`) covers the whole teardown, safely below the inherited 15s hook budget. These are diagnostic observation bounds, never timeout extensions: a watchdog fires while work is still pending, so an aborted/hung teardown has evidence rather than only a post-hoc silence.
|
||||
|
||||
On a watchdog breach, the harness lazily opens one dedicated maintenance connection and queries `pg_stat_activity` across all databases. `FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_PROBE_TIMEOUT_MS` (default `1500`) bounds connect/query/close; `FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_MAX_PROBES` (default `3`) caps probes per process. Probes are single-flight, use no runtime or admin pool, are force-closed on abort, and are never awaited by teardown work. Timers are unref'd and every diagnostics failure is fenced, so the observer cannot keep a worker alive or change the outcome it measures.
|
||||
|
||||
Set `FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_LOG=/path/to/teardown.jsonl` to synchronously append one JSON object per record. The schema includes timestamp, pid/worker, `trigger` (`phase-complete`, `phase-watchdog`, `teardown-watchdog`, or `snapshot`), phase-duration map, thresholds, `phaseIncomplete`/`elapsedAtSnapshotMs`, probe outcome/suppression, and snapshot rows (`datname`, state, wait event, backend type, query age, and backend count). Sink errors only fall back to `[pg-teardown-diagnostics]` stderr output. For the next loaded sighting, preserve full output and structured evidence with:
|
||||
|
||||
```bash
|
||||
FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS=1 \
|
||||
FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_LOG=/tmp/fn-9127-diag-core.jsonl \
|
||||
VITEST_MAX_WORKERS=12 \
|
||||
pnpm --filter @fusion/core test 2>&1 | tee /tmp/fn-9127-core.log
|
||||
```
|
||||
|
||||
Checkpoint parsed JSONL and run metadata in a durable task document after every run; `/tmp` is scratch storage, not the evidence system of record.
|
||||
|
||||
<!-- FNXC:EngineTestReliability 2026-06-27-10:05: FN-7119 rescued the 2026-06-26 engine scheduler/reliability quarantine burst by completing local TaskStore fakes for the scheduler heartbeat `updateSettings({ engineLastActiveAt })` write before adjusting any call-count assertions. When a scheduler batch reports zero mock calls or missing audit events after a heartbeat-era scheduler change, first mirror the production store surface in shared fakes and re-run the exact files together under `engine-default` / `engine-reliability`; do not weaken call-count invariants or quarantine ledger/config rows after the fake drift is fixed. -->
|
||||
|
||||
<!-- FNXC:TestQuarantine 2026-06-19-14:15: FN-6740 audited the same-day quarantine ledger as a coordinated deletion-ratchet batch. The ledger had 14 entries (3 dashboard, 6 core, 5 CLI) and every entry was mirrored in its package Vitest exclude; keep follow-up rescue/delete work scoped by subsystem so ledger/config edits remain lockstep and do not collide. -->
|
||||
|
||||
237
packages/core/src/__test-utils__/pg-teardown-diagnostics.ts
Normal file
237
packages/core/src/__test-utils__/pg-teardown-diagnostics.ts
Normal file
@@ -0,0 +1,237 @@
|
||||
import { appendFileSync } from "node:fs";
|
||||
|
||||
/** Rows deliberately limited to pg_stat_activity fields safe for test diagnostics. */
|
||||
export interface PgTeardownActivityRow {
|
||||
readonly pid?: number;
|
||||
readonly datname?: string | null;
|
||||
readonly usename?: string | null;
|
||||
readonly state?: string | null;
|
||||
readonly wait_event_type?: string | null;
|
||||
readonly wait_event?: string | null;
|
||||
readonly backend_type?: string | null;
|
||||
readonly query_age?: string | null;
|
||||
readonly query?: string | null;
|
||||
readonly total_backends?: number;
|
||||
}
|
||||
|
||||
export type PgTeardownDiagnosticTrigger = "phase-complete" | "phase-watchdog" | "teardown-watchdog" | "snapshot";
|
||||
|
||||
export interface PgTeardownDiagnosticRecord {
|
||||
readonly timestamp: string;
|
||||
readonly pid: number;
|
||||
readonly workerId?: string;
|
||||
readonly testFile?: string;
|
||||
readonly trigger: PgTeardownDiagnosticTrigger;
|
||||
readonly phase?: string;
|
||||
readonly phaseDurationsMs: Readonly<Record<string, number>>;
|
||||
readonly phaseIncomplete?: boolean;
|
||||
readonly elapsedAtSnapshotMs?: number;
|
||||
readonly thresholdMs: number;
|
||||
readonly hookWatchdogMs: number;
|
||||
readonly probeTimeoutMs: number;
|
||||
readonly probeRan: boolean;
|
||||
readonly probeSuppressed?: "cap" | "single-flight";
|
||||
readonly snapshotRows?: readonly PgTeardownActivityRow[];
|
||||
}
|
||||
|
||||
type TimerHandle = ReturnType<typeof setTimeout>;
|
||||
type TimerFactory = (callback: () => void, ms: number) => TimerHandle;
|
||||
|
||||
export interface PgTeardownDiagnosticsOptions {
|
||||
readonly env?: NodeJS.ProcessEnv;
|
||||
readonly now?: () => number;
|
||||
readonly setTimer?: TimerFactory;
|
||||
readonly clearTimer?: (timer: TimerHandle) => void;
|
||||
readonly append?: (path: string, line: string) => void;
|
||||
readonly writeError?: (line: string) => void;
|
||||
readonly probe?: (signal: AbortSignal) => Promise<readonly PgTeardownActivityRow[]>;
|
||||
readonly testFile?: string;
|
||||
}
|
||||
|
||||
export interface PgTeardownDiagnostics {
|
||||
readonly enabled: boolean;
|
||||
beginTeardown(): void;
|
||||
completeTeardown(): void;
|
||||
runPhase<T>(phase: string, action: () => Promise<T>): Promise<T>;
|
||||
dispose(): void;
|
||||
}
|
||||
|
||||
let processProbeCount = 0;
|
||||
|
||||
/** Test-only reset for deterministic cap coverage; production never calls this. */
|
||||
export function __resetPgTeardownDiagnosticsProbeCountForTest(): void {
|
||||
processProbeCount = 0;
|
||||
}
|
||||
|
||||
function boundedEnvNumber(env: NodeJS.ProcessEnv, key: string, fallback: number): number {
|
||||
const candidate = Number(env[key]);
|
||||
return Number.isFinite(candidate) && candidate > 0 ? Math.trunc(candidate) : fallback;
|
||||
}
|
||||
|
||||
/**
|
||||
* FNXC:PgTestHarnessTeardownDiagnostics 2026-08-16-19:40:
|
||||
* Keep the dedicated PostgreSQL probe's server-side bound aligned with its
|
||||
* watchdog budget, rather than allowing a lower caller-configured bound to drift.
|
||||
*/
|
||||
export function getPgTeardownDiagnosticsProbeTimeoutMs(env: NodeJS.ProcessEnv = process.env): number {
|
||||
return boundedEnvNumber(env, "FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_PROBE_TIMEOUT_MS", 1_500);
|
||||
}
|
||||
|
||||
/**
|
||||
* FNXC:PgTestHarnessTeardownDiagnostics 2026-08-16-19:40:
|
||||
* The probe's PostgreSQL statement timeout must stay below the configured
|
||||
* client-side bound, including deliberately small test budgets; otherwise its
|
||||
* server query could outlive the diagnostic watchdog it is meant to respect.
|
||||
*/
|
||||
export function getPgTeardownDiagnosticsStatementTimeoutMs(probeTimeoutMs: number): number {
|
||||
return Math.max(1, probeTimeoutMs - 100);
|
||||
}
|
||||
|
||||
function formatRecord(record: PgTeardownDiagnosticRecord): string {
|
||||
const rows = record.snapshotRows?.map((row) =>
|
||||
`${row.datname ?? "?"}/${row.state ?? "?"}/${row.wait_event ?? "?"}`,
|
||||
).join(", ");
|
||||
return `[pg-teardown-diagnostics] trigger=${record.trigger} phase=${record.phase ?? "teardown"} elapsed=${record.elapsedAtSnapshotMs ?? Object.values(record.phaseDurationsMs).at(-1) ?? 0}ms${rows ? ` activity=${rows}` : ""}`;
|
||||
}
|
||||
|
||||
/**
|
||||
* FNXC:PgTestHarnessTeardownDiagnostics 2026-08-16-19:12:
|
||||
* Register entry 7 observed a 15s afterAll abort without a reproducible phase
|
||||
* owner. This default-off recorder measures before changing teardown behavior.
|
||||
* Watchdogs fire while a phase is pending because post-hoc arithmetic is silent
|
||||
* when Vitest aborts a hung hook; their records flush synchronously because the
|
||||
* worker may be torn down immediately afterward. Timers are unref'd, and probes
|
||||
* are capped, single-flight, lazy, and hard-bounded so diagnostics cannot become
|
||||
* another connection contender or keep a worker alive during the contention being measured.
|
||||
*/
|
||||
export function createPgTeardownDiagnostics(options: PgTeardownDiagnosticsOptions = {}): PgTeardownDiagnostics {
|
||||
const env = options.env ?? process.env;
|
||||
const enabled = env.FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS === "1";
|
||||
if (!enabled) {
|
||||
return {
|
||||
enabled: false,
|
||||
beginTeardown() {},
|
||||
completeTeardown() {},
|
||||
async runPhase<T>(_phase: string, action: () => Promise<T>): Promise<T> { return action(); },
|
||||
dispose() {},
|
||||
};
|
||||
}
|
||||
|
||||
const now = options.now ?? Date.now;
|
||||
const setTimer = options.setTimer ?? setTimeout;
|
||||
const clearTimer = options.clearTimer ?? clearTimeout;
|
||||
const append = options.append ?? ((path, line) => appendFileSync(path, line));
|
||||
const writeError = options.writeError ?? ((line) => console.error(line));
|
||||
const thresholdMs = boundedEnvNumber(env, "FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_THRESHOLD_MS", 2_000);
|
||||
const hookWatchdogMs = boundedEnvNumber(env, "FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_HOOK_WATCHDOG_MS", 12_000);
|
||||
const probeTimeoutMs = getPgTeardownDiagnosticsProbeTimeoutMs(env);
|
||||
const maxProbes = boundedEnvNumber(env, "FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_MAX_PROBES", 3);
|
||||
const sink = env.FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_LOG;
|
||||
const phaseDurations: Record<string, number> = {};
|
||||
let teardownStartedAt = 0;
|
||||
let teardownWatchdog: TimerHandle | undefined;
|
||||
let teardownWatchdogFired = false;
|
||||
let disposed = false;
|
||||
let probeInFlight = false;
|
||||
|
||||
const unref = (timer: TimerHandle): void => {
|
||||
(timer as unknown as { unref?: () => void }).unref?.();
|
||||
};
|
||||
const emit = (record: Omit<PgTeardownDiagnosticRecord, "timestamp" | "pid" | "workerId" | "testFile" | "phaseDurationsMs" | "thresholdMs" | "hookWatchdogMs" | "probeTimeoutMs">): void => {
|
||||
const complete: PgTeardownDiagnosticRecord = {
|
||||
...record,
|
||||
timestamp: new Date(now()).toISOString(),
|
||||
pid: process.pid,
|
||||
...(env.VITEST_WORKER_ID ? { workerId: env.VITEST_WORKER_ID } : {}),
|
||||
...(options.testFile ? { testFile: options.testFile } : {}),
|
||||
phaseDurationsMs: { ...phaseDurations },
|
||||
thresholdMs,
|
||||
hookWatchdogMs,
|
||||
probeTimeoutMs,
|
||||
};
|
||||
const line = `${JSON.stringify(complete)}\n`;
|
||||
if (sink) {
|
||||
try { append(sink, line); } catch { /* diagnostic sink failures are non-fatal */ }
|
||||
}
|
||||
try { writeError(formatRecord(complete)); } catch { /* console failures are non-fatal */ }
|
||||
};
|
||||
|
||||
const requestProbe = (): { probeRan: boolean; probeSuppressed?: "cap" | "single-flight" } => {
|
||||
if (!options.probe) return { probeRan: false };
|
||||
if (probeInFlight) return { probeRan: false, probeSuppressed: "single-flight" };
|
||||
if (processProbeCount >= maxProbes) return { probeRan: false, probeSuppressed: "cap" };
|
||||
processProbeCount += 1;
|
||||
probeInFlight = true;
|
||||
const controller = new AbortController();
|
||||
let timedOut = false;
|
||||
const timeout = setTimer(() => {
|
||||
timedOut = true;
|
||||
controller.abort();
|
||||
}, probeTimeoutMs);
|
||||
unref(timeout);
|
||||
const probePromise = Promise.resolve().then(() => options.probe!(controller.signal));
|
||||
void probePromise.then(
|
||||
(snapshotRows) => {
|
||||
if (!timedOut) emit({ trigger: "snapshot", probeRan: true, snapshotRows });
|
||||
},
|
||||
() => {},
|
||||
).finally(() => {
|
||||
clearTimer(timeout);
|
||||
probeInFlight = false;
|
||||
}).catch(() => {});
|
||||
return { probeRan: true };
|
||||
};
|
||||
|
||||
const fireTeardownWatchdog = (): void => {
|
||||
if (disposed || teardownWatchdogFired) return;
|
||||
teardownWatchdogFired = true;
|
||||
const probe = requestProbe();
|
||||
emit({
|
||||
trigger: "teardown-watchdog",
|
||||
phaseIncomplete: true,
|
||||
elapsedAtSnapshotMs: Math.max(0, now() - teardownStartedAt),
|
||||
...probe,
|
||||
});
|
||||
};
|
||||
|
||||
return {
|
||||
enabled: true,
|
||||
beginTeardown(): void {
|
||||
if (disposed || teardownWatchdog) return;
|
||||
teardownStartedAt = now();
|
||||
teardownWatchdog = setTimer(fireTeardownWatchdog, hookWatchdogMs);
|
||||
unref(teardownWatchdog);
|
||||
},
|
||||
completeTeardown(): void {
|
||||
if (teardownWatchdog) clearTimer(teardownWatchdog);
|
||||
teardownWatchdog = undefined;
|
||||
},
|
||||
async runPhase<T>(phase: string, action: () => Promise<T>): Promise<T> {
|
||||
const startedAt = now();
|
||||
let settled = false;
|
||||
let watchdogFired = false;
|
||||
const watchdog = setTimer(() => {
|
||||
if (settled || disposed || watchdogFired) return;
|
||||
watchdogFired = true;
|
||||
const elapsedAtSnapshotMs = Math.max(0, now() - startedAt);
|
||||
phaseDurations[phase] = elapsedAtSnapshotMs;
|
||||
const probe = requestProbe();
|
||||
emit({ trigger: "phase-watchdog", phase, phaseIncomplete: true, elapsedAtSnapshotMs, ...probe });
|
||||
}, thresholdMs);
|
||||
unref(watchdog);
|
||||
try {
|
||||
return await action();
|
||||
} finally {
|
||||
settled = true;
|
||||
clearTimer(watchdog);
|
||||
phaseDurations[phase] = Math.max(0, now() - startedAt);
|
||||
emit({ trigger: "phase-complete", phase, probeRan: false });
|
||||
}
|
||||
},
|
||||
dispose(): void {
|
||||
disposed = true;
|
||||
if (teardownWatchdog) clearTimer(teardownWatchdog);
|
||||
teardownWatchdog = undefined;
|
||||
},
|
||||
};
|
||||
}
|
||||
@@ -44,7 +44,13 @@ import { Worker } from "node:worker_threads";
|
||||
import { mkdtemp, rm, writeFile } from "node:fs/promises";
|
||||
import { basename, join } from "node:path";
|
||||
import { tmpdir } from "node:os";
|
||||
import { describe as vitestDescribe } from "vitest";
|
||||
import {
|
||||
createPgTeardownDiagnostics,
|
||||
getPgTeardownDiagnosticsProbeTimeoutMs,
|
||||
getPgTeardownDiagnosticsStatementTimeoutMs,
|
||||
type PgTeardownActivityRow,
|
||||
} from "./pg-teardown-diagnostics.js";
|
||||
import { describe as vitestDescribe, expect as vitestExpect } from "vitest";
|
||||
import postgres, { type Sql } from "postgres";
|
||||
import { drizzle, type PostgresJsDatabase } from "drizzle-orm/postgres-js";
|
||||
import { sql } from "drizzle-orm";
|
||||
@@ -258,6 +264,42 @@ function uniqueDbName(prefix = "fusion_test"): string {
|
||||
* timeout can SET statement_timeout (server cancel) and force-close the
|
||||
* socket before the caller returns.
|
||||
*/
|
||||
/**
|
||||
* FNXC:PgTestHarnessTeardownDiagnostics 2026-08-16-19:12:
|
||||
* A watchdog must inspect a separate maintenance connection: adminSql and the
|
||||
* runtime layer can be the close phase currently stuck. Abort force-closes this
|
||||
* dedicated socket so a failed diagnostic cannot outlive the teardown it observes.
|
||||
*/
|
||||
function createPgStatActivityProbe(
|
||||
probeTimeoutMs = getPgTeardownDiagnosticsProbeTimeoutMs(),
|
||||
): (signal: AbortSignal) => Promise<readonly PgTeardownActivityRow[]> {
|
||||
return async (signal) => {
|
||||
const maintUrl = new URL(PG_TEST_URL_BASE);
|
||||
maintUrl.pathname = "/postgres";
|
||||
const client = postgres(maintUrl.toString(), {
|
||||
max: 1,
|
||||
prepare: false,
|
||||
connect_timeout: 1,
|
||||
onnotice: () => {},
|
||||
});
|
||||
const abort = () => { void client.end({ timeout: 0 }).catch(() => {}); };
|
||||
signal.addEventListener("abort", abort, { once: true });
|
||||
try {
|
||||
await client.unsafe(`SET statement_timeout = ${getPgTeardownDiagnosticsStatementTimeoutMs(probeTimeoutMs)}`);
|
||||
return await client.unsafe<PgTeardownActivityRow[]>(`
|
||||
SELECT pid, datname, usename, state, wait_event_type, wait_event, backend_type,
|
||||
now() - query_start AS query_age, left(query, 200) AS query,
|
||||
count(*) OVER ()::int AS total_backends
|
||||
FROM pg_stat_activity
|
||||
ORDER BY datname NULLS LAST, pid
|
||||
`);
|
||||
} finally {
|
||||
signal.removeEventListener("abort", abort);
|
||||
await client.end({ timeout: 5 }).catch(() => {});
|
||||
}
|
||||
};
|
||||
}
|
||||
|
||||
async function adminExecAsync(statement: string, timeoutMs = 15_000): Promise<void> {
|
||||
let timedOut = false;
|
||||
let timeoutHandle: ReturnType<typeof setTimeout> | undefined;
|
||||
@@ -864,36 +906,54 @@ export async function createTaskStoreForTest(options?: {
|
||||
const teardown = async (): Promise<void> => {
|
||||
if (tornDown) return;
|
||||
tornDown = true;
|
||||
/*
|
||||
FNXC:PgTestHarnessTeardownDiagnostics 2026-08-16-19:40:
|
||||
Loaded-core JSONL evidence must identify the Vitest file that owns a shared
|
||||
harness teardown; database-name prefixes cannot reliably distinguish files.
|
||||
Read Vitest's active caller state only at teardown entry, after the harness
|
||||
has been created from beforeAll, so no global per-test state is retained.
|
||||
*/
|
||||
const testFile = vitestExpect.getState().testPath;
|
||||
const diagnostics = createPgTeardownDiagnostics({
|
||||
probe: createPgStatActivityProbe(),
|
||||
...(testFile ? { testFile } : {}),
|
||||
});
|
||||
diagnostics.beginTeardown();
|
||||
try {
|
||||
store.stopWatching();
|
||||
} catch {
|
||||
// best-effort
|
||||
}
|
||||
try {
|
||||
await store.close();
|
||||
} catch {
|
||||
// best-effort
|
||||
}
|
||||
try {
|
||||
await layer.close();
|
||||
} catch {
|
||||
// best-effort
|
||||
}
|
||||
try {
|
||||
await adminSql.end({ timeout: 5 });
|
||||
} catch {
|
||||
// best-effort
|
||||
}
|
||||
try {
|
||||
// FNXC:PgTestHarness 2026-07-18-17:27: FORCE so open pool sockets cannot block drop after close races.
|
||||
await adminExecAsync(`DROP DATABASE IF EXISTS "${dbName}" WITH (FORCE)`);
|
||||
} catch {
|
||||
// best-effort
|
||||
}
|
||||
try {
|
||||
await rm(rootDir, { recursive: true, force: true });
|
||||
} catch {
|
||||
// best-effort
|
||||
try {
|
||||
store.stopWatching();
|
||||
} catch {
|
||||
// best-effort
|
||||
}
|
||||
try {
|
||||
await diagnostics.runPhase("store.close", () => store.close());
|
||||
} catch {
|
||||
// best-effort
|
||||
}
|
||||
try {
|
||||
await diagnostics.runPhase("layer.close", () => layer.close());
|
||||
} catch {
|
||||
// best-effort
|
||||
}
|
||||
try {
|
||||
await diagnostics.runPhase("adminSql.end", () => adminSql.end({ timeout: 5 }));
|
||||
} catch {
|
||||
// best-effort
|
||||
}
|
||||
try {
|
||||
// FNXC:PgTestHarness 2026-07-18-17:27: FORCE so open pool sockets cannot block drop after close races.
|
||||
await diagnostics.runPhase("dropDatabase", () => adminExecAsync(`DROP DATABASE IF EXISTS "${dbName}" WITH (FORCE)`));
|
||||
} catch {
|
||||
// best-effort
|
||||
}
|
||||
try {
|
||||
await diagnostics.runPhase("rmRootDir", () => rm(rootDir, { recursive: true, force: true }));
|
||||
} catch {
|
||||
// best-effort
|
||||
}
|
||||
} finally {
|
||||
diagnostics.completeTeardown();
|
||||
diagnostics.dispose();
|
||||
}
|
||||
};
|
||||
|
||||
|
||||
162
packages/core/src/__tests__/pg-teardown-diagnostics.test.ts
Normal file
162
packages/core/src/__tests__/pg-teardown-diagnostics.test.ts
Normal file
@@ -0,0 +1,162 @@
|
||||
import { describe, expect, it, vi, afterEach } from "vitest";
|
||||
import {
|
||||
__resetPgTeardownDiagnosticsProbeCountForTest,
|
||||
createPgTeardownDiagnostics,
|
||||
getPgTeardownDiagnosticsProbeTimeoutMs,
|
||||
getPgTeardownDiagnosticsStatementTimeoutMs,
|
||||
type PgTeardownActivityRow,
|
||||
} from "../__test-utils__/pg-teardown-diagnostics.js";
|
||||
|
||||
const enabledEnv = {
|
||||
FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS: "1",
|
||||
FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_THRESHOLD_MS: "20",
|
||||
FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_HOOK_WATCHDOG_MS: "60",
|
||||
FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_PROBE_TIMEOUT_MS: "10",
|
||||
};
|
||||
|
||||
afterEach(() => {
|
||||
vi.useRealTimers();
|
||||
__resetPgTeardownDiagnosticsProbeCountForTest();
|
||||
});
|
||||
|
||||
function recordsFrom(lines: string[]) {
|
||||
return lines.map((line) => JSON.parse(line) as { trigger: string; phase?: string; phaseIncomplete?: boolean; elapsedAtSnapshotMs?: number; probeRan: boolean; probeSuppressed?: string; snapshotRows?: PgTeardownActivityRow[]; phaseDurationsMs: Record<string, number> });
|
||||
}
|
||||
|
||||
describe("PG teardown diagnostics", () => {
|
||||
it("is inert when disabled", async () => {
|
||||
const setTimer = vi.fn(setTimeout);
|
||||
const probe = vi.fn();
|
||||
const append = vi.fn();
|
||||
const diagnostics = createPgTeardownDiagnostics({ env: {}, setTimer, probe, append });
|
||||
diagnostics.beginTeardown();
|
||||
await diagnostics.runPhase("store.close", async () => {});
|
||||
diagnostics.completeTeardown();
|
||||
diagnostics.dispose();
|
||||
expect(diagnostics.enabled).toBe(false);
|
||||
expect(setTimer).not.toHaveBeenCalled();
|
||||
expect(probe).not.toHaveBeenCalled();
|
||||
expect(append).not.toHaveBeenCalled();
|
||||
});
|
||||
|
||||
it("includes the caller test-file identity in durable records", async () => {
|
||||
const lines: string[] = [];
|
||||
const diagnostics = createPgTeardownDiagnostics({
|
||||
env: { ...enabledEnv, FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_LOG: "memory" },
|
||||
testFile: "src/__tests__/postgres/mission-store.pg.test.ts",
|
||||
append: (_path, line) => lines.push(line),
|
||||
writeError: () => {},
|
||||
});
|
||||
await diagnostics.runPhase("store.close", async () => {});
|
||||
expect(JSON.parse(lines[0] ?? "{}")).toMatchObject({
|
||||
testFile: "src/__tests__/postgres/mission-store.pg.test.ts",
|
||||
phase: "store.close",
|
||||
});
|
||||
});
|
||||
|
||||
it("keeps PostgreSQL statement timeout below a reduced probe bound", () => {
|
||||
const probeTimeoutMs = getPgTeardownDiagnosticsProbeTimeoutMs({
|
||||
FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_PROBE_TIMEOUT_MS: "100",
|
||||
});
|
||||
expect(getPgTeardownDiagnosticsStatementTimeoutMs(probeTimeoutMs)).toBeLessThanOrEqual(probeTimeoutMs);
|
||||
expect(getPgTeardownDiagnosticsStatementTimeoutMs(probeTimeoutMs)).toBe(1);
|
||||
});
|
||||
|
||||
it("records completed phases in order and clears unref'd watchdogs", async () => {
|
||||
vi.useFakeTimers();
|
||||
const lines: string[] = [];
|
||||
const setTimer = vi.fn((callback: () => void, ms: number) => setTimeout(callback, ms));
|
||||
const clearTimer = vi.fn(clearTimeout);
|
||||
const diagnostics = createPgTeardownDiagnostics({
|
||||
env: { ...enabledEnv, FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_LOG: "memory" },
|
||||
setTimer,
|
||||
clearTimer,
|
||||
append: (_path, line) => lines.push(line),
|
||||
writeError: () => {},
|
||||
});
|
||||
diagnostics.beginTeardown();
|
||||
await diagnostics.runPhase("store.close", async () => { await vi.advanceTimersByTimeAsync(5); });
|
||||
await diagnostics.runPhase("layer.close", async () => { await vi.advanceTimersByTimeAsync(5); });
|
||||
diagnostics.completeTeardown();
|
||||
diagnostics.dispose();
|
||||
expect(recordsFrom(lines).filter((record) => record.trigger === "phase-complete").map((record) => record.phase)).toEqual(["store.close", "layer.close"]);
|
||||
expect(clearTimer).toHaveBeenCalledTimes(3);
|
||||
expect(setTimer).toHaveBeenCalledTimes(3);
|
||||
});
|
||||
|
||||
it("flushes in-flight phase evidence synchronously while a phase never settles", async () => {
|
||||
vi.useFakeTimers();
|
||||
const lines: string[] = [];
|
||||
const probe = vi.fn(async () => [{ datname: "hung_db", state: "active", wait_event: "Lock" }]);
|
||||
const diagnostics = createPgTeardownDiagnostics({
|
||||
env: { ...enabledEnv, FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_LOG: "memory" },
|
||||
probe,
|
||||
append: (_path, line) => lines.push(line),
|
||||
writeError: () => {},
|
||||
});
|
||||
diagnostics.beginTeardown();
|
||||
void diagnostics.runPhase("dropDatabase", () => new Promise<void>(() => {}));
|
||||
await vi.advanceTimersByTimeAsync(20);
|
||||
const watchdog = recordsFrom(lines).find((record) => record.trigger === "phase-watchdog");
|
||||
expect(watchdog).toMatchObject({ phase: "dropDatabase", phaseIncomplete: true, probeRan: true });
|
||||
expect(watchdog?.elapsedAtSnapshotMs).toBeGreaterThanOrEqual(20);
|
||||
expect(probe).toHaveBeenCalledTimes(1);
|
||||
diagnostics.dispose();
|
||||
});
|
||||
|
||||
it("captures one whole-teardown watchdog even when no phase breaches", async () => {
|
||||
vi.useFakeTimers();
|
||||
const lines: string[] = [];
|
||||
const diagnostics = createPgTeardownDiagnostics({
|
||||
env: { ...enabledEnv, FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_LOG: "memory" },
|
||||
probe: async () => [],
|
||||
append: (_path, line) => lines.push(line),
|
||||
writeError: () => {},
|
||||
});
|
||||
diagnostics.beginTeardown();
|
||||
await vi.advanceTimersByTimeAsync(60);
|
||||
await vi.advanceTimersByTimeAsync(60);
|
||||
expect(recordsFrom(lines).filter((record) => record.trigger === "teardown-watchdog")).toHaveLength(1);
|
||||
diagnostics.dispose();
|
||||
});
|
||||
|
||||
it("is single-flight, caps probes, and fences rejected or abandoned probes", async () => {
|
||||
vi.useFakeTimers();
|
||||
const lines: string[] = [];
|
||||
let rejectProbe!: (error: Error) => void;
|
||||
const probe = vi.fn(() => new Promise<readonly PgTeardownActivityRow[]>((_resolve, reject) => { rejectProbe = reject; }));
|
||||
const diagnostics = createPgTeardownDiagnostics({
|
||||
env: { ...enabledEnv, FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_MAX_PROBES: "1", FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_LOG: "memory" },
|
||||
probe,
|
||||
append: (_path, line) => lines.push(line),
|
||||
writeError: () => {},
|
||||
});
|
||||
diagnostics.beginTeardown();
|
||||
void diagnostics.runPhase("store.close", () => new Promise<void>(() => {}));
|
||||
await vi.advanceTimersByTimeAsync(20);
|
||||
void diagnostics.runPhase("layer.close", () => new Promise<void>(() => {}));
|
||||
await vi.advanceTimersByTimeAsync(25);
|
||||
expect(probe).toHaveBeenCalledTimes(1);
|
||||
expect(recordsFrom(lines).some((record) => record.probeSuppressed === "single-flight" || record.probeSuppressed === "cap")).toBe(true);
|
||||
rejectProbe(new Error("late probe failure"));
|
||||
await Promise.resolve();
|
||||
diagnostics.dispose();
|
||||
});
|
||||
|
||||
it("writes schema records and formatted activity output without letting sink failures escape", async () => {
|
||||
vi.useFakeTimers();
|
||||
const output: string[] = [];
|
||||
const diagnostics = createPgTeardownDiagnostics({
|
||||
env: { ...enabledEnv, FUSION_PG_TEST_TEARDOWN_DIAGNOSTICS_LOG: "/unwritable/log" },
|
||||
probe: async () => [{ datname: "postgres", state: "active", wait_event: "ClientRead" }],
|
||||
append: () => { throw new Error("no sink"); },
|
||||
writeError: (line) => output.push(line),
|
||||
});
|
||||
diagnostics.beginTeardown();
|
||||
void diagnostics.runPhase("adminSql.end", () => new Promise<void>(() => {}));
|
||||
await vi.advanceTimersByTimeAsync(20);
|
||||
expect(output.join("\n")).toContain("adminSql.end");
|
||||
expect(output.join("\n")).toContain("phase-watchdog");
|
||||
diagnostics.dispose();
|
||||
});
|
||||
});
|
||||
@@ -9,8 +9,12 @@
|
||||
* counts; reorderMilestones/reorderSlices new order; linkGoal/unlinkGoal +
|
||||
* listGoalIdsForMission round-trip; linkFeatureToTask/unlinkFeatureFromTask;
|
||||
* addContractAssertion → listContractAssertions; startValidatorRun → getValidatorRunsByFeature;
|
||||
* computeMissionStatus reflects state; missing mission → undefined. Runs in the blocking
|
||||
* gate (test:pg-gate).
|
||||
* computeMissionStatus reflects state; missing mission → undefined. This remains in default
|
||||
* core discovery; `test:pg-gate` intentionally runs only its two PostgreSQL canaries.
|
||||
*
|
||||
* FNXC:MissionStore 2026-08-16-19:32:
|
||||
* FN-9127 corrected the stale gate-membership claim so loaded-teardown diagnosis runs the
|
||||
* actual default-core surface instead of implying this suite is a blocking PG-gate canary.
|
||||
*/
|
||||
|
||||
import { describe, it, expect, beforeAll, beforeEach, afterEach, afterAll, vi } from "vitest";
|
||||
|
||||
Reference in New Issue
Block a user