Closing the database clients waits for a scheduled reconnect that the shutdown cannot cancel

[Nitjsefnie]

Description

sql.end() waits for a reconnect attempt that has only been scheduled, and
cannot cancel it.

When the pool hands a queued query to a connection in its closed queue it calls
that connection's connect(query), which schedules the attempt through the
library's backoff rather than opening a socket immediately. A sql.end() that
arrives inside that scheduled window does not settle until the attempt has run
and its socket has closed.

The wait is as long as the schedule, and the schedule is computed from a
pool-wide retry counter. Measured with the probe below, single connection,
against a peer that accepts and closes until it starts refusing:

build	settle latency from the end() call	TCP attempts accepted
main at 0b306d8	43 ms	12,263
the branch of #222 at e6b1dd7	17,099 ms	7

Both numbers are the same defect. main is fast here only because it schedules
every reconnect with no delay at all, which is the connection storm #164 is
about — the 12,263 accepts in the same run are that storm. #222 fixes the storm
by spacing the attempts, and in doing so lengthens this window from a few
milliseconds to the library's 10–20 second backoff cap. So #222 does not
introduce the wait; it makes an existing one three orders of magnitude longer.

scripts/reconcile.ts awaits closeSql() in the finally of its entry point,
so a reconcile run shutting down in this window blocks there for up to the cap.

Expected Behavior

sql.end() settles without waiting for a reconnect attempt that has only been
scheduled, whatever the schedule length, and a query the pool has already
dispatched to a connection is still served rather than rejected.

Reproduction Steps

1. Check out the branch of fix(patch): settle and space a connect-phase socket death #222 (issue-164-connect-phase-end) and run
   pnpm install --frozen-lockfile. No container is needed; the probe is its
   own peer.
2. Save the probe below beside a node_modules that resolves postgres to that
   install, and run node probe-poolconnect.mjs 20000.

// The window opened by connection.connect(query), which discards the handle
// reconnect() returns, so end()'s cancel gate cannot fire.
//
// Construction:
//   1. an accept-then-close peer from the start, so every close is an error-free
//      connect-phase close, which advances the pool-wide retry counter.
//   2. at T the peer starts refusing, so the next attempt errors, `initial` is
//      nulled, the close takes the shared path, onclose() runs, and the pool
//      hands a still-queued query to the connection via connection.connect(),
//      which schedules the retry and discards its handle.
//   3. sql.end() is called from inside that window, via the `onclose` option,
//      which fires immediately before the pool calls connect().
import net from "node:net";
import fs from "node:fs";
import path from "node:path";
import { fileURLToPath } from "node:url";
import postgres from "postgres";

const here = path.dirname(fileURLToPath(import.meta.url));
const REFUSE_AT = Number(process.argv[2] ?? 30000);
const NQUERIES = Number(process.env.NQUERIES || 3);
const MAX = Number(process.env.MAX || 1);

const src = fs.readFileSync(path.join(here, "node_modules/postgres/src/connection.js"), "utf8");
const BUILD = src.includes("retryTimer") ? "POSTFIX" : src.includes("if (initial && ending)") ? "MID" : "PRE";
const t0 = Date.now();
const log = (...a) => console.log(`+${String(Date.now() - t0).padStart(6)}ms`, ...a);

const proxy = { connections: 0 };
const server = net.createServer((c) => {
  proxy.connections++;
  c.on("error", () => {});
  c.once("data", () => c.end());
  c.on("data", () => {});
});
await new Promise((r) => server.listen(0, "127.0.0.1", r));
const port = server.address().port;
console.log(`BUILD=${BUILD} refuse_at=${REFUSE_AT}ms max=${MAX} queries=${NQUERIES} proxy=${port}`);

let endAt = null, settledAt = null, how = null, fired = false, ordinaryCloses = 0;

