diff --git a/docs/PROJECT_STATE.md b/docs/PROJECT_STATE.md index 1ca55efa..db8e2c78 100644 --- a/docs/PROJECT_STATE.md +++ b/docs/PROJECT_STATE.md @@ -4,7 +4,70 @@ > to read **only this file** and continue immediately. Updated after every > milestone and every significant architectural step. -_Last updated: 2026-09-03 — M15 Increment 44: Signature B parent-side termination evidence._ +_Last updated: 2026-09-03 — M15 Increment 45: PostgreSQL isolated-database teardown race._ + + +## M15 Increment 45 — PostgreSQL isolated-database teardown race + +The intermittent `postgres integration (persistence)` failure recorded during Increment 44 — +`terminating connection due to administrator command`, arriving as an uncaught exception attributed +to whichever test happened to be running — is closed. It was a lifecycle defect in the test helpers, +not in migration logic: migration order, SQL, checksums, transaction semantics and advisory-lock +semantics are all untouched, and no migration was added. + +**Mechanism, measured rather than assumed.** `withDatabase` ended its pool and then immediately ran +`DROP DATABASE ... WITH (FORCE)`. `pool.end()` does not wait for its clients to close: in pg 8.22.0 +`_pulseQueue` reaches the end callback in the same synchronous turn in which `_remove` filters the +last client out of `_clients`, while `client.end()` has only queued the Terminate byte. Instrumented +here, **zero of four `remove` events had fired at the moment `end()` resolved**. A drop issued +straight afterwards could therefore still find a backend attached; `FORCE` terminated it, and the +`FATAL` landed on a socket whose pool still had `idleListener` attached — `_remove` never detaches +it — so `pg` re-emitted it as `pool.emit('error')`, an unhandled EventEmitter error. + +**`WITH (FORCE)` was not required, and was the harm.** Measured against PostgreSQL 16.14 with a +backend deliberately held open: plain `DROP DATABASE` fails with SQLSTATE 55006 and leaves that +connection untouched, where `WITH (FORCE)` succeeds by killing it. The fix trades a quiet, harmful +success for a loud, harmless failure — teardown waits for the database to be genuinely unused, then +drops it ordinarily, so the normal path terminates nothing. + +FORCE survives only on the emergency path, reached once teardown has already failed, and there it is +**best effort in both directions**. It does terminate whatever is still attached — the helper +installs an error listener on the pool and on every live client first, so the FATAL it causes cannot +escape as an uncaught error — and the final fallback drop runs inside a `catch`, so a cleanup failure +cannot bury the error being reported. A server that refuses that drop can therefore still leave a +database behind. Which of the two happened is recorded rather than assumed: +`DatabaseTeardownTimeoutError` carries `droppedDatabase`, with any failed drop attached as its +`cause`. Anyone diagnosing a teardown should read that flag instead of taking a reported timeout to +mean the server came out clean. + +**Shared helper.** `packages/persistence/src/test-support/database.ts` exposes `withTestDatabase` +through the new `@chess-platform/persistence/test-support` subpath, kept off the driver-facing `./pg` +surface. Both isolated-database call sites use it: `variant-migrations.integration.test.ts` and +`packages/api/test/auth-signin-schema.integration.test.ts`. The latter previously carried a +`pool.on('error', ...)` listener absorbing SQLSTATE 57P01 — a symptom fix for this same race, added +when it surfaced there first. **That listener is deleted**: the corrected lifecycle never terminates +a connection, so there is nothing to absorb, and a real connection failure in those tests is once +again as loud as it should be. `createPool` and `migrate` are unchanged; no production code moved. + +Teardown is bounded — `pool.end()` included, because a client checked out and never released leaves +it pending indefinitely (measured past a three-second bound) — names the lingering backends when it +gives up, and never lets a cleanup failure replace the assertion +the test actually failed on. It drops the disposable database on every path it can reach, including the +one where it gives up — but that last-resort drop is best effort: it runs inside a `catch` so a +cleanup failure cannot bury the error already being reported, which means a server that refuses the +drop can still leave a database behind. Ten regression tests pin the contract against a real server; none asserts on +elapsed wall-clock time, which would measure the machine rather than the guarantee. The emergency +path owns the termination it causes: it attaches a listener to the pool *and* to every live client +before force-dropping, because a client the callback checked out and never released is not idle, so +`pg` has removed its `idleListener` and the pool would never see its FATAL at all. + +**Found while validating, not fixed here:** the persistence suite is not idempotent against a reused +database. A second consecutive run against the same server fails — 12 tests on `b95065f`, 9 with +this change — in the achievements, identity-tokens and tournaments repositories, which share +`chess_test` rather than taking a database of their own. CI provisions a fresh server every run, so +it has never surfaced there. Pre-existing, and out of scope for this increment. + +**Signature B remains UNRESOLVED.** It is a separate defect and nothing here touches it. ## M15 Increment 44 — Signature B parent-side termination evidence diff --git a/docs/ROADMAP.md b/docs/ROADMAP.md index 7bce2f42..b0ff9707 100644 --- a/docs/ROADMAP.md +++ b/docs/ROADMAP.md @@ -1350,6 +1350,7 @@ Debt observed during M14. Each states what is known, not what is planned; items - **The search surface was not gated on `capabilities.search`, so an absolute kill switch still showed a search box (RESOLVED in M15 Increment 24 / ADR-0132 §5).** `SEARCH_ENABLED=0` — the chart's `search.enabled: false`, an absolute kill switch per ADR-0055 — leaves `searchRepository` unconstructed and `GET /v1/search` answering 503 on every mode, keyword included. The entry point was the persistent header form in `packages/web/index.html`, present on every page; being a `
` rather than an `a[data-route]`, `NAV_CAPABILITY_MAP` could not reach it, which is why the first pass at Increment 24 gated the semantic and hybrid *modes* and left keyword ungated — the same defect class one mode over. Raised by the Qodo review of PR #155. **Fixed in the same increment rather than deferred:** the form now ships `hidden` and is revealed by `applySearchCapability` only on an explicit `search: true`; the route renders an honest unavailable notice and issues no request; and keyword search waits for the capability answer, reversing this increment's own earlier latency decision, because knowing whether a request is pointless requires having asked. A markup-contract test pins the `hidden` attribute, since the gate depends on it and every other test passes without it. - **Clicking a search mode discarded text typed since the page loaded (RESOLVED in a follow-up to M15 Increment 24 / ADR-0132).** `createModeInput` in `packages/web/src/app/search-mount.ts` closed over the query captured when the route mounted, so `navigateToSearchMode` navigated with the old term and the remount reset the input to match it. Type a new term into the header field, click **Semantic** without pressing enter, and the typed text was gone with no indication it had been discarded. Pre-existing — the closure predated Increment 24 and was untouched by it — and found by the adversarial review of PR #155 while reviewing the capability gate wrapped around the same control. **Resolved:** the query is now a `() => string` read when a mode is chosen rather than a string captured when the selector renders, matching what `main.ts`'s submit handler already does, and falling back to the mounted query only where the document has no header input. Two regression tests, one of which fails against the exact pre-fix closure. - **`startHarness` drew ports `fetch` refuses (RESOLVED in ADR-0140); the unexplained whole-file failure is still open.** Two signatures were filed here, deliberately not as one cause, and that judgement held. **Signature A is resolved.** WHATWG Fetch blocks eighty-two ports and undici enforces the list on the port number alone, before opening a socket — so `server.listen(0)` could bind, listen and answer raw TCP while `fetch` still refused, surfacing as `TypeError: fetch failed` / `Error: bad port` at the harness’s first request rather than at the listen that caused it. Whether it can happen at all is a property of the host’s dynamic port range: a typical Linux CI range (32768–60999) contains no blocked port, while the Windows range in use here (1024–15000) contains nineteen, which is the whole of "green on CI, flaky locally". The guard that already existed was incomplete in a way that still failed — its hand-observed set of eighteen ports was the spec list intersected with one machine’s range **minus `6679`** — and it retried unboundedly, had no behaviour on exhaustion, and had been copy-pasted into `auth-signin-schema.integration.test.ts`, so the missing port had to be found twice. `packages/api/test/listen.ts` now owns port acquisition for both sites: the spec-complete eighty-two ports (verified by sweeping all 65535 through the real `fetch` on Node v24.15.0), a bounded twenty attempts, each rejected listener closed before the next is asked for, a guarded `address()` read in place of the `as AddressInfo` cast, and an exhaustion error naming the attempts and rejected ports and nothing else. **Signature B is not resolved and was not folded in.** A file still fails with `'test failed'`, no assertion, no stack and none of its own tests reported. Twenty consecutive full runs gave five failures: on pre-fix code one signature A (`auth.test.js`) and three signature B; on post-fix code one signature B and no signature A. The port fix removes A and leaves B exactly where it was, which is the evidence that they are two defects. Four different files were hit (`move-explanation-route`, `tournament-commentary-route`, `bot-detection-analyze`, `anti-cheat-analysis`), sharing no import beyond `./helpers`; each died in 589–703 ms with no test of its own reporting and no stderr. Refuted with evidence: ephemeral-port exhaustion (113 sockets in TIME_WAIT against a 13977-port range), a `Promise.race` loser becoming an unhandled rejection (`race` subscribes to every promise, confirmed on v24.15.0), a throwing `after`/`afterEach` hook (the affected files use none), and a double `close()` rejecting (awaited in a `finally`, it would be attributed to that test with a stack). A second bounded pass — twelve more full runs under the TAP reporter with a preload recording `uncaughtException`, `unhandledRejection` and any non-zero exit — produced twelve clean runs and captured nothing at the time. **A follow-up increment (`claude/node-test-signature-b`) then captured the defect directly, three more times, on three files never previously implicated** (`rate-limit-atomicity`, `dependency-parity`, `studies-api`) — seven distinct files observed with this symptom to date. Occurrences across seven distinct files make a shared or cross-cutting path more plausible and make a defect confined to one test file less likely, but do not exclude file-specific inputs or lifecycle interactions. An instrumented preload (`packages/api/test/diagnostics/signature-b-preload.cjs`) hooking process-level events — `process.exit`, `process.abort`, `process.kill`, `uncaughtExceptionMonitor` (passively observing uncaught exceptions and fatal unhandled rejections), `warning`, `beforeExit`, and Node’s own unconditional `exit` — showed **none of the hooks active at the time fired** on any of the three historical captures (though `process.abort()` was not wrapped in those initial runs and is now covered for future occurrences). A synthetic `process.exit(1)`-before-registration fixture reproduces the identical silent shape; every other synthetic mechanism tried (a post-test async throw, an emitter `'error'` with its listener removed, a synchronous module-load throw, a delayed `SIGKILL`) prints a visibly different diagnostic line, stack, or partial test output that the real defect never shows. This narrows the investigated possibilities while leaving the root cause unresolved: the per-file child process (`node --test` spawns one per file, confirmed by distinct PIDs) was not terminated by `process.exit`, uncaught exceptions, or fatal unhandled rejections, and future runs with `process.abort` instrumentation will record whether abort was called through JS; an absent record narrows in-runtime JS termination but cannot alone prove external termination without corroborating child exit status/signal data or OS-level crash evidence (e.g. distinguishing an external kill or uncatchable signal from a native C++/V8 crash). The machine had roughly 2.5 GB of 15.7 GB RAM free at capture time with several other agents’ processes concurrently running, which is circumstantially consistent with resource contention, but no crash was recorded in the Windows Application or System event logs in that window, so the exact external trigger is still not established. No fix was invented — the forbidden responses (sleeps, whole-file retries, lowering concurrency) would only hide the unresolved root cause, whose origin is not yet established. **A further increment then crossed the parent/child boundary the earlier work stopped at, and found the evidence had been there all along:** Node's runner attaches the child's `exitCode` and `signal` to the `ERR_TEST_FAILURE` it throws, and the `spec` reporter discards them — `formatError` replaces the error with `error.cause`, the bare string `'test failed'` — while the built-in `tap` reporter serializes them, so running `spec` to stdout and `tap` to a file recovers the exit status with no custom reporter and no patched internals. Exit codes were measured on this platform rather than assumed: `process.abort()` gives `134`, `Stop-Process -Force` gives `4294967295`, NTSTATUS faults surface as raw unsigned values such as `3221225477` (`0xC0000005`) — and `1` is produced alike by an uncaught exception, `process.exit(1)`, `taskkill /F` and `process.kill`, so it identifies nothing on its own and is classified `inconclusive`. `signature-b-correlate.cjs` joins the parent's TAP record to the child's JSONL log on the test file path (which also yields the child PID) and states what the pair does and does not establish; where the exit code is ambiguous, a child that reached `preload-installed` and then logged nothing still excludes `process.exit` and an uncaught exception, because both would have left a record and fired Node's `exit` event. A bounded pass of 20 runs under this instrumentation produced 0 captures — which bounds the rate and proves nothing: treating the historical ~1-in-5 as an independent per-run rate, zero captures in 20 runs has probability `(4/5)^20 ≈ 1.2%`, and independence is an assumption rather than an established fact; it ran at 3084–3834 MB free against roughly 2.5 GB at the historical captures, consistent with the resource-contention hypothesis but not evidence for it. **Signature B stays UNRESOLVED**; what changed is that the next occurrence is readable rather than silent. See ADR-0140 §4. +- **Isolated-database test teardown dropped databases out from under connections that had not finished closing (RESOLVED in M15 Increment 45).** `withDatabase` in `packages/persistence/test/variant-migrations.integration.test.ts` ended its pool and then immediately ran `DROP DATABASE ... WITH (FORCE)`. `pool.end()` does not wait for its clients to close: in pg 8.22.0 `_pulseQueue` reaches the end callback in the same synchronous turn in which `_remove` filters the last client out of `_clients`, while `client.end()` has only queued the Terminate byte — instrumentation recorded **zero of four `remove` events fired at the moment `end()` resolved**. The drop could therefore still find a backend attached; `FORCE` terminated it, and the resulting `FATAL` arrived on a socket whose pool still had `idleListener` attached, which `pg` re-emitted as `pool.emit('error')` — an unhandled EventEmitter error that `node:test` attributed to whichever test was running rather than to the teardown that caused it. It surfaced as intermittent `terminating connection due to administrator command` failures in `postgres integration (persistence)` during M15 Increment 44, on a different test each run, which is the signature of a race rather than a broken assertion. The same shape existed in `packages/api/test/auth-signin-schema.integration.test.ts`, which had absorbed SQLSTATE 57P01 with a `pool.on('error', ...)` listener — a symptom fix for the same cause. **Resolved in Increment 45:** a shared `withTestDatabase` helper (`@chess-platform/persistence/test-support`) ends the pool under a bound, waits for `pg_stat_activity` to report the database unused, and drops it *without* `FORCE`. Measured on PostgreSQL 16.14, a plain drop against a still-attached backend fails with SQLSTATE 55006 and leaves that connection untouched, where `FORCE` succeeds by killing it — so the change trades a quiet, harmful success for a loud, harmless failure. FORCE remains only on the emergency path that guarantees the disposable database is still dropped once teardown has already failed — best effort, since that last drop runs inside a `catch` so it cannot bury the error being reported. The 57P01 absorber is deleted, because the corrected lifecycle never causes one. `createPool` and `migrate` are unchanged, and no migration was added. - **`ApiServer.listen` registered no `'error'` handler, so a failed bind hung and raised an uncaught event (RESOLVED in ADR-0140 §5).** `packages/api/src/server.ts` resolved its promise from the `listening` callback only and built it with no reject path. A bind failing asynchronously (`EADDRINUSE`, `EMFILE`) left the promise pending forever and, with no `'error'` listener on the `http.Server`, was re-raised as an uncaught exception. Found while investigating ADR-0140 and independently raised by the Qodo review of PR #21. **Resolved in the same increment** rather than deferred, because ADR-0140 §2's bounded, diagnosable acquisition is not true without it — the retry can only report a bind error if the listener it is handed rejects. A one-shot `'error'` listener now rejects and is removed once listening, so later server errors keep their previous semantics rather than being swallowed by a `reject` on a settled promise. The regression test fails against the exact pre-fix code, through an uncaught `ERR_UNHANDLED_ERROR`. - **`main.ts`'s controller-disposal list is manual, untested, and silently incomplete when a section is added (RESOLVED in Increment 25 / ADR-0092).** `run()` in `packages/web/src/main.ts` disposes the previous route's controllers by name, and its own comment says doing so "is what makes re-bootstrapping safe" — but adding a section to `bootstrap` and forgetting to add it there compiles, passes every gate, and leaks. Increment 23 shipped exactly that omission for `LearningController` and it was caught in PR review, not by a test. `main.ts` has no test coverage of any kind, so no section's disposal is verified. A structural fix (bootstrap returning its disposables as a collection, or a type-level exhaustiveness check keyed off the result type) would make the next omission a compile error; it is a refactor across ~15 return sites and belongs in its own increment. **Resolved in Increment 25 (ADR-0092):** extracted `createLifecycle` run loop in `lifecycle.ts`, defined `BootstrappedDisposables` and `DisposableKey` driving `DISPOSABLE_TEARDOWN_MAP: Record` for compile-time exhaustiveness, normalised `.dispose()` verb across all disposables, and cascaded `GameController.stop()` to `gameSync.stop()`. - **`stepView` sends the answers to the learner (RESOLVED in Increment 29 / ADR-0095).** `packages/api/src/presenters.ts` emits `expectedSan` on a move step and `correctIndex` on a quiz step, and `GET /v1/lessons/:id/steps` is the route the learner's own lesson page calls. Increment 23 omits both from the client-side types (`packages/web/src/api/models.ts`), so the app cannot render or grade against them and a future edit that tries becomes a compile error — but the fields are still on the wire and readable in devtools. The authoring routes legitimately need them returned to the author, so the fix is a learner-scoped step view (or a caller-dependent projection), not a deletion: an API contract decision with its own ADR. Nothing rated or rewarded depends on step progress today, so this is a wart rather than a breach. **Resolved in Increment 29 (ADR-0095):** added `LearnerStepView` / `learnerStepView` in `packages/api/src/presenters.ts` omitting `expectedSan` and `correctIndex`. `GET /v1/lessons/:id/steps` and `GET /v1/steps/:id` now check course authorship via `repo.getLesson` / `repo.getCourse`, returning full `stepView` to the author and `learnerStepView` to learners and anonymous callers. Updated OpenAPI schema and web model comments. The first attempt resolved authorship with a separate `getLesson` + `getCourse` after the step read, which doubled both routes from 3 SQL queries to 6 because `listSteps` / `getStep` had already made those reads internally and discarded the course; caught in the PR #92 review and fixed by adding `getStepWithCourse` / `listStepsWithCourse` to `LearningRepository`, which return what was already loaded. Both routes now make exactly one repository call, pinned by a counting-proxy test. diff --git a/packages/api/test/auth-signin-schema.integration.test.ts b/packages/api/test/auth-signin-schema.integration.test.ts index 6c376edb..b732ed35 100644 --- a/packages/api/test/auth-signin-schema.integration.test.ts +++ b/packages/api/test/auth-signin-schema.integration.test.ts @@ -35,12 +35,12 @@ import { join } from 'node:path'; import type { Server } from 'node:http'; import { closeServer, listenOnFetchablePort } from './listen'; import { - createPool, migrate, migrationFiles, missingMigrations, migrationsDir, } from '@chess-platform/persistence/pg'; +import { withTestDatabase } from '@chess-platform/persistence/test-support'; import type { Pool } from 'pg'; import { createPgApiServer } from '../src/bootstrap'; import { JsonLogger } from '../src/ports/logger'; @@ -54,21 +54,6 @@ const TEST_SECRET = 'test-access-token-secret-0123456789abcdef'; /** The loopback address this suite binds; also the host in the `baseUrl` it hands to `run`. */ const SERVER_HOST = '127.0.0.1'; -/** SQLSTATE 57P01 — `admin_shutdown`: the backend was terminated by `pg_terminate_backend`. */ -const ADMIN_SHUTDOWN = '57P01'; - -/** - * Absorb the one failure a forced database drop is expected to cause, and nothing else. - * - * Re-throwing restores the previous behaviour for every other error — an uncaught exception that - * stops the run — which is what an unexpected connection failure in these tests deserves. - */ -function rethrowUnlessForcedTermination(error: Error): void { - if ((error as { code?: string }).code === ADMIN_SHUTDOWN) return; - if (error.message.includes('terminating connection due to administrator command')) return; - throw error; -} - /** * A directory holding the first `count` migrations, copied byte-for-byte from the real ones. * @@ -93,79 +78,89 @@ interface Fixture { migrateTo(dir: string): Promise; } -/** The same server, same credentials, a different database name. */ -function databaseUrlFor(name: string): string { - const url = new URL(DATABASE_URL!); - url.pathname = `/${name}`; - return url.toString(); -} - /** * Run one case against an API server whose entire world is a private PostgreSQL database, created * for the test and dropped after it. */ async function withSchema(run: (fixture: Fixture) => Promise): Promise { - // Both pools are capped well below `pg`'s default of ten. This file runs inside a suite that - // already holds a great many connections against one server, and a test that quietly opened twenty - // more would push the next file over `max_connections` — which surfaces as that file failing, not - // this one. Two is the floor rather than one: `migrate` holds the advisory lock on a dedicated - // client and runs its statements on another, so a single-connection pool deadlocks against itself. - const admin = createPool({ connectionString: DATABASE_URL, max: 2 }); - const database = `signin_${Date.now().toString(36)}_${Math.floor(Math.random() * 1e9).toString(36)}`; - await admin.query(`CREATE DATABASE "${database}"`); - - const pool = createPool({ connectionString: databaseUrlFor(database), max: 4 }); - - // Dropping a database WITH (FORCE) terminates whatever backends are still attached to it, and a - // `pg` pool with no `error` listener re-emits that as an *uncaught exception* — which node:test - // attributes to whichever test happens to be running, not to the teardown that caused it. That is - // exactly how this arrived: "terminating connection due to administrator command", surfacing in CI - // as a failure of the next test along, while three local runs never raced. + // The pool is capped well below `pg`'s default of ten. This file runs inside a suite that already + // holds a great many connections against one server, and a test that quietly opened twenty more + // would push the next file over `max_connections` — which surfaces as that file failing, not this + // one. Two is the floor rather than one: `migrate` holds the advisory lock on a dedicated client + // and runs its statements on another, so a single-connection pool deadlocks against itself. // - // Only that one error is absorbed. A listener that swallowed everything would also hide a real - // connection failure in these tests, which is the opposite of what they are for — so anything else - // is re-thrown and stays as loud as it was before. The SQLSTATE is the test rather than the - // message, because `lc_messages` can translate the text and cannot translate `57P01`. - pool.on('error', rethrowUnlessForcedTermination); - admin.on('error', rethrowUnlessForcedTermination); - // Errors only: a deliberately broken database is about to be exercised, and the point of these - // tests is the status codes, not a wall of expected failure logging. - const logger = new JsonLogger({}, { level: 'error', sink: () => {} }); - - const savedEnv = { NODE_ENV: process.env['NODE_ENV'], EMAIL_PROVIDER: process.env['EMAIL_PROVIDER'] }; - process.env['NODE_ENV'] = 'test'; - process.env['EMAIL_PROVIDER'] = 'console'; - - let http: Server | undefined; - let shutdownAnalysis: (() => Promise) | undefined; - try { - const composed = createPgApiServer({ pool, logger, config: { accessTokenSecret: TEST_SECRET } }); - shutdownAnalysis = composed.shutdownAnalysis; - - const listening = await listenOnFetchablePort( - (p, h) => composed.server.listen(p, h), - SERVER_HOST, - ); - http = listening.server; - - await run({ - baseUrl: `http://${SERVER_HOST}:${listening.port}`, - pool, - migrateTo: (dir) => migrate(pool, dir), - }); - } finally { - if (http) await closeServer(http); - if (shutdownAnalysis) await shutdownAnalysis(); - // Every connection to the database has to be gone before it can be dropped, and the admin pool - // is deliberately connected to a different one. - await pool.end(); - await admin.query(`DROP DATABASE IF EXISTS "${database}" WITH (FORCE)`); - await admin.end(); - for (const [key, value] of Object.entries(savedEnv)) { - if (value === undefined) delete process.env[key]; - else process.env[key] = value; - } - } + // This used to absorb SQLSTATE 57P01 on both pools, because ending the pool and immediately + // dropping the database WITH (FORCE) terminated backends the pool had not finished closing, and + // `pg` re-emitted that FATAL as an uncaught exception attributed to an unrelated test. That + // listener treated the symptom. `withTestDatabase` waits for the database to be genuinely unused + // and then drops it without FORCE, so nothing is terminated and there is no error to absorb — and + // a real connection failure in these tests is once again as loud as it should be. + await withTestDatabase( + async ({ pool }) => { + // Errors only: a deliberately broken database is about to be exercised, and the point of these + // tests is the status codes, not a wall of expected failure logging. + const logger = new JsonLogger({}, { level: 'error', sink: () => {} }); + + const savedEnv = { NODE_ENV: process.env['NODE_ENV'], EMAIL_PROVIDER: process.env['EMAIL_PROVIDER'] }; + process.env['NODE_ENV'] = 'test'; + process.env['EMAIL_PROVIDER'] = 'console'; + + let http: Server | undefined; + let shutdownAnalysis: (() => Promise) | undefined; + let caseFailed = false; + let caseError: unknown; + try { + const composed = createPgApiServer({ pool, logger, config: { accessTokenSecret: TEST_SECRET } }); + shutdownAnalysis = composed.shutdownAnalysis; + + const listening = await listenOnFetchablePort( + (p, h) => composed.server.listen(p, h), + SERVER_HOST, + ); + http = listening.server; + + await run({ + baseUrl: `http://${SERVER_HOST}:${listening.port}`, + pool, + migrateTo: (dir) => migrate(pool, dir), + }); + } catch (error) { + caseFailed = true; + caseError = error; + } + + // The server and the analysis worker both hold this pool, so they have to be shut down before + // the callback returns — teardown ends the pool the moment it does, and anything still using + // it would fail with "Cannot use a pool after calling end on the pool". + // + // Each step runs whatever the one before it did. Chained with plain awaits, a server that + // failed to close would skip `shutdownAnalysis` entirely, leaving the analysis worker holding + // this pool while teardown tried to end it — turning a small close failure into a teardown + // timeout and a run of pool-after-end errors. Restoring the environment must not be skipped + // either, or the next test in the file inherits it. + const cleanupFailures: unknown[] = []; + const record = (error: unknown): void => { + cleanupFailures.push(error); + }; + if (http) await closeServer(http).catch(record); + if (shutdownAnalysis) await shutdownAnalysis().catch(record); + for (const [key, value] of Object.entries(savedEnv)) { + if (value === undefined) delete process.env[key]; + else process.env[key] = value; + } + + // Same precedence the helper itself uses: the case's own failure is the one worth reading, and + // a cleanup failure rides along rather than replacing it. + if (caseFailed) { + if (cleanupFailures.length > 0 && caseError instanceof Error && caseError.cause === undefined) { + caseError.cause = cleanupFailures[0]; + } + throw caseError; + } + if (cleanupFailures.length > 0) throw cleanupFailures[0]; + }, + { connectionString: DATABASE_URL, max: 4 }, + ); } /** diff --git a/packages/persistence/package.json b/packages/persistence/package.json index bedc4c39..2bc6f23c 100644 --- a/packages/persistence/package.json +++ b/packages/persistence/package.json @@ -13,6 +13,10 @@ "./pg": { "types": "./dist/pg/index.d.ts", "default": "./dist/pg/index.js" + }, + "./test-support": { + "types": "./dist/test-support/database.d.ts", + "default": "./dist/test-support/database.js" } }, "files": [ diff --git a/packages/persistence/src/test-support/database.ts b/packages/persistence/src/test-support/database.ts new file mode 100644 index 00000000..5ce2e84d --- /dev/null +++ b/packages/persistence/src/test-support/database.ts @@ -0,0 +1,610 @@ +/** + * @packageDocumentation + * `@chess-platform/persistence/test-support` — a disposable PostgreSQL database per test. + * + * Test-only. Nothing under `src/pg` imports this and no production entry point re-exports it; it is + * a separate subpath so the driver-facing surface does not grow a test harness. + */ + +import type { Pool, PoolClient, QueryResult, QueryResultRow } from 'pg'; +import { createPool } from '../pg/pool'; + +/** A backend still attached to the disposable database when teardown wanted to drop it. */ +export interface LingeringBackend { + readonly pid: number; + readonly state: string | null; + readonly applicationName: string | null; +} + +/** What the callback is handed: an isolated database and a pool bound to it. */ +export interface TestDatabase { + readonly pool: Pool; + readonly database: string; + readonly connectionString: string; +} + +export interface TestDatabaseOptions { + /** Server to create the disposable database on. Defaults to `DATABASE_URL`. */ + readonly connectionString?: string; + /** + * Pool size handed to the callback. + * + * Two is the floor rather than one: `migrate` holds its advisory lock on a dedicated client and + * runs its statements on another, so a single-connection pool deadlocks against itself. + */ + readonly max?: number; + /** + * Budget for teardown, measured from the moment the callback returns. + * + * It bounds each teardown step rather than their sum: the wait for quiescence, the drop, and the + * last-resort drop are separately capped, so a server that stops answering costs a small multiple + * of this rather than the unbounded wait a between-await deadline check would allow. It is not + * applied as a `statement_timeout` on the admin pool, because that pool also runs the + * `CREATE DATABASE` this budget has nothing to do with. + */ + readonly teardownTimeoutMs?: number; + /** Gap between quiescence checks. */ + readonly pollIntervalMs?: number; + /** + * Called once per quiescence check with whatever is still attached. + * + * This exists so a regression test can prove teardown *waited* by observing a check that saw a + * backend, rather than asserting on elapsed wall-clock time — which measures the machine rather + * than the contract. + */ + readonly onQuiescenceCheck?: (backends: readonly LingeringBackend[]) => void; +} + +/** Teardown could not reach a state where the database was safe to drop within its budget. */ +export class DatabaseTeardownTimeoutError extends Error { + readonly database: string; + readonly lingering: readonly LingeringBackend[]; + /** + * Whether the emergency drop actually removed the database. + * + * The caller uses this rather than assuming a timeout implies a clean server: the forced drop is + * itself a query, and it can fail or overrun like any other. When it does, the database is still + * there and the last-resort drop still has work to do. + */ + readonly droppedDatabase: boolean; + + constructor( + database: string, + timeoutMs: number, + lingering: readonly LingeringBackend[], + droppedDatabase: boolean, + ) { + const who = + lingering.length > 0 + ? lingering + .map((b) => `pid ${b.pid} (${b.applicationName ?? 'unnamed'}, ${b.state ?? 'unknown state'})`) + .join(', ') + : 'nothing was visible on the server, so the pool itself never finished closing'; + super( + `database "${database}" was still in use ${timeoutMs}ms after its pool was closed: ${who}. ` + + (droppedDatabase + ? 'It has been dropped, but something held a connection it did not own.' + : 'Dropping it then failed too, so it may still be on the server — see this error’s cause.'), + ); + this.name = 'DatabaseTeardownTimeoutError'; + this.database = database; + this.lingering = lingering; + this.droppedDatabase = droppedDatabase; + } +} + +/** + * Force-drop for a teardown that has already failed, and report the timeout either way. + * + * The forced drop is a query like any other: it can fail, or overrun its own budget. Letting that + * escape would replace the typed timeout — and with it the list of backends that actually held the + * database, which is the only part of this a reader can act on. So the drop's failure becomes the + * timeout's `cause`, and whether it succeeded is recorded rather than assumed. + */ +async function reportTimeoutAfterForcedDrop( + admin: Pool, + pool: Pool, + clients: ReadonlySet, + database: string, + timeoutMs: number, + lingering: readonly LingeringBackend[], +): Promise { + let dropFailure: unknown; + try { + await forceDropAbandoned(admin, pool, clients, database, timeoutMs); + } catch (error) { + dropFailure = error; + } + const timeout = new DatabaseTeardownTimeoutError( + database, + timeoutMs, + lingering, + dropFailure === undefined, + ); + if (dropFailure !== undefined) timeout.cause = dropFailure; + throw timeout; +} + +/** + * Bound on creating the disposable database, covering both its connection and its statement. + * + * Deliberately generous, and deliberately *not* `teardownTimeoutMs`: creation happens before the + * callback runs and before there is any cleanup to start, so it has nothing to do with how long + * teardown may wait. Tests here set the teardown budget as low as 300ms to exercise the timeout + * path, and creation held to that would fail on a loaded server rather than on a real fault. + */ +const CREATE_TIMEOUT_MS = 30_000; + +/** SQLSTATE 55006 — `DROP DATABASE` refusing because a backend is still attached. */ +const OBJECT_IN_USE = '55006'; + +/** SQLSTATE 57P01 — `admin_shutdown`: the backend was terminated by `pg_terminate_backend`. */ +const ADMIN_SHUTDOWN = '57P01'; + +/** Reads the SQLSTATE off an unknown thrown value, or null when it carries none. */ +function sqlState(error: unknown): string | null { + if (typeof error !== 'object' || error === null) return null; + const code = (error as { code?: unknown }).code; + return typeof code === 'string' ? code : null; +} + +/** + * Whether an error is the backend termination this helper itself just asked for. + * + * SQLSTATE only. `pg` also reports a bare "Connection terminated unexpectedly" when the socket + * closes before the `FATAL` is read, and matching that string would absorb every unrelated + * disconnect too — a server restart, a dropped network — precisely while the emergency listeners are + * installed. 57P01 is the server saying it terminated the backend on command, which is the only + * thing this code has grounds to treat as its own doing. + */ +function isForcedTermination(error: unknown): boolean { + return sqlState(error) === ADMIN_SHUTDOWN; +} + +/** Replaces the database in a connection URL, leaving credentials and host alone. */ +function urlForDatabase(connectionString: string, database: string): string { + const url = new URL(connectionString); + url.pathname = `/${database}`; + return url.toString(); +} + +/** Sleeps, as the gap between two quiescence checks. */ +function delay(ms: number): Promise { + return new Promise((resolve) => setTimeout(resolve, ms)); +} + +/** A teardown step that ran out of budget, as opposed to one that failed on its own terms. */ +class TeardownDeadlineError extends Error { + constructor(what: string, timeoutMs: number) { + super(`withTestDatabase: ${what} exceeded its ${timeoutMs}ms budget`); + this.name = 'TeardownDeadlineError'; + } +} + +/** + * Run `work`, but stop waiting for it after `timeoutMs`. + * + * Checking `Date.now()` between awaits does not bound the awaits themselves: an established + * connection that stops answering would sit past the deadline with nothing to interrupt it, which + * would make the budget advisory rather than real. Every teardown step therefore goes through here. + * + * Losing the race abandons the wait, not the work — so callers that raced a *query* must also + * destroy the connection it was running on. {@link boundedQuery} is how they do that. + */ +async function withDeadline(work: Promise, timeoutMs: number, what: string): Promise { + let timer: NodeJS.Timeout | undefined; + try { + return await Promise.race([ + work, + new Promise((_resolve, reject) => { + timer = setTimeout(() => reject(new TeardownDeadlineError(what, timeoutMs)), timeoutMs); + }), + ]); + } finally { + if (timer !== undefined) clearTimeout(timer); + } +} + +/** + * Run one admin statement under the budget, and take its connection away if it overruns. + * + * Racing `pool.query()` alone is not enough to bound anything. The abandoned query keeps its client + * checked out, and `pool.end()` never closes a checked-out client — so the bounded end gives up too + * and the helper returns with live sockets and a query still running, which is the opposite of the + * guarantee. Leasing the client here makes it reachable: `release(true)` destroys it rather than + * returning it to the pool, which drops the socket the statement is waiting on. + * + * Only a deadline overrun destroys the connection. A statement that fails on its own terms — 55006 + * from a drop, say — has finished with its client, and that client is still perfectly good. + */ +async function boundedQuery( + admin: Pool, + timeoutMs: number, + what: string, + text: string, + values: readonly unknown[] = [], +): Promise> { + const lease = admin.connect(); + let client: PoolClient; + try { + client = await withDeadline(lease, timeoutMs, `${what} (connect)`); + } catch (error) { + // The deadline stops this waiting; it does not cancel the connect. A lease that lands afterwards + // would be checked out with nobody left to release it — and `pool.end()` waits for checked-out + // clients, so the pool this was meant to bound would never close. Destroy the late arrival + // instead, and tolerate the lease rejecting on its own. + void lease.then( + (late) => { + late.release(true); + }, + () => undefined, + ); + throw error; + } + + let overran = false; + try { + return await withDeadline(client.query(text, [...values]), timeoutMs, what); + } catch (error) { + overran = error instanceof TeardownDeadlineError; + throw error; + } finally { + client.release(overran); + } +} + +/** + * Resolve once no backend is attached to `database`, or return what is still there at the deadline. + * + * The admin pool is deliberately attached to a different database, so it never counts itself; the + * `pid <> pg_backend_pid()` guard covers a caller who points the admin connection at the target + * anyway. Filtering on `datname` is what keeps two concurrent isolated databases from ever seeing + * each other. + */ +async function waitForQuiescence( + admin: Pool, + database: string, + deadline: number, + stepTimeoutMs: number, + pollIntervalMs: number, + onCheck: ((backends: readonly LingeringBackend[]) => void) | undefined, +): Promise { + for (;;) { + const { rows } = await boundedQuery<{ + pid: number; + state: string | null; + application_name: string | null; + }>( + admin, + stepTimeoutMs, + 'quiescence check', + `SELECT pid, state, application_name + FROM pg_stat_activity + WHERE datname = $1 AND pid <> pg_backend_pid()`, + [database], + ); + const lingering: LingeringBackend[] = rows.map((row) => ({ + pid: row.pid, + state: row.state, + applicationName: row.application_name, + })); + onCheck?.(lingering); + if (lingering.length === 0 || Date.now() >= deadline) return lingering; + await delay(pollIntervalMs); + } +} + +/** + * End a pool, but never wait forever for it. + * + * `pool.end()` closes only *idle* clients: one checked out and never released leaves it pending + * indefinitely — measured against pg 8.22.0, where a leased client kept `end()` unresolved past a + * three-second bound. Teardown has to fail with a diagnostic rather than hang the suite, so the wait + * is bounded and a leaked lease falls through to the quiescence check, which can name the culprit. + */ +async function endPoolWithin(pool: Pool, timeoutMs: number): Promise { + let timer: NodeJS.Timeout | undefined; + try { + await Promise.race([ + pool.end(), + new Promise((resolve) => { + timer = setTimeout(resolve, timeoutMs); + }), + ]); + } catch { + // A rejecting end() still leaves the quiescence check as the authority on whether the database + // can be dropped, and that check reports the situation far better than this error would. + } finally { + if (timer !== undefined) clearTimeout(timer); + } +} + +/** + * Every connection the pool has open, tracked through public events only. + * + * The emergency drop below can terminate a client that is *checked out* — a lease the callback never + * returned, which is the very thing that made `pool.end()` time out. A leased client is not idle, so + * `pg` has removed `idleListener` from it and the pool never sees its errors: attaching to the pool + * alone leaves that FATAL with no listener at all, and Node raises it as an uncaught exception. So + * the clients have to be reachable individually, and `connect`/`remove` are the documented events + * that bracket their lifetime. + */ +function trackClients(pool: Pool): ReadonlySet { + const live = new Set(); + pool.on('connect', (client: PoolClient) => { live.add(client); }); + pool.on('remove', (client: PoolClient) => { live.delete(client); }); + return live; +} + +/** + * Take the database away from connections that would not let go, and own the consequence. + * + * This is the only place `WITH (FORCE)` survives, and it is reached only once teardown has already + * failed — the caller is about to throw either way. It is still a deliberate termination, so the + * connections it is about to kill get a listener *first*, on the pool and on every live client. + * + * That listener is not the absorber this change deleted from the API test. That one sat on every + * run and hid a race in the normal path. This one is installed only where this code itself issues + * the termination, one statement later, on connections already being abandoned — and it re-throws + * anything it did not cause, so a genuine connection failure stays exactly as loud as it was. + */ +async function forceDropAbandoned( + admin: Pool, + pool: Pool, + clients: ReadonlySet, + database: string, + timeoutMs: number, +): Promise { + // Two shapes reach these connections, and both are this call's own doing. The server's `FATAL` + // carries SQLSTATE 57P01. When the backend dies before that message can be read, `pg` reports a + // bare "Connection terminated unexpectedly" with no code at all — measured here, that is what a + // *leased* client sees, because its socket goes down under an in-flight lease. + // + // Matching that string is defensible only because of where it sits: on connections belonging to a + // pool already being abandoned, after this function has itself issued the termination, on a path + // whose caller always throws. It is deliberately not part of {@link isForcedTermination}, which + // stays SQLSTATE-only — as a general predicate the string would absorb an unrelated server restart + // or dropped network too, which is the observability loss the deleted 57P01 absorber caused. + const absorbOwnTermination = (error: Error): void => { + if (isForcedTermination(error) || error.message.includes('Connection terminated')) return; + throw error; + }; + pool.on('error', absorbOwnTermination); + for (const client of clients) client.on('error', absorbOwnTermination); + + await boundedQuery(admin, timeoutMs, 'forced drop', `DROP DATABASE IF EXISTS "${database}" WITH (FORCE)`); +} + +/** + * Drop the database, tolerating one specific lost race and nothing else. + * + * Quiescence is established with a query, and a backend can attach between that answer and the drop + * — autovacuum being the realistic case. PostgreSQL reports exactly that as 55006, so the drop is + * retried inside the deadline the caller already granted. Every other SQLSTATE propagates untouched: + * this absorbs a *scheduling* outcome, never a database error. + */ +async function dropWhenFree( + admin: Pool, + pool: Pool, + clients: ReadonlySet, + database: string, + deadline: number, + teardownTimeoutMs: number, + pollIntervalMs: number, + onCheck: ((backends: readonly LingeringBackend[]) => void) | undefined, +): Promise { + for (;;) { + try { + await boundedQuery( + admin, + teardownTimeoutMs, + 'drop', + `DROP DATABASE IF EXISTS "${database}"`, + ); + return; + } catch (error) { + // Anything but "still in use" is a real database error and belongs to the caller untouched. + if (sqlState(error) !== OBJECT_IN_USE) throw error; + + const lingering = await waitForQuiescence( + admin, + database, + deadline, + teardownTimeoutMs, + pollIntervalMs, + onCheck, + ); + if (Date.now() >= deadline) { + // 55006 arriving at or past the deadline is still a teardown timeout, not a raw SQL fault: + // rethrowing the PostgreSQL error would skip the snapshot that names what was holding the + // database and leave only the outer best-effort drop. + await reportTimeoutAfterForcedDrop(admin, pool, clients, database, teardownTimeoutMs, lingering); + } + } + } +} + +/** + * Make the database safe to drop, then drop it. + * + * Split out so the lifecycle above reads as create/run/tear-down rather than as one long block: the + * ordering here is the contract, and it is easier to check when it is not interleaved with the + * bookkeeping that decides which error to throw. + * + * Returns nothing and throws on failure, so the caller can record the failure without having to + * distinguish "cleaned up" from "reported". + */ +async function tearDown( + admin: Pool, + pool: Pool, + clients: ReadonlySet, + database: string, + teardownTimeoutMs: number, + pollIntervalMs: number, + onCheck: ((backends: readonly LingeringBackend[]) => void) | undefined, +): Promise { + const deadline = Date.now() + teardownTimeoutMs; + await endPoolWithin(pool, Math.max(0, deadline - Date.now())); + + const lingering = await waitForQuiescence( + admin, + database, + deadline, + teardownTimeoutMs, + pollIntervalMs, + onCheck, + ); + if (lingering.length > 0) { + // Something outlived its owner. Drop the database anyway so the server is not littered with + // abandoned test databases, then say precisely what was holding it. + await reportTimeoutAfterForcedDrop(admin, pool, clients, database, teardownTimeoutMs, lingering); + } + await dropWhenFree(admin, pool, clients, database, deadline, teardownTimeoutMs, pollIntervalMs, onCheck); +} + +/** + * Run `body` against a database created for it alone, and take that database away afterwards. + * + * **Why this is not simply `DROP DATABASE ... WITH (FORCE)`.** `pool.end()` resolves before its + * clients have closed. In pg 8.22.0, `_pulseQueue` reaches the end callback in the same synchronous + * turn in which `_remove` filters the last client out of `_clients`, while `client.end()` has only + * queued the Terminate byte — measured here as zero of four `remove` events having fired at the + * moment `end()` resolved. A drop issued straight afterwards can therefore still find a backend + * attached, and `FORCE` then does exactly what it promises: it terminates that backend, and the + * resulting `FATAL` arrives on a socket whose pool still has `idleListener` attached, because + * `_remove` never detaches it. The error re-emits as `pool.emit('error')` — an unhandled + * EventEmitter error, which `node:test` attributes to whichever test happens to be running rather + * than to the teardown that caused it. Absorbing SQLSTATE 57P01 hides that; it does not fix it. + * + * A plain `DROP DATABASE` cannot do the same damage. Measured against PostgreSQL 16.14: with a + * backend still attached it fails with 55006 and leaves that connection untouched, where `FORCE` + * succeeds by killing it. So teardown waits for the database to be genuinely unused and then drops + * it ordinarily — trading a quiet, harmful success for a loud, harmless failure. + * + * Teardown always runs, and drops the disposable database on every path it can reach — including the + * one where it gives up and reports a timeout. The final fallback drop is best effort: it runs inside + * a `catch`, because a cleanup failure must not bury the error already being reported, so a server + * that refuses that drop can still leave a database behind. Teardown never replaces the callback's + * own error: when both fail, the callback's error is thrown with the teardown failure as its `cause`. + */ +export async function withTestDatabase( + body: (db: TestDatabase) => Promise, + options: TestDatabaseOptions = {}, +): Promise { + const connectionString = options.connectionString ?? process.env['DATABASE_URL']; + if (connectionString === undefined || connectionString === '') { + throw new Error('withTestDatabase: no connectionString was given and DATABASE_URL is not set'); + } + + const teardownTimeoutMs = options.teardownTimeoutMs ?? 10_000; + const pollIntervalMs = options.pollIntervalMs ?? 25; + // Generated here and never supplied by a caller, which is what makes it safe to interpolate into + // the DDL below: PostgreSQL has no bound-parameter form for an identifier, so `CREATE DATABASE` + // and `DROP DATABASE` cannot be parameterised. Both radix strings emit only `[0-9a-z]`, so the + // result matches `[a-z0-9_]+` and there is nothing to escape. It is also ~25 characters against + // PostgreSQL's 63-byte identifier limit, so two concurrent databases cannot be truncated to the + // same name — which would let one run's teardown drop another run's database. + const suffix = `${Date.now().toString(36)}_${Math.floor(Math.random() * 0xffffffff).toString(16)}`; + const database = `test_db_${suffix}`; + + // Every teardown step runs on this pool, so the budget is applied here rather than only around + // `pool.end()`. Checking `Date.now()` after an awaited query does not bound that query: a stalled + // but established connection would sit past the deadline with nothing to interrupt it. These + // options make the server itself give up, so the documented budget is the real one. + // A backstop, deliberately looser than the budget it guards. The teardown paths run right up to + // `teardownTimeoutMs` on purpose and then still have cleanup to do — force-dropping the database + // and building the diagnostic — so a backstop set to the same value would preempt the very error + // teardown was trying to report. This exists only for a server that has stopped answering, where + // nothing else would ever return. + const teardownBackstopMs = teardownTimeoutMs * 2 + 1_000; + // No pool-level `connectionTimeoutMillis`. It would apply to *every* acquisition on this pool, + // including the one `boundedQuery` makes for `CREATE DATABASE` — which runs before the callback + // and has nothing to do with how long teardown may wait. Tests here pass `teardownTimeoutMs: 300` + // to exercise the timeout path, so binding acquisition to it would cap setup at 300ms and fail + // creation on a loaded server. It is also redundant: every `admin.connect()` in this file goes + // through `boundedQuery`, which bounds acquisition with the budget belonging to that operation. + const admin = createPool({ connectionString, max: 2 }); + // Hoisted so the last-resort drop can route through `forceDropAbandoned`: that drop is a forced + // one too, and it terminates the same connections, so it owes them the same listener. + let pool: Pool | undefined; + let clients: ReadonlySet = new Set(); + let dropped = false; + let bodyFailed = false; + let teardownFailed = false; + let bodyError: unknown; + let teardownError: unknown; + let result!: T; + + try { + await boundedQuery(admin, CREATE_TIMEOUT_MS, 'create', `CREATE DATABASE "${database}"`); + const databaseUrl = urlForDatabase(connectionString, database); + pool = createPool({ connectionString: databaseUrl, max: options.max ?? 4 }); + clients = trackClients(pool); + try { + result = await body({ pool, database, connectionString: databaseUrl }); + } catch (error) { + // A promise may reject with anything, `undefined` included, so the flag is what records that + // the callback failed. Using the captured value as its own sentinel would turn + // `Promise.reject(undefined)` into a success and return an uninitialised result. + bodyFailed = true; + bodyError = error; + } finally { + try { + await withDeadline( + tearDown(admin, pool, clients, database, teardownTimeoutMs, pollIntervalMs, options.onQuiescenceCheck), + teardownBackstopMs, + 'teardown', + ); + dropped = true; + } catch (error) { + teardownFailed = true; + teardownError = error; + // A timeout reports whether its own forced drop succeeded, because that drop is a query and + // can fail too. Trusting the error type alone would skip the net below exactly when the + // database is still there. + dropped = error instanceof DatabaseTeardownTimeoutError && error.droppedDatabase; + } + } + } catch (error) { + // `CREATE DATABASE` failed, or the URL rewrite or pool construction after it did. The last of + // those can happen with the database already created, so the drop below has to stay reachable — + // it is `IF EXISTS`, which makes it harmless when there is nothing there. + if (!teardownFailed) { + teardownFailed = true; + teardownError = error; + } + } finally { + try { + if (!dropped) { + // The same forced drop, so the same duty of care: if a pool exists it may still own + // connections this is about to terminate, and they need a listener before it happens. + if (pool !== undefined) { + await forceDropAbandoned(admin, pool, clients, database, teardownBackstopMs); + } else { + await boundedQuery( + admin, + teardownBackstopMs, + 'last-resort drop', + `DROP DATABASE IF EXISTS "${database}" WITH (FORCE)`, + ); + } + } + } catch { + // A last-resort drop that fails leaves the error already in flight, which describes the real + // problem better than this one would. + } finally { + await endPoolWithin(admin, teardownTimeoutMs); + } + } + + if (bodyFailed) { + // The test's own failure is the one worth reading. A teardown failure rides along as its cause + // rather than replacing it: losing the assertion that actually failed would be the worse trade. + if (teardownFailed && bodyError instanceof Error && bodyError.cause === undefined) { + bodyError.cause = teardownError; + } + throw bodyError; + } + if (teardownFailed) throw teardownError; + return result; +} diff --git a/packages/persistence/test/test-database.integration.test.ts b/packages/persistence/test/test-database.integration.test.ts new file mode 100644 index 00000000..48ef1c39 --- /dev/null +++ b/packages/persistence/test/test-database.integration.test.ts @@ -0,0 +1,433 @@ +/** + * The teardown contract for a disposable PostgreSQL database. + * + * This file exists because of a reproduced CI failure, not a hypothesis. `withDatabase` in + * `variant-migrations.integration.test.ts` ended its pool and then immediately ran + * `DROP DATABASE ... WITH (FORCE)`. Measured against pg 8.22.0: `pool.end()` resolves in the same + * synchronous turn that `_remove` filters the last client out of `_clients`, while `client.end()` + * has only queued the Terminate byte — zero of four `remove` events had fired at the moment `end()` + * resolved. A drop issued straight afterwards could still find a backend attached, `FORCE` + * terminated it, and the FATAL arrived on a socket whose pool still had `idleListener` attached. + * `pg` re-emitted it as `pool.emit('error')`, which with no listener is an uncaught exception — + * attributed by `node:test` to whichever test was running, never to the teardown that caused it. + * + * Measured against PostgreSQL 16.14, the two drops differ in exactly the way that matters: with a + * backend still attached, plain `DROP DATABASE` fails with 55006 and leaves that connection + * untouched, where `WITH (FORCE)` succeeds by killing it. The fix is therefore to wait for the + * database to be unused and drop it ordinarily — a loud, harmless failure instead of a quiet, + * harmful success. + * + * Nothing here asserts on elapsed wall-clock time. A test that waits 250ms and checks the clock is + * measuring the machine; these observe the quiescence checks themselves, which is the contract. + */ + +import test from 'node:test'; +import assert from 'node:assert/strict'; +import { Client } from 'pg'; +import type { Pool } from 'pg'; +import { + DatabaseTeardownTimeoutError, + withTestDatabase, + type LingeringBackend, +} from '../src/test-support/database'; + +const DATABASE_URL = process.env['DATABASE_URL']; +const skip = DATABASE_URL ? false : 'DATABASE_URL not set'; + +/** Opens an admin connection to the configured server, never to a disposable database. */ +async function admin(): Promise { + const client = new Client({ connectionString: DATABASE_URL }); + await client.connect(); + return client; +} + +/** Whether the server still has a database of this name. */ +async function databaseExists(name: string): Promise { + const client = await admin(); + try { + const { rowCount } = await client.query('SELECT 1 FROM pg_database WHERE datname = $1', [name]); + return rowCount === 1; + } finally { + await client.end(); + } +} + +test('test database: a successful callback leaves no database behind', { skip }, async () => { + let name = ''; + let poolRef: Pool | undefined; + await withTestDatabase(async ({ pool, database }) => { + name = database; + poolRef = pool; + await pool.query('SELECT 1'); + assert.equal(await databaseExists(database), true, 'the database exists while the callback runs'); + }); + + assert.notEqual(name, ''); + assert.equal(await databaseExists(name), false, 'and is gone once the callback returns'); + + // Teardown must end the pool *before* it decides the database is unused, not merely reach the + // same state eventually. Without this, a teardown that never ended the pool still passes: `pg` + // closes idle clients after `idleTimeoutMillis` (10s by default), so the quiescence wait drains + // on its own and the only visible symptom is every test taking fifty times longer. `pool.end()` + // rejecting on a second call is pg's own documented contract, which makes this a fact about the + // pool rather than a measurement of the clock. + await assert.rejects( + poolRef!.end(), + /more than once/, + 'teardown had already ended the pool it was handed', + ); +}); + +test('test database: a throwing callback still loses its database, and its own error', { skip }, async () => { + let name = ''; + const thrown = new Error('the assertion this test actually cares about'); + + await assert.rejects( + withTestDatabase(async ({ pool, database }) => { + name = database; + await pool.query('SELECT 1'); + throw thrown; + }), + (error: unknown) => { + // The callback's failure is the one worth reading. Teardown must not replace it. + assert.equal(error, thrown, 'the callback error is rethrown unchanged, not a cleanup error'); + return true; + }, + ); + + assert.equal(await databaseExists(name), false, 'cleanup runs on the failure path too'); +}); + +test('test database: teardown waits for a lingering backend instead of terminating it', { skip }, async () => { + // A backend that is deterministically still attached when teardown begins: not a race to win, a + // connection this test holds open on purpose. Teardown must observe it, wait, and only drop once + // it has gone — rather than killing it, which is what FORCE did. + const checks: Array = []; + let lingering: Client | undefined; + let lingeringErrored: unknown; + let name = ''; + + await withTestDatabase( + async ({ pool, connectionString, database }) => { + name = database; + await pool.query('SELECT 1'); + + lingering = new Client({ connectionString, application_name: 'lingering-on-purpose' }); + await lingering.connect(); + // If teardown terminated this connection, `pg` would deliver the FATAL here. Recording it + // rather than letting it go unhandled is what makes the assertion below meaningful — and + // keeps this test from becoming the uncaught-exception source it is testing for. + lingering.on('error', (error) => { + lingeringErrored = error; + }); + }, + { + onQuiescenceCheck: (backends) => { + checks.push(backends); + // Release the connection the first time teardown reports seeing it. This is a latch, not a + // sleep: teardown cannot proceed until the backend is gone, and it only goes because a + // check observed it. + if (backends.length > 0 && lingering !== undefined) { + const closing = lingering; + lingering = undefined; + void closing.end(); + } + }, + }, + ); + + const sawIt = checks.some((backends) => + backends.some((backend) => backend.applicationName === 'lingering-on-purpose'), + ); + assert.equal(sawIt, true, 'teardown observed the lingering backend rather than dropping through it'); + assert.deepEqual(checks.at(-1), [], 'and only stopped waiting once nothing was attached'); + assert.equal( + lingeringErrored, + undefined, + 'the lingering connection was never terminated — no FORCE, so no 57P01 to absorb', + ); + assert.equal(await databaseExists(name), false, 'and the database was dropped'); +}); + +test('test database: a backend that never leaves is bounded, named, and not leaked', { skip }, async () => { + // The failure path: something holds a connection it does not own and never lets go. Teardown must + // give up on a bound rather than hang the suite, say what was holding the database, and still not + // leave the database behind. + let held: Client | undefined; + let name = ''; + + try { + await assert.rejects( + withTestDatabase( + async ({ pool, connectionString, database }) => { + name = database; + await pool.query('SELECT 1'); + held = new Client({ connectionString, application_name: 'never-leaves' }); + await held.connect(); + held.on('error', () => { + // Emergency cleanup drops this database WITH (FORCE) precisely because this connection + // refused to go, so this client is expected to be terminated. Swallowing it here is + // this test tidying up after itself, not the helper hiding a failure. + }); + }, + { teardownTimeoutMs: 400, pollIntervalMs: 25 }, + ), + (error: unknown) => { + assert.ok(error instanceof DatabaseTeardownTimeoutError, 'teardown fails loudly on the bound'); + assert.equal(error.database, name); + assert.ok(error.lingering.length > 0, 'and reports what was still attached'); + assert.ok( + error.lingering.some((backend) => backend.applicationName === 'never-leaves'), + 'naming the culprit by application_name, so the owner is findable', + ); + return true; + }, + ); + } finally { + if (held) await held.end().catch(() => undefined); + } + + assert.equal( + await databaseExists(name), + false, + 'a database is never leaked, even when teardown could not do it the safe way', + ); +}); + +test('test database: when both the callback and teardown fail, the callback error wins', { skip }, async () => { + // The case the naive try/finally gets wrong. A teardown failure thrown from `finally` would + // replace the assertion that actually failed, leaving the author reading a cleanup error instead + // of their own test. Both halves fail here on purpose: a throwing callback that also leaves a + // connection behind, so teardown times out too. + const thrown = new Error('the assertion that must survive teardown'); + let held: Client | undefined; + let name = ''; + + try { + await assert.rejects( + withTestDatabase( + async ({ pool, connectionString, database }) => { + name = database; + await pool.query('SELECT 1'); + held = new Client({ connectionString, application_name: 'held-through-failure' }); + await held.connect(); + held.on('error', () => { + // Expected: emergency cleanup terminates this one. + }); + throw thrown; + }, + { teardownTimeoutMs: 300, pollIntervalMs: 25 }, + ), + (error: unknown) => { + assert.equal(error, thrown, 'the callback error is what surfaces'); + assert.ok( + (error as Error).cause instanceof DatabaseTeardownTimeoutError, + 'and the teardown failure rides along as its cause rather than replacing it', + ); + return true; + }, + ); + } finally { + if (held) await held.end().catch(() => undefined); + } + + assert.equal(await databaseExists(name), false, 'and the database still went away'); +}); + +test('test database: a concurrent run is not blocked by another database’s backends', { skip }, async () => { + // The quiescence predicate filters on `datname`, so one run's busy backends must be invisible to + // the other's teardown. Asserting that no check ever saw *anything* would be flaky for the very + // reason this helper exists — a run's own pool can still be closing when its first check runs — + // and would prove nothing about isolation anyway, since the query already filters by database and + // a `LingeringBackend` does not carry the one it came from. + // + // What does prove it: the short run finishes while the long one is still holding a backend open. + // If teardown waited on anything outside its own database, that could not happen. + const names: string[] = []; + const checksLong: Array = []; + const checksShort: Array = []; + let longFinished = false; + + // The long run is held open by an explicit release rather than a sleep. A fixed `pg_sleep` would + // make this assertion a bet that the short run finishes first, which a loaded server can lose — + // failing a correct implementation. Held this way, the ordering is a fact of the test. + let releaseLong = (): void => undefined; + const heldOpen = new Promise((resolve) => { + releaseLong = resolve; + }); + + const long = withTestDatabase( + async ({ pool, database }) => { + names.push(database); + // A leased client, not `pool.query`. `pool.query` returns its client to the pool as soon as it + // answers, and an idle client can be closed before the short run finishes — which would leave + // this run holding no backend at all, and the isolation this test claims to prove unproven. + const leased = await pool.connect(); + try { + await leased.query('SELECT 1'); + await heldOpen; + } finally { + leased.release(); + } + }, + { onQuiescenceCheck: (backends) => checksLong.push(backends) }, + // Settled here, where the promise is created, rather than after `await short`. A rejection + // arriving while `short` is still pending would otherwise be unhandled at that moment, and + // node:test would report an uncaught rejection instead of the failure the precedence logic + // below exists to preserve — hiding exactly what it was written to surface. + ).then( + () => { + longFinished = true; + return undefined; + }, + (error: unknown) => error ?? new Error('the long run rejected with a falsy value'), + ); + + const short = withTestDatabase( + async ({ pool, database }) => { + names.push(database); + await pool.query('SELECT 1'); + }, + { onQuiescenceCheck: (backends) => checksShort.push(backends) }, + ); + + // The gate has to open on every path. If the short run rejects or the ordering assertion fails, + // an unreleased latch leaves the long callback suspended forever: its teardown never runs, its + // database and pool stay alive, and the runner may not exit. A test that leaks the thing it is + // policing is the failure this whole file exists to prevent. + // + // Not a `finally`, though — throwing from one replaces whatever was already propagating, so a + // long run that also failed would bury the short-run failure that started all this. The same rule + // the helper follows for callback-versus-teardown errors: the first failure is the one worth + // reading, and the second rides along. + let primaryFailure: unknown; + let primaryFailed = false; + try { + await short; + assert.equal(longFinished, false, 'the short run completed while the long one still held its database'); + } catch (error) { + primaryFailed = true; + primaryFailure = error; + } + + releaseLong(); + const longFailure = await long; + + if (primaryFailed) { + if (longFailure !== undefined && primaryFailure instanceof Error && primaryFailure.cause === undefined) { + primaryFailure.cause = longFailure; + } + throw primaryFailure; + } + if (longFailure !== undefined) throw longFailure; + + assert.equal(names.length, 2); + assert.notEqual(names[0], names[1], 'each run gets its own database'); + for (const name of names) assert.equal(await databaseExists(name), false, `${name} was dropped`); + assert.deepEqual(checksShort.at(-1), [], 'the short run reached quiescence before dropping'); + assert.deepEqual(checksLong.at(-1), [], 'and so did the long one'); +}); + +test('test database: giving up on teardown still leaves no database behind', { skip }, async () => { + // The bounded path force-drops before it reports, and the outer net must not wrongly assume it + // did. A leaked database is invisible to every other assertion here, so it is checked directly — + // by name rather than by counting `test_db_%` on the server. This suite shares a server with + // whatever else is running against `DATABASE_URL`, and a count taken before and after would be + // answering for that other process as much as for this fixture. + let name = ''; + let held: Client | undefined; + + try { + await assert.rejects( + withTestDatabase( + async ({ pool, connectionString, database }) => { + name = database; + await pool.query('SELECT 1'); + held = new Client({ connectionString, application_name: 'leak-check' }); + await held.connect(); + held.on('error', () => { + // Expected: this is the connection teardown gives up on and then terminates. + }); + }, + { teardownTimeoutMs: 300, pollIntervalMs: 25 }, + ), + (error: unknown) => error instanceof DatabaseTeardownTimeoutError, + ); + } finally { + if (held) await held.end().catch(() => undefined); + } + + assert.notEqual(name, '', 'the fixture reported the database it created'); + assert.equal(await databaseExists(name), false, 'the disposable database did not survive teardown'); +}); + +test('test database: a leaked pool client does not become an uncaught error', { skip }, async () => { + // The emergency path is the one place FORCE survives, and the connection it terminates can belong + // to the callback's own pool — a client checked out and never released, which is exactly what + // makes `pool.end()` time out and send teardown down that path. That pool has no `error` listener + // during the run, so without one installed before the forced drop, `pg` re-emits the FATAL as an + // uncaught exception: the failure this whole helper exists to remove, reintroduced by its own + // cleanup. Unlike the other leak tests, nothing here attaches a listener of its own — the helper + // has to own the termination it causes. + let name = ''; + + await assert.rejects( + withTestDatabase( + async ({ pool, database }) => { + name = database; + const leased = await pool.connect(); + await leased.query('SELECT 1'); + // Deliberately never released. + }, + { teardownTimeoutMs: 400, pollIntervalMs: 25 }, + ), + (error: unknown) => { + assert.ok(error instanceof DatabaseTeardownTimeoutError, 'the bound is what reports, not a crash'); + return true; + }, + ); + + // If the FATAL had escaped, node:test would have failed this run with an uncaught exception rather + // than reaching here. Checked by name, not by counting `test_db_%`: this suite shares a server, so + // a count would be answering for whatever else is running against it too. + assert.notEqual(name, '', 'the fixture reported the database it created'); + assert.equal(await databaseExists(name), false, 'and the database still went away'); +}); + +test('test database: a callback that rejects with undefined is still a failure', { skip }, async () => { + // `undefined` is a legal rejection value, so it must not double as the helper's own no-error + // sentinel — that would turn this call into a success returning an uninitialised result. + let name = ''; + let resolved = false; + + await assert.rejects( + withTestDatabase(async ({ pool, database }) => { + name = database; + await pool.query('SELECT 1'); + throw undefined; + }).then(() => { + resolved = true; + }), + (error: unknown) => { + assert.equal(error, undefined, 'the rejection value is preserved exactly as thrown'); + return true; + }, + ); + + assert.equal(resolved, false, 'a rejection with undefined never becomes a successful return'); + assert.equal(await databaseExists(name), false, 'and its database is still cleaned up'); +}); + +test('test database: a real query failure is not swallowed by teardown', { skip }, async () => { + // The helper absorbs exactly one thing — 55006 while retrying its own drop. A genuine SQL error + // from the callback has to arrive unchanged, or these tests stop being able to fail. + await assert.rejects( + withTestDatabase(async ({ pool }: { pool: Pool }) => { + await pool.query('SELECT * FROM a_table_that_does_not_exist'); + }), + (error: unknown) => { + assert.equal((error as { code?: string }).code, '42P01', 'undefined_table reaches the caller'); + return true; + }, + ); +}); diff --git a/packages/persistence/test/variant-migrations.integration.test.ts b/packages/persistence/test/variant-migrations.integration.test.ts index daae0865..2881a75e 100644 --- a/packages/persistence/test/variant-migrations.integration.test.ts +++ b/packages/persistence/test/variant-migrations.integration.test.ts @@ -5,8 +5,8 @@ import { copyFileSync, mkdtempSync, rmSync } from 'node:fs'; import { tmpdir } from 'node:os'; import { join } from 'node:path'; import type { Pool } from 'pg'; -import { createPool } from '../src/pg/pool'; import { migrate, migrationFiles, migrationsDir } from '../src/pg/migrate'; +import { withTestDatabase } from '../src/test-support/database'; const DATABASE_URL = process.env['DATABASE_URL']; const skip = DATABASE_URL ? false : 'DATABASE_URL not set'; @@ -40,13 +40,6 @@ function isConstraintViolation(error: unknown, code: string, constraint: string) return pgError.code === code && pgError.constraint === constraint; } -/** Replaces the database path in the configured PostgreSQL connection URL. */ -function databaseUrlFor(database: string): string { - const url = new URL(DATABASE_URL!); - url.pathname = `/${database}`; - return url.toString(); -} - /** Copies migrations through the requested version into a disposable directory. */ function migrationsThrough(version: number): { readonly dir: string; cleanup(): void } { const dir = mkdtempSync(join(tmpdir(), `variant-migrations-${version}-`)); @@ -57,29 +50,16 @@ function migrationsThrough(version: number): { readonly dir: string; cleanup(): return { dir, cleanup: () => rmSync(dir, { recursive: true, force: true }) }; } -/** Runs a callback in an isolated database and always releases its pools and database. */ +/** + * Runs a callback in an isolated database and always releases its pools and database. + * + * The teardown protocol itself lives in {@link withTestDatabase}. This file used to end its pool and + * then immediately `DROP DATABASE ... WITH (FORCE)`, which terminated backends the pool had not yet + * finished closing and delivered the resulting FATAL to a live socket — surfacing as an uncaught + * error that `node:test` attributed to whichever test happened to run next. + */ async function withDatabase(run: (pool: Pool) => Promise): Promise { - const admin = createPool({ connectionString: DATABASE_URL, max: 2 }); - const database = `variant_migration_${randomUUID().replaceAll('-', '')}`; - let databaseCreated = false; - try { - await admin.query(`CREATE DATABASE "${database}"`); - databaseCreated = true; - const pool = createPool({ connectionString: databaseUrlFor(database), max: 4 }); - try { - await run(pool); - } finally { - await pool.end(); - } - } finally { - try { - if (databaseCreated) { - await admin.query(`DROP DATABASE IF EXISTS "${database}" WITH (FORCE)`); - } - } finally { - await admin.end(); - } - } + await withTestDatabase(async ({ pool }) => run(pool), { connectionString: DATABASE_URL, max: 4 }); } /** Reads one named constraint from PostgreSQL's catalog. */