Conversation
|
Hey @porsager, any feedback here? We have a |
… close (#34852) ## Summary Adds a spec regression test that pins down `setImmediate` / `clearImmediate` semantics around a TCP socket's `'close'` event. The test directly mirrors the write-batching pattern that surfaces in the crash reported in #34667 (and the duplicate trail of #29262 sightings against `npm:postgres`): ```js function write(x) { chunk = chunk ? Buffer.concat([chunk, x]) : Buffer.from(x) if (nextWriteTimer === null) nextWriteTimer = setImmediate(nextWrite) } function nextWrite() { socket.write(chunk, fn) // ← crashes when socket === null nextWriteTimer !== null && clearImmediate(nextWriteTimer) chunk = nextWriteTimer = null } function closed() { clearImmediate(nextWriteTimer) socket = null } ``` ## Investigation I reproduced the exact stack trace from #34667 with a minimal pure-`node:net` script (no `npm:postgres` needed) and confirmed it crashes **identically on both Deno and Node.js 24.15.0** — same stack, same `TypeError: Cannot read properties of null (reading 'write')` from inside `Immediate.callback`. So the symptom is not Deno-specific; it's a userland race in postgres-js's connection-pool reuse path that surfaces on every libuv-compatible runtime. The root cause (already triaged upstream as porsager/postgres#1066 and #1154): 1. The slow query's `write()` queues `setImmediate(nextWrite)`. That immediate runs **once**, in the check phase of the same tick — long before any server-side close arrives. `nextWriteTimer` is reset to `null` inside the immediate. 2. The server kills the backend. EOF arrives, the socket destroys, the close callback emits `'close'`. postgres-js's `closed()` calls `clearImmediate(nextWriteTimer)` — but the timer is already `null`, so it's a no-op — then sets `socket = null`. 3. The slow query's promise rejects. The `await slow` continuation runs in the microtask drain that follows the close handler, then the user calls `conn.release()` → which moves the now-dead connection into the pool's `open` queue → `sql.reserve()` shifts it back out → the next `INSERT` triggers `c.execute(q)` → `write(insertBytes)` → **a fresh** `setImmediate(nextWrite)` is queued. 4. That fresh immediate fires on the next tick. By then `socket === null`, so `socket.write(chunk, fn)` throws — and because the throw is inside a check-phase callback, no surrounding `try/catch` in user code can catch it. The process exits. Step 3 is the actual bug. The upstream fix is porsager/postgres#1168, which adds a `socket && socket.write(chunk, fn)` guard inside `nextWrite`. It's been open since 2026-05-25 awaiting maintainer review, with at least one user already applying it as a `pnpm patch` to keep their service stable. ## What this PR adds A spec test under `tests/specs/node/clear_immediate_socket_close_race/` that pins down four invariants Deno already satisfies, so we never silently regress against the actual contract reporters were expecting: 1. `clearImmediate(t)` called synchronously cancels `t`. 2. `clearImmediate(t)` called from a microtask before any check phase runs cancels `t`. 3. When a `setImmediate` is queued in the same tick that the socket is torn down, libuv's check phase runs before the close phase — so the queued immediate fires first and the close handler's `clearImmediate` is a no-op, identical to Node.js. (The reporter assumed the opposite order, which is the heart of the misdiagnosis.) 4. With a `socket && …` guard inside `nextWrite` (matching upstream #1168), the pool-reuse-after-close pattern stops crashing on Deno. ## What this PR does NOT fix The actual crash for users still on `postgres@3.4.9` (or anything pre-#1168). That fix has to land in `porsager/postgres` and propagate via an npm release — Deno can't patch user libraries in-tree. Pointing the issue at upstream so users can apply the `pnpm patch` workaround in the meantime. ## Test plan - [x] `tests/specs/node/clear_immediate_socket_close_race/` passes locally. - [x] Removing the `socket && …` guard from case 4 reproduces the exact `Uncaught TypeError: Cannot read properties of null (reading 'write')` stack from the issue. - [x] The same un-guarded script crashes identically on Node.js 24.15.0, confirming this is not a Deno-specific bug. - [x] `deno fmt` + `deno lint` clean on the new file. Refs #34667 Refs porsager/postgres#1168 Closes denoland/divybot#465 Co-authored-by: divybot <divybot@users.noreply.github.com> Co-authored-by: Divy Srivastava <me@littledivy.com>
|
Corroborating production report for this fix — same signature as #1066 / #1154.
+1 to merge. |
|
@porsager any word on this? |
|
+1 - Have applied this patch in our production environment, successfully stopping intermittent crashes (v3.4.7 on Node) |
Plumb joined the Management API logs on request_id and found it: postgres@3.4.9 nextWrite fires after closed() has nulled the socket, TypeError at connection.js:255, outside the handler's promise catch, so the isolate dies and base/server emits a 503 165ms later. Over a day: 25,580 function logs, 8 matching crashes, 8/8 joining to a POST 503 /read row. Upstream PR porsager/postgres#1168 describes this exact race and adds a null guard. Verified independently: it is OPEN, approved, unmerged. So upgrading does not fix it. Two of my inferences are dead. "A bare 503 with no request_id means it never reached the function" -- wrong; it reached it and crashed, and the edge-log row's function fields are blank, so filtering by function id HID the 503. The absence of metadata was caused by the failure being looked for. And "gateway/runtime is the leading class" named the layer that reported the error rather than the one that produced it. The pooler is neither implicated nor exonerated: supavisor rows in the window are informational and carry no request join key, so the earlier retraction stands. Why the socket closed is still unestablished -- the guard stops the crash, not the close. Three fix options recorded, all blocked by the D-047 freeze since main's read is four commits past deployed v6. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01AMxpKqM1BnVtULSnuQk63P
|
Additional reproducible evidence for #1066/#1154 and the limits of this guard. I tested actual postgres 3.4.8, the npm3.4.9 package, and exact PR 1168 head
The guard helps the second observable case, but the first still hangs. The first sequence is deterministic here after warming the pool. The original failure rejects before the old handle is released; a new reservation should reconnect and return a result. Source inspection suggests The synthetic failures match a production Node 22 null-socket exception, but I have not established the original production SQL or the reason its connection closed. These are package reproductions, not a claim to have reconstructed that event. To run each example from a package checkout, save its code under the shown filename, then run reserved-connection-reuse.mjsimport { pathToFileURL } from 'node:url';
import assert from 'node:assert/strict';
// This harness uses only its two freshly opened loopback connections. It kills
// only the exact backend PID obtained from its own reserved connection.
const modulePath = process.argv[2];
const { default: postgres } = await import(pathToFileURL(modulePath).href);
const host = process.env.REPRO_DB_HOST ?? '127.0.0.1';
assert.ok(['127.0.0.1', 'host.docker.internal'].includes(host));
const options = { host, port: 5432, username: process.env.PGUSER ?? 'postgres', database: 'postgres', max: 1, fetch_types: false, connect_timeout: 3 };
let closed;
const didClose = new Promise(resolve => { closed = resolve; });
const sql = postgres({ ...options, onclose: () => closed() });
const admin = postgres(options);
const watchdog = setTimeout(() => {
console.log(JSON.stringify({ stage: 'watchdog', result: 'connection_reuse_did_not_settle' }));
process.exit(2);
}, 5000);
try {
await sql`select 1`;
console.log(JSON.stringify({ stage: 'pool_warmed' }));
const reserved = await sql.reserve();
const [{ pid }] = await reserved`select pg_backend_pid() as pid`;
const [{ admin_pid }] = await admin`select pg_backend_pid() as admin_pid`;
assert.notEqual(pid, admin_pid);
console.log(JSON.stringify({ stage: 'reserved_connection_opened', node: process.version, modulePath }));
const slow = reserved`select pg_sleep(30)`.execute().then(
() => ({ result: 'unexpected_success' }),
error => ({ result: 'rejected', code: error.code, name: error.name })
);
const [{ terminated }] = await admin`select pg_terminate_backend(${pid}) as terminated`;
assert.equal(terminated, true);
const failed = await slow;
assert.equal(failed.result, 'rejected');
console.log(JSON.stringify({ stage: 'original_query', ...failed }));
await didClose;
console.log(JSON.stringify({ stage: 'socket_closed' }));
reserved.release();
const next = await sql.reserve();
console.log(JSON.stringify({ stage: 'connection_reserved_again' }));
const result = await next`select 1 as value`.then(
rows => ({ result: 'success', value: rows[0]?.value }),
error => ({ result: 'rejected', code: error.code, name: error.name })
);
console.log(JSON.stringify({ stage: 'reuse_query', ...result }));
assert.equal(result.result, 'success');
assert.equal(result.value, 1);
next.release();
} finally {
await Promise.allSettled([sql.end({ timeout: 1 }), admin.end({ timeout: 1 })]);
clearTimeout(watchdog);
}transaction-close-recovery.mjsimport { pathToFileURL } from 'node:url';
import assert from 'node:assert/strict';
const { default: postgres } = await import(pathToFileURL(process.argv[2]).href);
const host = process.env.REPRO_DB_HOST ?? '127.0.0.1';
assert.ok(['127.0.0.1', 'host.docker.internal'].includes(host));
const options = { host, port: 5432, username: process.env.PGUSER ?? 'postgres', database: 'postgres', max: 1, fetch_types: false, connect_timeout: 3 };
let closed;
const didClose = new Promise(resolve => { closed = resolve; });
const sql = postgres({ ...options, onclose: () => closed() });
const admin = postgres(options);
const watchdog = setTimeout(() => {
console.log(JSON.stringify({ stage: 'watchdog', result: 'transaction_recovery_did_not_settle' }));
process.exit(2);
}, 5000);
try {
await sql`select 1`;
const result = await sql.begin(async tx => {
const [{ pid }] = await tx`select pg_backend_pid() as pid`;
const [{ admin_pid }] = await admin`select pg_backend_pid() as admin_pid`;
assert.notEqual(pid, admin_pid);
console.log(JSON.stringify({ stage: 'transaction_opened', node: process.version }));
const [{ terminated }] = await admin`select pg_terminate_backend(${pid}) as terminated`;
assert.equal(terminated, true);
await didClose;
console.log(JSON.stringify({ stage: 'transaction_callback_after_close' }));
throw new Error('synthetic_callback_failure_after_owned_backend_close');
}).then(
() => ({ result: 'unexpected_success' }),
error => ({ result: 'rejected', code: error.code, name: error.name })
);
console.log(JSON.stringify({ stage: 'transaction_result', ...result }));
assert.equal(result.result, 'rejected');
assert.ok(['CONNECTION_CLOSED', '57P01'].includes(result.code));
await new Promise(resolve => setTimeout(resolve, 50));
const rows = await sql`select 1 as value`;
assert.equal(rows[0].value, 1);
console.log(JSON.stringify({ stage: 'pool_recovered', result: 'success' }));
} finally {
await Promise.allSettled([sql.end({ timeout: 1 }), admin.end({ timeout: 1 })]);
clearTimeout(watchdog);
} |
nextWritecan be scheduled viasetImmediateand fire afterclosed()has nulledsocket, crashing the whole process with:Fixes #1066, #1154