const sql = postgres({
  host: "127.0.0.1", port, database: "probe", user: "probe", password: "probe", max: MAX,
  // fires only on the ordinary onclose path, never on the connect-phase early return
  onclose: () => {
    ordinaryCloses++;
    if (fired || Date.now() - t0 < REFUSE_AT) return;
    fired = true;
    log(`ordinary onclose #${ordinaryCloses} -- the pool is about to call connection.connect(queued)`);
    endAt = Date.now();
    sql.end().then(() => { settledAt = Date.now(); how = "resolved"; log("sql.end(): RESOLVED"); },
                   (e) => { settledAt = Date.now(); how = "rejected " + e.message; log("sql.end(): REJECTED"); });
    log("sql.end() called from inside the scheduled window");
  },
});

const settled = [];
for (let i = 0; i < NQUERIES; i++)
  sql`select ${i}::int as n`.then(() => settled.push(`q${i}:ok`), (e) => settled.push(`q${i}:${e.message}`));

setTimeout(() => { server.close(); log("peer now REFUSES"); }, REFUSE_AT);

const deadline = Date.now() + REFUSE_AT + 120000;
while (Date.now() < deadline && !settledAt) await new Promise((r) => setTimeout(r, 200));
console.log(`RESULT build=${BUILD} accepts=${proxy.connections} ordinary_closes=${ordinaryCloses} ` +
  `window_settle_ms=${settledAt ? settledAt - endAt : "PENDING"} settled=${how ?? "no"} queries=${JSON.stringify(settled)}`);
process.exit(0);

Observed on the branch:

BUILD=POSTFIX refuse_at=20000ms max=1 queries=3 proxy=44643
+ 20015ms peer now REFUSES
+ 30360ms ordinary onclose #1 -- the pool is about to call connection.connect(queued)
+ 30360ms sql.end() called from inside the scheduled window
+ 47459ms sql.end(): RESOLVED
RESULT build=POSTFIX accepts=7 ordinary_closes=2 window_settle_ms=17099 settled=resolved queries=["q0:connect ECONNREFUSED 127.0.0.1:44643","q1:connect ECONNREFUSED 127.0.0.1:44643"]

3. For the control, check out 0b306d8, re-run pnpm install --frozen-lockfile
   so the pre-fix(patch): settle and space a connect-phase socket death #222 patch is installed, and run the identical probe:

+ 20018ms ordinary onclose #1 -- the pool is about to call connection.connect(queued)
+ 20019ms sql.end() called from inside the scheduled window
+ 20061ms sql.end(): RESOLVED
RESULT build=PRE accepts=12263 ordinary_closes=3 window_settle_ms=43 settled=resolved queries=["q0:connect ECONNRESET 127.0.0.1:45149","q1:connect ECONNREFUSED 127.0.0.1:45149","q2:connect ECONNREFUSED 127.0.0.1:45149"]

The 120-second bound in the probe is an observation window so that it
terminates. It is not an assertion of a timing margin.

Environment / Context

• Node 24.17.0, Linux.
• postgres 3.4.9 with patches/postgres@3.4.9.patch applied, as installed by
  pnpm install --frozen-lockfile.
• The client is built with library defaults except max: 1. The window is
  reached at any pool size; a larger pool reaches the backoff cap sooner,
  because the retry counter the delay is computed from is shared across the
  pool.

Discovered During

Review of #222, the branch fixing #164. Surfaced by a scoped re-review of that
branch, measured by an adversary agent, and reproduced independently by the
session lead with the runs quoted above.

Suggested Fix

Unverified. In the package's src/connection.js, connect(query) is
initial = query; reconnect() and discards the handle reconnect() returns,
so the cancel gate #222 adds to end() — which tests retryTimer !== null —
never fires for a pool-driven reconnect.

Keeping the handle there is not on its own a fix, and that is the interesting
part of this issue. It would let end() cancel a query the pool has just
dispatched and never attempted, which every build serves today: the branch's own
boundary case in tests/db/connect-phase-death.test.ts exists to pin exactly
that, and the behaviour was verified by running all three builds rather than by
reading them. A fix therefore needs to distinguish a retry of an attempt that
already failed from the first attempt at freshly dispatched work, rather than
widening the gate.