From 9fde59afd9dd1c790090112b3ef03858c5b30ef3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dawid=20Wr=C3=B3blewski?= Date: Sat, 12 Sep 2026 20:08:43 +0200 Subject: [PATCH 1/2] Deadlines on every wait for the database (#172) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The pool was built with pg's defaults, which meant the one that matters was absent: connectionTimeoutMillis 0, a caller waiting for a free connection waiting for ever. Nothing set statement_timeout or lock_timeout either, on the client or on the server, so contention queued where nobody could see it. Now the pool states what it holds and how long anything may wait, and the server cuts off a statement that runs past ten seconds or waits past three for a lock. Each number is an environment variable: dev is one core shared by dev and every preview, and prod's managed database (#24) is another machine with another cap. They travel in the connection's startup packet, not in DATABASE_URL, because the same address belongs to the migration runner, psql and the scripts — a migration cut off half-applied by a bound meant for a page is worse than a slow one. The scripts say so out loud (runAsBatchJob) and run without them. Proven against a real PostgreSQL rather than asserted, including that lock_timeout does cover the advisory lock every write in this app takes. A failure now carries the name of the bound it hit, and onRequestError puts that name in the log — a stall used to look exactly like a slow request. Co-Authored-By: Claude Opus 5 --- .env.example | 15 +++ SPEC.md | 8 ++ deploy/migrate.mjs | 11 ++- scripts/backfill-file-keys.ts | 4 +- scripts/import-teryt.ts | 5 +- scripts/seed.ts | 5 +- src/db/client.test.ts | 159 ++++++++++++++++++++++++++++++ src/db/client.ts | 179 +++++++++++++++++++++++++++++++++- src/instrumentation.ts | 18 ++++ tasks/plan.md | 19 ++-- 10 files changed, 410 insertions(+), 13 deletions(-) create mode 100644 src/db/client.test.ts diff --git a/.env.example b/.env.example index 33f385e..8f8fa84 100644 --- a/.env.example +++ b/.env.example @@ -7,6 +7,21 @@ DATABASE_URL= # Separate test database (platform_test_ — SPEC.md §6) DATABASE_URL_TEST= +# The database's deadlines (#172). All optional: leaving them blank keeps the +# numbers in src/db/client.ts, which are sized for dev's one-core instance +# shared by dev and every open preview. Production's managed database (#24) +# is a different machine with a different connection cap and sets its own. +# A whole number of milliseconds; 0 turns that bound off. +# Connections this container may hold at once. +DB_POOL_MAX= +# How long a request waits for a free connection before it is answered with +# an error. Never 0 in a deployed environment: 0 means it waits for ever. +DB_CONNECT_TIMEOUT_MS= +# How long one statement may run before the server cuts it off. +DB_STATEMENT_TIMEOUT_MS= +# How long one statement may wait for a lock another transaction holds. +DB_LOCK_TIMEOUT_MS= + # SSH target of the dev instance for the tunnel, e.g. ubuntu@ DEV_SSH_HOST= # Hostname the dev deployment answers on (SPEC §8). Leave empty and diff --git a/SPEC.md b/SPEC.md index 680a749..f19ebf1 100644 --- a/SPEC.md +++ b/SPEC.md @@ -337,6 +337,14 @@ export function ownerKey( plain Docker image). The one line worth paying from day one is the managed database, and not for performance: prod holds real accounts and photos, so someone else's backups and patching is the product being bought. To settle with #24. +- **Every wait on the database has a deadline, and each environment sets its own** (#172): + the pool answers a caller it cannot give a connection to within five seconds instead of + queueing them for ever, and the server cuts off a statement that runs past ten seconds or + waits past three for a lock. The numbers live in `src/db/client.ts`, sized for dev's one + core shared by dev and every preview, and each is an environment variable (`DB_POOL_MAX`, + `DB_CONNECT_TIMEOUT_MS`, `DB_STATEMENT_TIMEOUT_MS`, `DB_LOCK_TIMEOUT_MS`) because prod's + managed database is another machine with another cap. They travel in the connection, not + in `DATABASE_URL`, so a migration or a script is never cut off by a bound meant for a page. - Outside prod (`APP_ENV` other than `production`): `X-Robots-Tag: noindex` (A7) — set on every response by `src/proxy.ts`; the deployment provides `APP_ENV`. - One time zone for the whole interface: `Europe/Warsaw` (next-intl `timeZone`; decision of diff --git a/deploy/migrate.mjs b/deploy/migrate.mjs index 84616b4..cfac08c 100644 --- a/deploy/migrate.mjs +++ b/deploy/migrate.mjs @@ -38,7 +38,16 @@ const folder = path.join( const pending = readdirSync(folder).filter((name) => name.endsWith(".sql")); console.log(`${pending.length} migration file(s) in the image`); -const pool = new Pool({ connectionString: url }); +// #172 deliberately does not reach this file: the web deadlines +// (statement_timeout, lock_timeout) live in the pool src/db/client.ts opens, +// not in DATABASE_URL, precisely so a migration is never cut off half-applied +// by a bound meant for a page. The one bound worth having here is the +// opposite one — a database that cannot be reached should fail the deploy +// rather than hold it open for ever. +const pool = new Pool({ + connectionString: url, + connectionTimeoutMillis: 30_000, +}); try { // Drizzle records what it has applied in its own table and skips those, so // this is safe to run on every deploy — including one that changes nothing. diff --git a/scripts/backfill-file-keys.ts b/scripts/backfill-file-keys.ts index 9e7704c..04e49fa 100644 --- a/scripts/backfill-file-keys.ts +++ b/scripts/backfill-file-keys.ts @@ -1,6 +1,6 @@ import { eq, isNull } from "drizzle-orm"; import { alias } from "drizzle-orm/pg-core"; -import { getDb } from "@/db/client"; +import { getDb, runAsBatchJob } from "@/db/client"; import { files } from "@/db/schema"; import { requireEnv } from "@/lib/env"; import { contentKey, keyPrefix } from "@/lib/storage"; @@ -46,6 +46,8 @@ function assertLocalTarget(url: string, allowRemote: boolean): void { } async function main(): Promise { + // #172: one pass over every file row, allowed to take as long as it takes. + runAsBatchJob(); loadDotEnv(); const url = requireEnv("DATABASE_URL"); assertLocalTarget(url, process.argv.includes("--allow-remote")); diff --git a/scripts/import-teryt.ts b/scripts/import-teryt.ts index 7f213cd..07e1a60 100644 --- a/scripts/import-teryt.ts +++ b/scripts/import-teryt.ts @@ -1,6 +1,6 @@ import { readFileSync } from "node:fs"; import { sql } from "drizzle-orm"; -import { getDb, type Database } from "@/db/client"; +import { getDb, runAsBatchJob, type Database } from "@/db/client"; import { places } from "@/db/schema"; import { requireEnv } from "@/lib/env"; import { @@ -106,6 +106,9 @@ export async function importPlaces( } async function main(argv: readonly string[]): Promise { + // #172: a hundred thousand places upserted in one statement is a batch job, + // not a web request. + runAsBatchJob(); loadDotEnv(); const target = new URL(requireEnv("DATABASE_URL")); const database = `${target.host}${target.pathname}`; diff --git a/scripts/seed.ts b/scripts/seed.ts index d1b11c6..79aaedb 100644 --- a/scripts/seed.ts +++ b/scripts/seed.ts @@ -1,4 +1,4 @@ -import { getDb } from "@/db/client"; +import { getDb, runAsBatchJob } from "@/db/client"; import { requireEnv } from "@/lib/env"; import { getStorage, isStorageConfigured, keyPrefix } from "@/lib/storage"; import { @@ -68,6 +68,9 @@ function printSummary(summary: SeedSummary, password: string): void { } async function main(argv: readonly string[]): Promise { + // #172: a seed writes fourteen accounts and their photos — long by the web + // deadlines' standards, and nobody is waiting on a page for it. + runAsBatchJob(); loadDotEnv(); // Sample accounts with one published password belong in dev and test // databases only. The loopback check below is the guard; this is the belt. diff --git a/src/db/client.test.ts b/src/db/client.test.ts new file mode 100644 index 0000000..8672522 --- /dev/null +++ b/src/db/client.test.ts @@ -0,0 +1,159 @@ +import { Pool } from "pg"; +import { afterEach, describe, expect, it, vi } from "vitest"; +import { databaseStall, deadlinesFor, poolConfig } from "./client"; + +// #172. Two halves: what the pool is configured with (pure, runs everywhere) +// and what those settings actually do to a waiting statement — which only a +// real server can answer, so that half runs when DATABASE_URL_TEST is set +// (always in CI, through the tunnel locally). PGlite cannot stand in: it is +// one in-process connection, and every bound here is about the second one. + +afterEach(() => { + vi.unstubAllEnvs(); +}); + +describe("the deadlines a web process runs under", () => { + it("bounds the wait for a connection, the statement and the lock", () => { + const config = poolConfig("web", "postgres://example/db"); + expect(config.max).toBe(10); + expect(config.connectionTimeoutMillis).toBe(5_000); + expect(config.statement_timeout).toBe(10_000); + expect(config.lock_timeout).toBe(3_000); + // A transaction that has gone quiet still holds its locks, so it is given + // no longer than a single statement may run. + expect(config.idle_in_transaction_session_timeout).toBe(10_000); + }); + + it("lets a batch job take as long as its work takes", () => { + const { statementMs, lockMs, connectMs } = deadlinesFor("batch"); + // 0 is PostgreSQL's own "no bound": a seed, an import or a backfill must + // never be cut off halfway by a number chosen for a page. + expect(statementMs).toBe(0); + expect(lockMs).toBe(0); + // It still gives up on a database that cannot be reached at all. + expect(connectMs).toBeGreaterThan(0); + }); + + it("takes its numbers from the environment, so production can differ", () => { + vi.stubEnv("DB_POOL_MAX", "40"); + vi.stubEnv("DB_STATEMENT_TIMEOUT_MS", "2500"); + expect(deadlinesFor("web")).toMatchObject({ + poolMax: 40, + statementMs: 2500, + // Untouched variables keep the built-in number. + connectMs: 5_000, + }); + }); + + it("refuses a deadline that is not a whole number of milliseconds", () => { + vi.stubEnv("DB_CONNECT_TIMEOUT_MS", "5s"); + // Loud, like every other environment mistake here: a deadline that + // silently fell back to the default would be found the night it mattered. + expect(() => deadlinesFor("web")).toThrow(/DB_CONNECT_TIMEOUT_MS/); + }); + + it("names the connection after the environment holding it", () => { + vi.stubEnv("S3_PREFIX", "pr-170/"); + // dev and every preview share one database (#113); pg_stat_activity has + // to say which of them is queueing. + expect(poolConfig("web", "postgres://example/db").application_name).toBe( + "platform-lite/pr-170/web", + ); + }); +}); + +describe("reading a failure", () => { + it("recognises each bound by the code PostgreSQL raises", () => { + expect( + databaseStall(Object.assign(new Error("x"), { code: "57014" })), + ).toBe("statement-timeout"); + expect( + databaseStall(Object.assign(new Error("x"), { code: "55P03" })), + ).toBe("lock-timeout"); + expect( + databaseStall(Object.assign(new Error("x"), { code: "25P03" })), + ).toBe("idle-transaction"); + }); + + it("recognises the pool's own refusal to wait any longer", () => { + expect( + databaseStall(new Error("timeout exceeded when trying to connect")), + ).toBe("no-connection"); + }); + + it("looks through the wrapper drizzle puts around driver errors", () => { + const wrapped = new Error("Failed query: select 1", { + cause: Object.assign(new Error("canceling statement"), { code: "57014" }), + }); + expect(databaseStall(wrapped)).toBe("statement-timeout"); + }); + + it("says nothing about failures that are not a deadline", () => { + expect(databaseStall(new Error("duplicate key value"))).toBeNull(); + expect(databaseStall("not an error")).toBeNull(); + }); +}); + +const url = process.env.DATABASE_URL_TEST?.trim(); + +describe.skipIf(!url)("against a real PostgreSQL", () => { + const open: Pool[] = []; + + function pool(overrides: Record): Pool { + for (const [name, value] of Object.entries(overrides)) { + vi.stubEnv(name, value); + } + const created = new Pool(poolConfig("web", url!)); + created.on("error", () => {}); + open.push(created); + return created; + } + + afterEach(async () => { + await Promise.all(open.splice(0).map((created) => created.end())); + }); + + it("cuts off a statement waiting on a lock somebody else holds", async () => { + const holder = pool({ DB_LOCK_TIMEOUT_MS: "0" }); + const held = await holder.connect(); + await held.query("begin"); + await held.query("select pg_advisory_xact_lock(20260912)"); + + const waiter = pool({ DB_LOCK_TIMEOUT_MS: "300" }); + // The app's own per-user lock is an advisory one (lockUser in + // lib/works.ts), and lock_timeout covers it — measured here rather than + // assumed, because that is the lock every write in the app takes. + const failure = await waiter + .query("select pg_advisory_xact_lock(20260912)") + .then(() => null) + .catch((error: unknown) => error); + expect(databaseStall(failure)).toBe("lock-timeout"); + + await held.query("rollback"); + held.release(); + }); + + it("cuts off a statement that simply runs too long", async () => { + const slow = pool({ DB_STATEMENT_TIMEOUT_MS: "300" }); + const failure = await slow + .query("select pg_sleep(5)") + .then(() => null) + .catch((error: unknown) => error); + expect(databaseStall(failure)).toBe("statement-timeout"); + }); + + it("answers the caller that cannot get a connection instead of queueing it", async () => { + const crowded = pool({ DB_POOL_MAX: "1", DB_CONNECT_TIMEOUT_MS: "300" }); + const taken = await crowded.connect(); + const started = Date.now(); + // Before #172 this call waited for as long as the holder kept the + // connection — for ever, if that was a statement nothing cut off. + const failure = await crowded + .query("select 1") + .then(() => null) + .catch((error: unknown) => error); + expect(databaseStall(failure)).toBe("no-connection"); + expect(Date.now() - started).toBeLessThan(5_000); + taken.release(); + }); +}); diff --git a/src/db/client.ts b/src/db/client.ts index fff280d..a203a6d 100644 --- a/src/db/client.ts +++ b/src/db/client.ts @@ -1,6 +1,6 @@ import { drizzle } from "drizzle-orm/node-postgres"; import type { PgDatabase, PgQueryResultHKT } from "drizzle-orm/pg-core"; -import { Pool } from "pg"; +import { Pool, type PoolConfig } from "pg"; import { requireEnv } from "@/lib/env"; import * as schema from "./schema"; @@ -9,15 +9,190 @@ import * as schema from "./schema"; // the same drizzle surface either way. export type Database = PgDatabase; +/** + * What the process holding the pool is doing (#172). + * + * `web` answers a visitor: every bound is short, because a page that has not + * answered in a few seconds has already failed as far as they are concerned, + * and the connection it is holding is one of ten. + * + * `batch` is a script (scripts/*.ts): a seed, a TERYT import, a backfill. + * It is allowed to take its time — a statement timeout sized for a web + * request would cut an import off halfway through, which is the one failure + * worse than a slow one. + */ +export type DatabaseUse = "web" | "batch"; + +interface Deadlines { + /** Connections this process may hold at once. */ + poolMax: number; + /** How long a caller waits for a free connection before it is told no. */ + connectMs: number; + /** How long one statement may run. 0 turns it off (PostgreSQL's own 0). */ + statementMs: number; + /** How long one statement may wait for a lock. 0 turns it off. */ + lockMs: number; +} + +// Dev's numbers, chosen for the shape of dev: one core, one containerised +// PostgreSQL with max_connections 100, and dev plus every open preview +// sharing it with a pool each (#31, #113). Production's managed database +// (#24) is another machine with another cap and sets its own through the +// environment — which is why each of these is a variable and not a constant. +// +// The web numbers, and why: the app's statements are all small (a profile, a +// page of works, one reorder), so ten seconds is not a slow query, it is a +// stuck one. Three seconds of waiting for a lock is a queue forming behind +// another writer — answering then beats joining it. +const DEADLINES: Record = { + web: { poolMax: 10, connectMs: 5_000, statementMs: 10_000, lockMs: 3_000 }, + batch: { poolMax: 4, connectMs: 30_000, statementMs: 0, lockMs: 0 }, +}; + +// Fail loud, like requireEnv: a mistyped deadline that silently fell back to +// the default would be discovered the night it was needed. +function readOverride(name: string, fallback: number): number { + const raw = process.env[name]?.trim(); + if (!raw) return fallback; + const value = Number(raw); + if (!Number.isInteger(value) || value < 0) { + throw new Error( + `${name} must be a whole number of milliseconds (0 turns the bound off), not "${raw}"`, + ); + } + return value; +} + +export function deadlinesFor(use: DatabaseUse): Deadlines { + const defaults = DEADLINES[use]; + return { + poolMax: readOverride("DB_POOL_MAX", defaults.poolMax), + connectMs: readOverride("DB_CONNECT_TIMEOUT_MS", defaults.connectMs), + statementMs: readOverride("DB_STATEMENT_TIMEOUT_MS", defaults.statementMs), + lockMs: readOverride("DB_LOCK_TIMEOUT_MS", defaults.lockMs), + }; +} + +/** + * The pool's configuration, spelled out (#172). + * + * The two server-side bounds travel in the connection's startup packet, NOT + * in DATABASE_URL — deliberately. The same address is used by the migration + * runner (deploy/migrate.mjs), by psql and by the scripts, and a migration + * that hit a web statement timeout would leave a half-applied schema behind. + * Putting them here means only what opens a pool through this module is + * bound, and each kind of process gets its own numbers. + */ +export function poolConfig( + use: DatabaseUse, + connectionString: string, +): PoolConfig { + const { poolMax, connectMs, statementMs, lockMs } = deadlinesFor(use); + return { + connectionString, + max: poolMax, + // Without this the eleventh caller waits for ever: pg's default is 0, + // and 0 means no deadline at all. This is the whole of #172 in one line. + connectionTimeoutMillis: connectMs, + // A connection nobody has used for half a minute is given back. Previews + // come and go all day and each holds its own pool against dev's single + // PostgreSQL; idle connections there are pure occupancy. + idleTimeoutMillis: 30_000, + statement_timeout: statementMs, + lock_timeout: lockMs, + // A transaction left open with nothing happening in it still holds every + // lock it has taken. Nothing here does I/O inside a transaction, so a gap + // longer than a whole statement may run means the caller is gone. + idle_in_transaction_session_timeout: statementMs, + // Who is holding the connection, as pg_stat_activity will show it: dev + // and every preview share one database (#113), so "one of them is + // queueing" is only actionable if the row says which. + application_name: connectionLabel(use), + }; +} + +// The environment's own name, taken from the prefix it already scopes its +// objects with (SPEC §4): "devski/" → devski, "pr-170/" → pr-170, blank in +// production. +function connectionLabel(use: DatabaseUse): string { + const environment = + process.env.S3_PREFIX?.trim().replace(/\/+$/, "") || + process.env.APP_ENV?.trim() || + "local"; + return `platform-lite/${environment}/${use}`; +} + let db: Database | undefined; +let poolUse: DatabaseUse = "web"; + +/** + * Declares this process a batch job (#172) — a script that may take as long + * as its work takes. Call it before the first getDb(); afterwards the pool is + * already open with the web deadlines and the call would be a lie, so it + * throws rather than pretend. + */ +export function runAsBatchJob(): void { + if (db) { + throw new Error( + "the database pool is already open — runAsBatchJob() belongs before the first getDb()", + ); + } + poolUse = "batch"; +} // Lazy on purpose: importing this module must stay side-effect free so route // modules can be evaluated at build time (and by the DB-less e2e job) without // DATABASE_URL; the first query is where a missing variable fails loudly. export function getDb(): Database { if (!db) { - const pool = new Pool({ connectionString: requireEnv("DATABASE_URL") }); + const pool = new Pool(poolConfig(poolUse, requireEnv("DATABASE_URL"))); + // Without a listener here an idle connection dropped by the server (a + // restart, an idle-transaction kill) reaches the process as an unhandled + // 'error' event, which is a crash rather than a log line. + pool.on("error", (error) => { + console.error("[db] an idle connection failed:", error.message); + }); db = drizzle({ client: pool, schema }) as Database; } return db; } + +/** + * The bound a failure ran into, or null for everything else (#172). + * + * These four are the ones nobody could see before: each one used to be an + * unbounded wait, and in the log they all looked like a request that never + * came back. Drizzle wraps driver errors and keeps the original in `cause`, + * so the chain is walked rather than the top. + */ +export type DatabaseStall = + "no-connection" | "statement-timeout" | "lock-timeout" | "idle-transaction"; + +// SQLSTATEs, from PostgreSQL's errcodes table. +const STALL_BY_CODE: Record = { + // query_canceled — what statement_timeout raises (also a hand cancel). + "57014": "statement-timeout", + // lock_not_available — what lock_timeout raises. + "55P03": "lock-timeout", + // idle_in_transaction_session_timeout — the session was terminated. + "25P03": "idle-transaction", +}; + +// pg-pool's own wording when connectionTimeoutMillis runs out; there is no +// code on that one, it is an Error the pool makes itself. +const NO_CONNECTION = "timeout exceeded when trying to connect"; + +export function databaseStall(error: unknown): DatabaseStall | null { + for ( + let current: unknown = error; + current instanceof Error; + current = current.cause + ) { + const code = (current as { code?: unknown }).code; + if (typeof code === "string" && code in STALL_BY_CODE) { + return STALL_BY_CODE[code]; + } + if (current.message.includes(NO_CONNECTION)) return "no-connection"; + } + return null; +} diff --git a/src/instrumentation.ts b/src/instrumentation.ts index 2f3abd3..0c92349 100644 --- a/src/instrumentation.ts +++ b/src/instrumentation.ts @@ -50,3 +50,21 @@ export async function register() { console.error("[r360] collector: the schedule did not start", error); } } + +// #172: the one place every server-side failure passes through (the +// `onRequestError` half of the instrumentation file convention). It exists +// for one line of log — the database deadlines answer with an error now +// instead of waiting for ever, and an operator reading the log has to be able +// to tell that from a request that was merely slow. Everything else Next +// already prints; this adds a name to the four bounds #172 introduced. +export async function onRequestError( + error: unknown, + request: { path: string; method: string }, +) { + const { databaseStall } = await import("@/db/client"); + const stall = databaseStall(error); + if (!stall) return; + console.error( + `[db] ${request.method} ${request.path} hit the ${stall} bound — the numbers are DB_* in .env.example (#172)`, + ); +} diff --git a/tasks/plan.md b/tasks/plan.md index f53ecb2..f56a263 100644 --- a/tasks/plan.md +++ b/tasks/plan.md @@ -90,13 +90,18 @@ in under 5 minutes (manual walkthrough); e2e green. and someone is there to reason about it. - [#111](https://github.com/Devski/platform-lite/issues/111) Preview cleanup loses the race with a CI run still in flight, and the orphan blocks the two-preview cap (`bug`). -- [#172](https://github.com/Devski/platform-lite/issues/172) The database has no deadlines - (`infra`, `deployment`). Found 12.09.2026 in the security review of #66: the pool is built - with pg's defaults, so `connectionTimeoutMillis` is 0 — a request waiting for a free - connection waits for ever — and neither `statement_timeout` nor `lock_timeout` is set - anywhere, on either side. Every limit in this system is a rate limit on the way IN; past - it, nothing bounds how long a request holds a connection or a lock, so contention queues - silently instead of failing with something to read. +- ~~[#172](https://github.com/Devski/platform-lite/issues/172) The database has no deadlines~~ + — **done 12.09.2026**. Found in the security review of #66: the pool was built with pg's + defaults, so `connectionTimeoutMillis` was 0 — a request waiting for a free connection + waited for ever — and neither `statement_timeout` nor `lock_timeout` was set anywhere, on + either side. Now the pool says how many connections it may hold, waits five seconds for a + free one and then answers, and the server cuts off a statement that runs past ten seconds + or waits past three for a lock. Each number is an environment variable, because prod's + managed database (#24) is another machine with another cap, and they travel in the + connection rather than in `DATABASE_URL`: a migration or a seed must never be cut off by a + bound meant for a page, so the scripts declare themselves batch jobs and run without them. + Proven against a real PostgreSQL — including that `lock_timeout` does cover the advisory + lock every write in this app takes, which was worth measuring rather than assuming. - [#119](https://github.com/Devski/platform-lite/issues/119) The dev instance keeps every image it ever pulled (`infra`). Filed 09.09.2026 when its root filesystem reached 100%: 129 images, 21.8 GB, three of them in use. Previews stopped starting at all, and dev's From 18996f97283ab61cd483b40c7bfd23749f204705 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Dawid=20Wr=C3=B3blewski?= Date: Sat, 12 Sep 2026 20:38:37 +0200 Subject: [PATCH 2/2] What the reviews found in the deadlines (#172) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The idle-transaction bound could kill the process. pg-pool takes its own error listener off a connection while somebody holds it, so a connection the server ends mid-transaction reaches a client with no listener at all — and Node turns that into an exit, not a log line. Measured against dev's PostgreSQL: without the listener added here the process exits, with it the query rejects and the request fails on its own. The test fails without the fix. The batch escape hatch was defeated by the very variables this change adds: a seed or an import would have inherited the web statement timeout from the environment's .env. A batch job now takes the built-in numbers and nothing else, and a server is refused the batch deadlines outright. The collector kept the web bound it cannot live under. It runs inside the server, so it could not opt out — and its sweep over every file row would not have failed loudly, it would have started reporting "nothing found" as the table grew. It gets a pool of its own. Also: the idle bound has its own variable, so lifting the statement bound no longer lifts it too; the reader refuses 0, hexadecimal, and numbers past setTimeout's ceiling, where a value meant as "never" fires after one millisecond; the cause walk is capped, so a chain pointing at itself ends the walk and not the core; the logged path drops its query string, where a verification token lives; a session read that fails on a bound says so, because signing everyone out silently is what a stalled database looks like from the outside; and the migration runner gets a five-second lock bound — that one guards the site, not the migration, because a migration queueing for ACCESS EXCLUSIVE queues every reader behind it while the old container serves. Two tails filed rather than smuggled in: #179 (anonymous renders have no cache and no per-address limit) and #180 (three queries that scan a whole table). Co-Authored-By: Claude Opus 5 --- .env.example | 24 +++-- SPEC.md | 11 ++- deploy/migrate.mjs | 7 ++ src/db/client.test.ts | 197 ++++++++++++++++++++++++++++++++--------- src/db/client.ts | 146 ++++++++++++++++++++++++------ src/instrumentation.ts | 32 +++++-- src/lib/api-route.ts | 14 ++- src/lib/auth.ts | 15 +++- tasks/plan.md | 6 +- 9 files changed, 363 insertions(+), 89 deletions(-) diff --git a/.env.example b/.env.example index 8f8fa84..399b03e 100644 --- a/.env.example +++ b/.env.example @@ -7,20 +7,28 @@ DATABASE_URL= # Separate test database (platform_test_ — SPEC.md §6) DATABASE_URL_TEST= -# The database's deadlines (#172). All optional: leaving them blank keeps the -# numbers in src/db/client.ts, which are sized for dev's one-core instance -# shared by dev and every open preview. Production's managed database (#24) -# is a different machine with a different connection cap and sets its own. -# A whole number of milliseconds; 0 turns that bound off. -# Connections this container may hold at once. +# The web process's database deadlines (#172). All optional: leaving one blank +# keeps the number in src/db/client.ts, sized for dev's one-core instance +# shared by dev and every open preview. Production's managed database (#24) is +# another machine with another connection cap and sets its own. Whole numbers +# only, at most 2147483647. The scripts (seed, import, backfill) ignore these +# and run without deadlines — a migration or an import cut off halfway is +# worse than a slow one. +# Connections this container may hold at once. At least 1. DB_POOL_MAX= # How long a request waits for a free connection before it is answered with -# an error. Never 0 in a deployed environment: 0 means it waits for ever. +# an error. At least 1: without a bound it waits for ever, which is the bug +# this set of variables exists to keep fixed. DB_CONNECT_TIMEOUT_MS= -# How long one statement may run before the server cuts it off. +# How long one statement may run before the server cuts it off. 0 does not +# mean "no bound" — it means the server's own setting stands, which is 0 on +# our PostgreSQL but need not be on a managed one. DB_STATEMENT_TIMEOUT_MS= # How long one statement may wait for a lock another transaction holds. DB_LOCK_TIMEOUT_MS= +# How long a transaction may sit between statements before the server ends the +# session. It still holds every lock it has taken while it sits there. +DB_IDLE_TX_TIMEOUT_MS= # SSH target of the dev instance for the tunnel, e.g. ubuntu@ DEV_SSH_HOST= diff --git a/SPEC.md b/SPEC.md index f19ebf1..5569a23 100644 --- a/SPEC.md +++ b/SPEC.md @@ -342,9 +342,14 @@ export function ownerKey( queueing them for ever, and the server cuts off a statement that runs past ten seconds or waits past three for a lock. The numbers live in `src/db/client.ts`, sized for dev's one core shared by dev and every preview, and each is an environment variable (`DB_POOL_MAX`, - `DB_CONNECT_TIMEOUT_MS`, `DB_STATEMENT_TIMEOUT_MS`, `DB_LOCK_TIMEOUT_MS`) because prod's - managed database is another machine with another cap. They travel in the connection, not - in `DATABASE_URL`, so a migration or a script is never cut off by a bound meant for a page. + `DB_CONNECT_TIMEOUT_MS`, `DB_STATEMENT_TIMEOUT_MS`, `DB_LOCK_TIMEOUT_MS`, + `DB_IDLE_TX_TIMEOUT_MS`) because prod's managed database is another machine with another + cap. They travel in the connection, not in `DATABASE_URL`, so a migration or a script is + never cut off by a bound meant for a page — the scripts ignore those variables entirely. + The migration runner keeps one bound of its own, and it guards the site rather than the + migration: five seconds of waiting for a lock, because the old container is still serving + and a migration queueing for `ACCESS EXCLUSIVE` queues every reader of that table behind + itself. - Outside prod (`APP_ENV` other than `production`): `X-Robots-Tag: noindex` (A7) — set on every response by `src/proxy.ts`; the deployment provides `APP_ENV`. - One time zone for the whole interface: `Europe/Warsaw` (next-intl `timeZone`; decision of diff --git a/deploy/migrate.mjs b/deploy/migrate.mjs index cfac08c..1bba48e 100644 --- a/deploy/migrate.mjs +++ b/deploy/migrate.mjs @@ -44,9 +44,16 @@ console.log(`${pending.length} migration file(s) in the image`); // by a bound meant for a page. The one bound worth having here is the // opposite one — a database that cannot be reached should fail the deploy // rather than hold it open for ever. +// The lock bound is the exception, and it guards the SITE rather than the +// migration: the old container is still serving while this runs, and a +// migration waiting for ACCESS EXCLUSIVE queues every reader of that table +// behind itself. Better to fail the deploy in five seconds — old container +// serving, old schema untouched — than to stall the site for as long as +// whatever holds the table. const pool = new Pool({ connectionString: url, connectionTimeoutMillis: 30_000, + lock_timeout: 5_000, }); try { // Drizzle records what it has applied in its own table and skips those, so diff --git a/src/db/client.test.ts b/src/db/client.test.ts index 8672522..ae2f1a4 100644 --- a/src/db/client.test.ts +++ b/src/db/client.test.ts @@ -1,6 +1,12 @@ import { Pool } from "pg"; -import { afterEach, describe, expect, it, vi } from "vitest"; -import { databaseStall, deadlinesFor, poolConfig } from "./client"; +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import { + databaseStall, + deadlinesFor, + poolConfig, + runAsBatchJob, + watchPool, +} from "./client"; // #172. Two halves: what the pool is configured with (pure, runs everywhere) // and what those settings actually do to a waiting statement — which only a @@ -8,6 +14,21 @@ import { databaseStall, deadlinesFor, poolConfig } from "./client"; // (always in CI, through the tunnel locally). PGlite cannot stand in: it is // one in-process connection, and every bound here is about the second one. +const VARIABLES = [ + "DB_POOL_MAX", + "DB_CONNECT_TIMEOUT_MS", + "DB_STATEMENT_TIMEOUT_MS", + "DB_LOCK_TIMEOUT_MS", + "DB_IDLE_TX_TIMEOUT_MS", +]; + +beforeEach(() => { + // Vitest loads .env, and these variables are meant to be set — so a + // developer who has set one would otherwise fail the tests that assert the + // built-in numbers, for a reason that has nothing to do with the change. + for (const name of VARIABLES) vi.stubEnv(name, ""); +}); + afterEach(() => { vi.unstubAllEnvs(); }); @@ -19,21 +40,10 @@ describe("the deadlines a web process runs under", () => { expect(config.connectionTimeoutMillis).toBe(5_000); expect(config.statement_timeout).toBe(10_000); expect(config.lock_timeout).toBe(3_000); - // A transaction that has gone quiet still holds its locks, so it is given - // no longer than a single statement may run. + // A transaction that has gone quiet still holds its locks. expect(config.idle_in_transaction_session_timeout).toBe(10_000); }); - it("lets a batch job take as long as its work takes", () => { - const { statementMs, lockMs, connectMs } = deadlinesFor("batch"); - // 0 is PostgreSQL's own "no bound": a seed, an import or a backfill must - // never be cut off halfway by a number chosen for a page. - expect(statementMs).toBe(0); - expect(lockMs).toBe(0); - // It still gives up on a database that cannot be reached at all. - expect(connectMs).toBeGreaterThan(0); - }); - it("takes its numbers from the environment, so production can differ", () => { vi.stubEnv("DB_POOL_MAX", "40"); vi.stubEnv("DB_STATEMENT_TIMEOUT_MS", "2500"); @@ -45,6 +55,17 @@ describe("the deadlines a web process runs under", () => { }); }); + it("keeps the idle-transaction bound when the statement bound is lifted", () => { + // One variable must not turn off two bounds: raising the statement bound + // to let a slow report through must not also let a transaction sit on its + // locks for ever. + vi.stubEnv("DB_STATEMENT_TIMEOUT_MS", "0"); + expect(deadlinesFor("web")).toMatchObject({ + statementMs: 0, + idleTxMs: 10_000, + }); + }); + it("refuses a deadline that is not a whole number of milliseconds", () => { vi.stubEnv("DB_CONNECT_TIMEOUT_MS", "5s"); // Loud, like every other environment mistake here: a deadline that @@ -52,6 +73,25 @@ describe("the deadlines a web process runs under", () => { expect(() => deadlinesFor("web")).toThrow(/DB_CONNECT_TIMEOUT_MS/); }); + it("refuses the values that look permissive and are not", () => { + // 0 connections becomes pg's default of 10, silently. + vi.stubEnv("DB_POOL_MAX", "0"); + expect(() => deadlinesFor("web")).toThrow(/DB_POOL_MAX/); + vi.unstubAllEnvs(); + // 0 here is the unbounded wait this whole issue is about. + vi.stubEnv("DB_CONNECT_TIMEOUT_MS", "0"); + expect(() => deadlinesFor("web")).toThrow(/DB_CONNECT_TIMEOUT_MS/); + vi.unstubAllEnvs(); + // Past setTimeout's ceiling Node fires after ONE millisecond, so "a big + // number meaning never" would refuse every queued caller instantly. + vi.stubEnv("DB_CONNECT_TIMEOUT_MS", "3000000000"); + expect(() => deadlinesFor("web")).toThrow(/DB_CONNECT_TIMEOUT_MS/); + vi.unstubAllEnvs(); + // Number("0x10") is 16 — a typo that quietly means something else. + vi.stubEnv("DB_POOL_MAX", "0x10"); + expect(() => deadlinesFor("web")).toThrow(/DB_POOL_MAX/); + }); + it("names the connection after the environment holding it", () => { vi.stubEnv("S3_PREFIX", "pr-170/"); // dev and every preview share one database (#113); pg_stat_activity has @@ -62,6 +102,36 @@ describe("the deadlines a web process runs under", () => { }); }); +describe("the deadlines a batch job runs under", () => { + it("lets the work take as long as it takes", () => { + const { statementMs, lockMs, connectMs } = deadlinesFor("batch"); + // 0 leaves the server's own setting standing — 0 on ours. A seed, an + // import or a backfill must never be cut off halfway by a number chosen + // for a page. + expect(statementMs).toBe(0); + expect(lockMs).toBe(0); + // It still gives up on a database that cannot be reached at all. + expect(connectMs).toBeGreaterThan(0); + }); + + it("ignores the variables an environment sets for its web process", () => { + vi.stubEnv("DB_STATEMENT_TIMEOUT_MS", "10000"); + vi.stubEnv("DB_LOCK_TIMEOUT_MS", "3000"); + // Otherwise the opt-out would be defeated by the very variables this + // change introduces: `pnpm db:import-teryt` upserts a hundred thousand + // places in one statement, and ten seconds would roll it back. + expect(deadlinesFor("batch")).toMatchObject({ + statementMs: 0, + lockMs: 0, + }); + }); + + it("refuses to put a server's own pool on those deadlines", () => { + vi.stubEnv("NEXT_RUNTIME", "nodejs"); + expect(() => runAsBatchJob()).toThrow(/scripts/); + }); +}); + describe("reading a failure", () => { it("recognises each bound by the code PostgreSQL raises", () => { expect( @@ -88,6 +158,15 @@ describe("reading a failure", () => { expect(databaseStall(wrapped)).toBe("statement-timeout"); }); + it("gives up on a cause chain that points back at itself", () => { + // This runs on the failure path of every request, on one core: a chain + // with a loop in it must end the walk, not the process. + const first = new Error("first"); + const second = new Error("second", { cause: first }); + (first as { cause?: unknown }).cause = second; + expect(databaseStall(first)).toBeNull(); + }); + it("says nothing about failures that are not a deadline", () => { expect(databaseStall(new Error("duplicate key value"))).toBeNull(); expect(databaseStall("not an error")).toBeNull(); @@ -103,8 +182,7 @@ describe.skipIf(!url)("against a real PostgreSQL", () => { for (const [name, value] of Object.entries(overrides)) { vi.stubEnv(name, value); } - const created = new Pool(poolConfig("web", url!)); - created.on("error", () => {}); + const created = watchPool(new Pool(poolConfig("web", url!))); open.push(created); return created; } @@ -116,21 +194,28 @@ describe.skipIf(!url)("against a real PostgreSQL", () => { it("cuts off a statement waiting on a lock somebody else holds", async () => { const holder = pool({ DB_LOCK_TIMEOUT_MS: "0" }); const held = await holder.connect(); - await held.query("begin"); - await held.query("select pg_advisory_xact_lock(20260912)"); - - const waiter = pool({ DB_LOCK_TIMEOUT_MS: "300" }); - // The app's own per-user lock is an advisory one (lockUser in - // lib/works.ts), and lock_timeout covers it — measured here rather than - // assumed, because that is the lock every write in the app takes. - const failure = await waiter - .query("select pg_advisory_xact_lock(20260912)") - .then(() => null) - .catch((error: unknown) => error); - expect(databaseStall(failure)).toBe("lock-timeout"); + try { + await held.query("begin"); + await held.query("select pg_advisory_xact_lock(20260912)"); + + const waiter = pool({ DB_LOCK_TIMEOUT_MS: "300" }); + // Taken inside a transaction, as lib/works.ts takes it: this is the + // per-user advisory lock every write in the app goes through, and that + // lock_timeout covers an ADVISORY lock at all is the one thing here + // worth measuring rather than assuming. + const failure = await waiter + .query("begin; select pg_advisory_xact_lock(20260912)") + .then(() => null) + .catch((error: unknown) => error); + expect(databaseStall(failure)).toBe("lock-timeout"); - await held.query("rollback"); - held.release(); + await held.query("rollback"); + } finally { + // Released whatever the assertions did: an outstanding client would + // make pool.end() in afterEach wait for a client that never comes back, + // and the suite would time out instead of reporting the failure. + held.release(); + } }); it("cuts off a statement that simply runs too long", async () => { @@ -145,15 +230,47 @@ describe.skipIf(!url)("against a real PostgreSQL", () => { it("answers the caller that cannot get a connection instead of queueing it", async () => { const crowded = pool({ DB_POOL_MAX: "1", DB_CONNECT_TIMEOUT_MS: "300" }); const taken = await crowded.connect(); - const started = Date.now(); - // Before #172 this call waited for as long as the holder kept the - // connection — for ever, if that was a statement nothing cut off. - const failure = await crowded - .query("select 1") - .then(() => null) - .catch((error: unknown) => error); - expect(databaseStall(failure)).toBe("no-connection"); - expect(Date.now() - started).toBeLessThan(5_000); - taken.release(); + try { + const started = Date.now(); + // Before #172 this call waited for as long as the holder kept the + // connection — for ever, if that was a statement nothing cut off. + const failure = await crowded + .query("select 1") + .then(() => null) + .catch((error: unknown) => error); + expect(databaseStall(failure)).toBe("no-connection"); + expect(Date.now() - started).toBeLessThan(5_000); + } finally { + taken.release(); + } + }); + + it("survives the server killing a transaction that went quiet", async () => { + const said: string[] = []; + const logged = vi + .spyOn(console, "error") + .mockImplementation((...parts: unknown[]) => { + said.push(parts.join(" ")); + }); + const napping = pool({ DB_IDLE_TX_TIMEOUT_MS: "300" }); + const client = await napping.connect(); + try { + await client.query("begin"); + await new Promise((wake) => setTimeout(wake, 1_000)); + // The point of the test is not this rejection. It is that the process + // is still here to make it: the kill arrives on a client the pool has + // checked out, whose own error listener pg-pool removed, and an 'error' + // event with no listener ends the process. Measured 12.09.2026 — the + // guard in watchPool is what this reaches. + const failure = await client + .query("select 1") + .then(() => null) + .catch((error: unknown) => error); + expect(failure).toBeInstanceOf(Error); + expect(said.join("\n")).toContain("idle-transaction"); + } finally { + client.release(); + logged.mockRestore(); + } }); }); diff --git a/src/db/client.ts b/src/db/client.ts index a203a6d..87c08f5 100644 --- a/src/db/client.ts +++ b/src/db/client.ts @@ -28,12 +28,21 @@ interface Deadlines { poolMax: number; /** How long a caller waits for a free connection before it is told no. */ connectMs: number; - /** How long one statement may run. 0 turns it off (PostgreSQL's own 0). */ + /** How long one statement may run. */ statementMs: number; - /** How long one statement may wait for a lock. 0 turns it off. */ + /** How long one statement may wait for a lock. */ lockMs: number; + /** How long a transaction may sit between statements, holding its locks. */ + idleTxMs: number; } +// 0 on the three server-side bounds does NOT mean "off": pg only puts a +// setting in the startup packet when it is truthy (pg/lib/client.js), so 0 +// means "send nothing, the server's own setting stands". On ours that setting +// is 0, which is off — but a managed database (#24) may well ship a role-level +// statement_timeout, and a batch job there would inherit it. Read 0 as +// "inherit", and check what is inherited when production exists. + // Dev's numbers, chosen for the shape of dev: one core, one containerised // PostgreSQL with max_connections 100, and dev plus every open preview // sharing it with a pool each (#31, #113). Production's managed database @@ -45,19 +54,39 @@ interface Deadlines { // stuck one. Three seconds of waiting for a lock is a queue forming behind // another writer — answering then beats joining it. const DEADLINES: Record = { - web: { poolMax: 10, connectMs: 5_000, statementMs: 10_000, lockMs: 3_000 }, - batch: { poolMax: 4, connectMs: 30_000, statementMs: 0, lockMs: 0 }, + web: { + poolMax: 10, + connectMs: 5_000, + statementMs: 10_000, + lockMs: 3_000, + idleTxMs: 10_000, + }, + batch: { + poolMax: 4, + connectMs: 30_000, + statementMs: 0, + lockMs: 0, + idleTxMs: 0, + }, }; +// setTimeout's ceiling. Past it Node warns and fires after ONE millisecond — +// so an operator reaching for a large finite number as "effectively never" +// would make every queued checkout fail instantly, and the log would blame +// the database. Refused instead. +const MAX_MS = 2_147_483_647; + // Fail loud, like requireEnv: a mistyped deadline that silently fell back to -// the default would be discovered the night it was needed. -function readOverride(name: string, fallback: number): number { +// the default would be discovered the night it was needed. Decimal digits +// only — Number("0x10") is 16, and a typo that quietly means something else +// is worse than one that stops the process. +function readOverride(name: string, fallback: number, least = 0): number { const raw = process.env[name]?.trim(); if (!raw) return fallback; const value = Number(raw); - if (!Number.isInteger(value) || value < 0) { + if (!/^\d+$/.test(raw) || value < least || value > MAX_MS) { throw new Error( - `${name} must be a whole number of milliseconds (0 turns the bound off), not "${raw}"`, + `${name} must be a whole number between ${least} and ${MAX_MS}, not "${raw}"`, ); } return value; @@ -65,11 +94,22 @@ function readOverride(name: string, fallback: number): number { export function deadlinesFor(use: DatabaseUse): Deadlines { const defaults = DEADLINES[use]; + // A batch job takes the built-in numbers and nothing else. These variables + // belong to the WEB process of an environment; a seed or an import that + // inherited a web statement timeout would be cut off halfway through, which + // is the whole reason the opt-out exists. + if (use === "batch") return defaults; return { - poolMax: readOverride("DB_POOL_MAX", defaults.poolMax), - connectMs: readOverride("DB_CONNECT_TIMEOUT_MS", defaults.connectMs), + // Never 0: a pool of 0 silently becomes pg's default of 10, and a connect + // deadline of 0 is the unbounded wait this issue is about. + poolMax: readOverride("DB_POOL_MAX", defaults.poolMax, 1), + connectMs: readOverride("DB_CONNECT_TIMEOUT_MS", defaults.connectMs, 1), statementMs: readOverride("DB_STATEMENT_TIMEOUT_MS", defaults.statementMs), lockMs: readOverride("DB_LOCK_TIMEOUT_MS", defaults.lockMs), + // Its own variable, not the statement bound reused: raising the statement + // bound to let one slow report through must not also let a transaction + // sit on its locks for ever. + idleTxMs: readOverride("DB_IDLE_TX_TIMEOUT_MS", defaults.idleTxMs), }; } @@ -87,7 +127,8 @@ export function poolConfig( use: DatabaseUse, connectionString: string, ): PoolConfig { - const { poolMax, connectMs, statementMs, lockMs } = deadlinesFor(use); + const { poolMax, connectMs, statementMs, lockMs, idleTxMs } = + deadlinesFor(use); return { connectionString, max: poolMax, @@ -102,8 +143,8 @@ export function poolConfig( lock_timeout: lockMs, // A transaction left open with nothing happening in it still holds every // lock it has taken. Nothing here does I/O inside a transaction, so a gap - // longer than a whole statement may run means the caller is gone. - idle_in_transaction_session_timeout: statementMs, + // that long means the caller is gone. + idle_in_transaction_session_timeout: idleTxMs, // Who is holding the connection, as pg_stat_activity will show it: dev // and every preview share one database (#113), so "one of them is // queueing" is only actionable if the row says which. @@ -132,6 +173,11 @@ let poolUse: DatabaseUse = "web"; * throws rather than pretend. */ export function runAsBatchJob(): void { + if (process.env.NEXT_RUNTIME) { + throw new Error( + "runAsBatchJob() is for scripts/*: a server must not put the pool its pages use on the batch deadlines (#172)", + ); + } if (db) { throw new Error( "the database pool is already open — runAsBatchJob() belongs before the first getDb()", @@ -144,19 +190,65 @@ export function runAsBatchJob(): void { // modules can be evaluated at build time (and by the DB-less e2e job) without // DATABASE_URL; the first query is where a missing variable fails loudly. export function getDb(): Database { - if (!db) { - const pool = new Pool(poolConfig(poolUse, requireEnv("DATABASE_URL"))); - // Without a listener here an idle connection dropped by the server (a - // restart, an idle-transaction kill) reaches the process as an unhandled - // 'error' event, which is a crash rather than a log line. - pool.on("error", (error) => { - console.error("[db] an idle connection failed:", error.message); - }); - db = drizzle({ client: pool, schema }) as Database; - } + db ??= openPool(poolUse); return db; } +let backgroundDb: Database | undefined; + +/** + * A second pool, for work that runs inside the server but is answering + * nobody: today the R360 collector's sweep (#127, #156), which reads every + * file row to find objects no record names. + * + * It has to be a pool of its own, because the deadlines are a property of the + * connection and the collector shares this process with the pages. Under the + * web bound its sweep would not fail loudly, it would return "nothing found" + * as the table grows — and nothing tells that apart from a clean bucket. + */ +export function getBackgroundDb(): Database { + backgroundDb ??= openPool("batch"); + return backgroundDb; +} + +function openPool(use: DatabaseUse): Database { + const pool = watchPool(new Pool(poolConfig(use, requireEnv("DATABASE_URL")))); + return drizzle({ client: pool, schema }) as Database; +} + +/** + * Both listeners a pool of ours must carry, and the second is not the first + * one written twice. + * + * pg-pool's own listener watches a connection sitting IDLE IN THE POOL, and + * it takes that listener off the client the moment the client is checked out. + * So a connection the server kills while somebody holds it — an + * idle-in-transaction kill, a restart, the tunnel dropping — arrives at a + * client with no listener at all, and Node turns an 'error' event with no + * listener into a crashed process. + * + * Measured on 12.09.2026 against dev's PostgreSQL: with only the pool + * listener the process exits on the idle-in-transaction kill; with the client + * listener the query rejects and the request fails on its own. + */ +export function watchPool(pool: Pool): Pool { + pool.on("error", (error) => { + console.error( + `[db] an idle connection failed (${databaseStall(error) ?? "no bound"}):`, + error.message, + ); + }); + pool.on("connect", (client) => { + client.on("error", (error) => { + console.error( + `[db] a connection in use failed (${databaseStall(error) ?? "no bound"}):`, + error.message, + ); + }); + }); + return pool; +} + /** * The bound a failure ran into, or null for everything else (#172). * @@ -183,10 +275,12 @@ const STALL_BY_CODE: Record = { const NO_CONNECTION = "timeout exceeded when trying to connect"; export function databaseStall(error: unknown): DatabaseStall | null { + // Bounded: a cause chain that points back at itself would otherwise spin + // for ever, and this runs on the failure path of every request. for ( - let current: unknown = error; - current instanceof Error; - current = current.cause + let current: unknown = error, links = 0; + current instanceof Error && links < 16; + current = current.cause, links++ ) { const code = (current as { code?: unknown }).code; if (typeof code === "string" && code in STALL_BY_CODE) { diff --git a/src/instrumentation.ts b/src/instrumentation.ts index 0c92349..8f75cc3 100644 --- a/src/instrumentation.ts +++ b/src/instrumentation.ts @@ -20,7 +20,7 @@ export async function register() { appEnv: process.env.APP_ENV, collect: async () => { const [ - { getDb }, + { getBackgroundDb }, { getStorage, keyPrefix }, { collectAllUnfinishedFrameSets, unrecordedFrameSets }, ] = await Promise.all([ @@ -29,7 +29,11 @@ export async function register() { import("@/lib/r360/frame-set"), ]); const deps = { - db: getDb(), + // #172: its own pool, without the web deadlines. This sweep reads + // every file row, and under a statement bound it would stop + // reporting rather than fail — "nothing found" and "nothing looked" + // read the same in a log. + db: getBackgroundDb(), storage: getStorage(), prefix: keyPrefix(), }; @@ -61,10 +65,22 @@ export async function onRequestError( error: unknown, request: { path: string; method: string }, ) { - const { databaseStall } = await import("@/db/client"); - const stall = databaseStall(error); - if (!stall) return; - console.error( - `[db] ${request.method} ${request.path} hit the ${stall} bound — the numbers are DB_* in .env.example (#172)`, - ); + // Nothing in here may throw: this hook runs while a request is already + // failing, and a failure of its own would replace the error somebody needs + // to read with the error of the thing meant to explain it. + try { + const { databaseStall } = await import("@/db/client"); + const stall = databaseStall(error); + if (!stall) return; + // The path, not the request target Next hands over: that one carries the + // query string, and a verification or reset token lives there. Those are + // hashed at rest (lib/auth.ts) precisely so a leaked store cannot redeem + // a live link — writing one into the log would undo that in another store. + const path = request.path.split("?")[0]; + console.error( + `[db] ${request.method} ${path} hit the ${stall} bound — the numbers are DB_* in .env.example (#172)`, + ); + } catch { + // Deliberately silent: Next has already reported the original error. + } } diff --git a/src/lib/api-route.ts b/src/lib/api-route.ts index c6bd072..7bcbcf6 100644 --- a/src/lib/api-route.ts +++ b/src/lib/api-route.ts @@ -1,6 +1,7 @@ import { headers } from "next/headers"; import { NextResponse } from "next/server"; import type { z } from "zod"; +import { databaseStall } from "@/db/client"; import { getAuth } from "@/lib/auth"; import { appOrigin } from "@/lib/env"; @@ -15,7 +16,18 @@ export async function sessionUserId(): Promise { headers: await headers(), }); return session?.user.id ?? null; - } catch { + } catch (error) { + // Closed, but no longer silent (#172). Since the pool answers instead of + // queueing, a database in trouble arrives HERE — and signing everybody + // out is what that looks like from the outside. Nothing else would say so: + // this catch returns a value, so the request succeeds and Next's error + // path never runs. + const stall = databaseStall(error); + if (stall) { + console.error( + `[db] a session could not be read: the ${stall} bound — everyone reads as signed out while this lasts (#172)`, + ); + } return null; } } diff --git a/src/lib/auth.ts b/src/lib/auth.ts index ca3d37e..c1b5f9e 100644 --- a/src/lib/auth.ts +++ b/src/lib/auth.ts @@ -59,7 +59,10 @@ function withCallbackStatus(verifyUrl: string, status: string): string { const link = new URL(verifyUrl); const callbackURL = link.searchParams.get("callbackURL") ?? "/email-changed"; const separator = callbackURL.includes("?") ? "&" : "?"; - link.searchParams.set("callbackURL", `${callbackURL}${separator}status=${status}`); + link.searchParams.set( + "callbackURL", + `${callbackURL}${separator}status=${status}`, + ); return link.href; } @@ -131,6 +134,12 @@ export function createAuth(options: { telemetry: { enabled: false }, // #4 contract: no `fields` mappings — the adapter resolves by the TS // property names in schema.ts, which are the Better Auth defaults. + // + // No `transaction: true`, and that is load-bearing since #172: the + // library wraps sign-up in a transaction when the adapter says it can, + // and that wrapper would hold a connection across scrypt AND the e-mail + // provider's HTTP call — straight into the idle-transaction bound. With + // it off the wrapper is a pass-through and nothing pins a connection. database: drizzleAdapter(db, { provider: "pg", usePlural: true, schema }), advanced: { // §9: ids come from the database (gen_random_uuid()), never the app. @@ -311,7 +320,9 @@ export function createAuth(options: { const callbackURL = requestUrl.searchParams.get("callbackURL"); if ( callbackURL && - ctx.context.isTrustedOrigin(callbackURL, { allowRelativePaths: true }) + ctx.context.isTrustedOrigin(callbackURL, { + allowRelativePaths: true, + }) ) { const target = new URL(callbackURL, ctx.context.baseURL); target.searchParams.set("error", "INVALID_TOKEN"); diff --git a/tasks/plan.md b/tasks/plan.md index f56a263..a7e2afb 100644 --- a/tasks/plan.md +++ b/tasks/plan.md @@ -101,7 +101,11 @@ in under 5 minutes (manual walkthrough); e2e green. connection rather than in `DATABASE_URL`: a migration or a seed must never be cut off by a bound meant for a page, so the scripts declare themselves batch jobs and run without them. Proven against a real PostgreSQL — including that `lock_timeout` does cover the advisory - lock every write in this app takes, which was worth measuring rather than assuming. + lock every write in this app takes, which was worth measuring rather than assuming. The + review found the sting in the tail: the new idle-transaction bound kills a connection + somebody is holding, and pg-pool takes its own error listener off a connection while it is + checked out — so without a listener of ours the kill ended the PROCESS. Measured, fixed, + and the test fails without the fix. - [#119](https://github.com/Devski/platform-lite/issues/119) The dev instance keeps every image it ever pulled (`infra`). Filed 09.09.2026 when its root filesystem reached 100%: 129 images, 21.8 GB, three of them in use. Previews stopped starting at all, and dev's