From 1c9e4dfccd75b44bde3cfd103b10d16a355f62f5 Mon Sep 17 00:00:00 2001 From: gsxdsm Date: Sun, 16 Aug 2026 12:59:23 -0700 Subject: [PATCH] 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) --- .../suite-only-flakes-observed-register.md | 12 + docs/testing.md | 19 ++ .../__test-utils__/pg-teardown-diagnostics.ts | 237 ++++++++++++++++++ .../src/__test-utils__/pg-test-harness.ts | 120 ++++++--- .../__tests__/pg-teardown-diagnostics.test.ts | 162 ++++++++++++ .../postgres/mission-store.pg.test.ts | 8 +- 6 files changed, 526 insertions(+), 32 deletions(-) create mode 100644 packages/core/src/__test-utils__/pg-teardown-diagnostics.ts create mode 100644 packages/core/src/__tests__/pg-teardown-diagnostics.test.ts diff --git a/docs/solutions/test-failures/suite-only-flakes-observed-register.md b/docs/solutions/test-failures/suite-only-flakes-observed-register.md index 0d67762b7f..f42f4102a9 100644 --- a/docs/solutions/test-failures/suite-only-flakes-observed-register.md +++ b/docs/solutions/test-failures/suite-only-flakes-observed-register.md @@ -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` diff --git a/docs/testing.md b/docs/testing.md index af91051152..599b8913c6 100644 --- a/docs/testing.md +++ b/docs/testing.md @@ -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. + + +### 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. + diff --git a/packages/core/src/__test-utils__/pg-teardown-diagnostics.ts b/packages/core/src/__test-utils__/pg-teardown-diagnostics.ts new file mode 100644 index 0000000000..d6df6c2c6a --- /dev/null +++ b/packages/core/src/__test-utils__/pg-teardown-diagnostics.ts @@ -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>; + 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; +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 testFile?: string; +} + +export interface PgTeardownDiagnostics { + readonly enabled: boolean; + beginTeardown(): void; + completeTeardown(): void; + runPhase(phase: string, action: () => Promise): Promise; + 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(_phase: string, action: () => Promise): Promise { 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 = {}; + 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): 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(phase: string, action: () => Promise): Promise { + 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; + }, + }; +} diff --git a/packages/core/src/__test-utils__/pg-test-harness.ts b/packages/core/src/__test-utils__/pg-test-harness.ts index 68ca50f409..6cad2e339e 100644 --- a/packages/core/src/__test-utils__/pg-test-harness.ts +++ b/packages/core/src/__test-utils__/pg-test-harness.ts @@ -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 { + 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(` + 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 { let timedOut = false; let timeoutHandle: ReturnType | undefined; @@ -864,36 +906,54 @@ export async function createTaskStoreForTest(options?: { const teardown = async (): Promise => { 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(); } }; diff --git a/packages/core/src/__tests__/pg-teardown-diagnostics.test.ts b/packages/core/src/__tests__/pg-teardown-diagnostics.test.ts new file mode 100644 index 0000000000..15d810ce4a --- /dev/null +++ b/packages/core/src/__tests__/pg-teardown-diagnostics.test.ts @@ -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 }); +} + +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(() => {})); + 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((_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(() => {})); + await vi.advanceTimersByTimeAsync(20); + void diagnostics.runPhase("layer.close", () => new Promise(() => {})); + 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(() => {})); + await vi.advanceTimersByTimeAsync(20); + expect(output.join("\n")).toContain("adminSql.end"); + expect(output.join("\n")).toContain("phase-watchdog"); + diagnostics.dispose(); + }); +}); diff --git a/packages/core/src/__tests__/postgres/mission-store.pg.test.ts b/packages/core/src/__tests__/postgres/mission-store.pg.test.ts index f5f732f5c6..707799c9aa 100644 --- a/packages/core/src/__tests__/postgres/mission-store.pg.test.ts +++ b/packages/core/src/__tests__/postgres/mission-store.pg.test.ts @@ -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";