From 4568f39bc0a3252097ef65a4b2345e1a815fd7da Mon Sep 17 00:00:00 2001 From: Oleg Komarov Date: Sun, 25 Oct 2026 21:55:39 +0000 Subject: [PATCH 1/4] test: run the tracing comparison on every pull request and pin request settling before the restructure (#73) The restructure of the pool and query side (#73) must not change behaviour, so this commit adds what holds it to that. Everything here passes on main. The tracing comparison against Postgres.js 3.4.9 (npm run test:tracing) was only ever run by hand, although dd-trace and Sentry rewrite and wrap the driver by shape. It is now a job on every pull request, and a release waits for it. The harness gains COPY to stdout and from stdin, a query cancelled before it is sent and a query that fails to build. dd-trace ends a COPY span on the second resolve of the query, so a change that settles a query once would leave every COPY span open and nothing noticed. The guard tests assert what main does on real PostgreSQL, including paths that look wrong. A spy counts resolve and reject calls in one table: COPY in and out resolve twice, sql`begin` on a pool resolves after rejecting with UNSAFE_TRANSACTION, a query cancelled before it is awaited rejects once at max: 2 and three times at max: 1 (the refused statement is written and its reply trips BindComplete on the unbuilt statement), and a query cancelled in the queue of a reserved connection or of a transaction rejects three times. A query cancelled before it is awaited is still routed: never built, the pool keeps working, an idle connection is filed busy and a connection that was still closed opens idle. A reservation queued behind plain queries gets the connection after them, close() during the first query's connection start runs that query and lets the next one reopen, and two paths that stay raw are pinned with a thrown string: a cursor callback that throws, and queries rejected after a failed reconnect while the pool is ending. --- .github/workflows/test.yml | 17 ++- tests-startup/run.js | 2 +- tests-startup/startup.js | 23 +++-- tests-tracing/harness.mjs | 21 +++- tests/index.js | 205 +++++++++++++++++++++++++++++++++++++ 5 files changed, 258 insertions(+), 10 deletions(-) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 9f64475a..c4f54724 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -100,6 +100,21 @@ jobs: WORKERD_TLS_PORT: 55433 WORKERD_TLS_CA: ${{ runner.temp }}/server.crt + tracing: + name: Tracing integrations (dd-trace, Sentry) + runs-on: ubuntu-24.04 + timeout-minutes: 15 + steps: + - uses: actions/checkout@11d5960a326750d5838078e36cf38b85af677262 + - uses: ./.github/actions/setup-postgres + with: + version: '18' + - uses: actions/setup-node@49933ea5288caeca8642d1e84afbd3f7d6820020 + with: + node-version: '24' + - run: echo /usr/lib/postgresql/18/bin >> "$GITHUB_PATH" + - run: npm run test:tracing + lint: name: Lint runs-on: ubuntu-24.04 @@ -117,7 +132,7 @@ jobs: publish: name: Stage on npm if: startsWith(github.ref, 'refs/tags/v') - needs: [node, deno, cloudflare, lint] + needs: [node, deno, cloudflare, lint, tracing] runs-on: ubuntu-24.04 timeout-minutes: 45 environment: npm diff --git a/tests-startup/run.js b/tests-startup/run.js index a64a9742..08e0ce84 100644 --- a/tests-startup/run.js +++ b/tests-startup/run.js @@ -35,7 +35,7 @@ const phaseNames = ['stale-ending-lifetime', 'stale-ending-close', 'stale-ending 'cancel-pipelined', 'cancel-pipelined-lost', 'cancel-settled', 'cancel-request-tls-error', 'cancel-request-refused', 'cancel-unawaited', 'cancel-query-unawaited', 'first-query-pipeline', 'release-inflight', 'draining-release-busy', 'factory-undefined', 'factory-empty', - 'ending-queued-reconnect', 'ending-queued-down', 'ending-other-open', 'error-close-reconnect', + 'ending-queued-reconnect', 'ending-queued-down', 'ending-queued-down-string', 'ending-other-open', 'error-close-reconnect', 'fatal-catalog', 'end-queued-cold', 'delay-clamp', 'idle-clamp', 'idle-throw', 'closing-bounded', 'closing-clean', 'closing-no-error', 'handout-idle', 'handout-lifetime', diff --git a/tests-startup/startup.js b/tests-startup/startup.js index 8ef4e759..b58cd070 100644 --- a/tests-startup/startup.js +++ b/tests-startup/startup.js @@ -410,7 +410,7 @@ export async function phases(name, postgres, onEvent) { const base = { host: '127.0.0.1', user: 'fixture', database: 'fixture', ssl: false, max: 1, fetch_types: true, onnotice: () => { /* Quiet. */ } } const hang = ['forced-queued', 'cancel-errors', 'gap-query', 'gap-query-pool', 'stale-ending-lifetime', 'stale-ending-close', 'stale-ending-rst', 'fin-inflight', 'rst-inflight', 'begin-socket-cause', - 'cancel-request-refused', 'cancel-unawaited', 'ending-queued-reconnect', 'ending-queued-down', + 'cancel-request-refused', 'cancel-unawaited', 'ending-queued-reconnect', 'ending-queued-down', 'ending-queued-down-string', 'ending-other-open', 'terminate-ready', 'terminate-draining', 'terminate-pipeline'].includes(name) const cause = name.startsWith('cause-') ? name.split('-')[2] : '' const holding = ['reserve-end', 'cancel-initial', 'cancel-initial-untyped', 'failover-timeout', @@ -944,27 +944,36 @@ export async function phases(name, postgres, onEvent) { } assert.deepStrictEqual(unhandled, []) await sql.end({ timeout: 0 }) - } else if (name === 'ending-queued-reconnect' || name === 'ending-queued-down') { + } else if (name === 'ending-queued-reconnect' || name.startsWith('ending-queued-down')) { let calls = 0 - const down = name === 'ending-queued-down' + const down = name.startsWith('ending-queued-down') + const thrown = name.endsWith('-string') ? 'factory denied' : new Error('factory denied') const options = { connect_timeout: 2, max_pipeline: 0 } if (down) { const factory = tracked(server) options.socket = () => { if (calls++) - throw new Error('factory denied') + throw thrown return factory.socket() } } const sql = make(options) const hung = settle(sql.unsafe('select hang', [], { simple: true })) await until(() => server.events.some(x => x.sql === 'select hang')) - const queued = [1, 2, 3].map(x => settle(sql.unsafe('select ' + x, [], { simple: true }).execute())) + const queries = [1, 2, 3].map(x => sql.unsafe('select ' + x, [], { simple: true }).execute()) + const queued = queries.map(x => settle(x)) + const raw = queries.map(x => x.then(() => 'resolved', error => error)) const ending = settle(sql.end()) server.reset() assert.strictEqual(await hung, 'rejected:ECONNRESET') - const expected = down ? 'rejected:factory denied' : 'resolved' - assert.deepStrictEqual(await Promise.all(queued), [expected, expected, expected]) + if (typeof thrown === 'string') { + const [opener, ...rest] = await Promise.all(raw) + assert(opener instanceof Error && opener.message === thrown) + assert.deepStrictEqual(rest, [thrown, thrown]) + } else { + const expected = down ? 'rejected:factory denied' : 'resolved' + assert.deepStrictEqual(await Promise.all(queued), [expected, expected, expected]) + } assert.strictEqual(await ending, 'resolved') if (down) { assert.strictEqual(calls, 2) diff --git a/tests-tracing/harness.mjs b/tests-tracing/harness.mjs index 9ac9ac49..5cff7ebc 100644 --- a/tests-tracing/harness.mjs +++ b/tests-tracing/harness.mjs @@ -23,7 +23,26 @@ export const scenarios = { await tx`select 1 as x` throw new Error('rollback') }).catch(() => {}), - savepoint: sql => sql.begin(tx => tx.savepoint(sp => sp`select 1 as x`)) + savepoint: sql => sql.begin(tx => tx.savepoint(sp => sp`select 1 as x`)), + copyOut: async sql => { + const readable = await sql`copy (select generate_series(1, 3)) to stdout`.readable() + await new Promise((resolve, reject) => readable.on('data', () => {}).on('end', resolve).on('error', reject)) + }, + copyIn: async sql => { + await sql`drop table if exists tracing_copy` + await sql`create table tracing_copy (x int)` + const writable = await sql`copy tracing_copy from stdin`.writable() + writable.write('1\n') + writable.end('2\n') + await new Promise((resolve, reject) => writable.on('finish', resolve).on('error', reject)) + await sql`drop table tracing_copy` + }, + cancelBeforeSend: async sql => { + const query = sql`select 1 as x` + await query.cancel() + await query.catch(() => {}) + }, + buildFailure: sql => sql`select ${ sql.json(1n) } as x`.catch(() => {}) } export async function tracer(mode, events) { diff --git a/tests/index.js b/tests/index.js index 26767ad4..f525f5ae 100644 --- a/tests/index.js +++ b/tests/index.js @@ -5828,3 +5828,208 @@ for (const [name, thrown] of unextensibleThrows) { ] }) } + +const pinned = { + copyOut: { resolve: 2, reject: 0 }, + copyIn: { resolve: 2, reject: 0 }, + unsafeTransaction: { resolve: 1, reject: 1 }, + cancelledBeforeAwaitedAtMax1: { resolve: 0, reject: 3 }, + cancelledBeforeAwaitedAtMax2: { resolve: 0, reject: 1 }, + cancelledInReservedQueue: { resolve: 0, reject: 3 }, + cancelledInTransactionQueue: { resolve: 0, reject: 3 } +} + +function counted(query) { + const calls = { resolve: 0, reject: 0 } + const { resolve, reject } = query + query.resolve = x => (calls.resolve++, resolve(x)) + query.reject = x => (calls.reject++, reject(x)) + return calls +} + +t('a copy to stdout resolves its query twice, with the stream and then with the result', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 1 }) + const query = sql`copy (select generate_series(1, 10)) to stdout` + const calls = counted(query) + const readable = await query.readable() + let lines = 0 + for await (const chunk of readable) + lines += chunk.toString().split('\n').length - 1 + await sql`select 1` + await sql.end() + + return [ + JSON.stringify([10, pinned.copyOut]), + JSON.stringify([lines, calls]) + ] +}) + +t('a copy from stdin resolves its query twice, with the stream and then with the result', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 1 }) + await sql`create table test (x int)` + const query = sql`copy test from stdin` + const calls = counted(query) + const writable = await query.writable() + const handedOut = { ...calls } + const finished = new Promise(r => writable.on('finish', r)) + writable.end('1\n2\n') + await finished + const rows = (await sql`select count(*)::int as n from test`)[0].n + await sql`drop table test` + await sql.end() + + return [ + JSON.stringify([{ resolve: 1, reject: 0 }, 2, pinned.copyIn]), + JSON.stringify([handedOut, rows, calls]) + ] +}) + +t('a transaction started with sql`begin` on a pool rejects with UNSAFE_TRANSACTION after its command completed', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 2, fetch_types: false }) + const query = sql`begin` + const calls = counted(query) + const error = await query.catch(e => e) + await sql.end() + + return [ + JSON.stringify(['UNSAFE_TRANSACTION', pinned.unsafeTransaction]), + JSON.stringify([error.code, calls]) + ] +}) + +t('a query cancelled before it is awaited is never built and the pool keeps working with max: 1', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 1 }) + await sql`select 1` + const query = sql`select 2 as x` + const calls = counted(query) + await query.cancel() + const error = await query.catch(e => e) + const next = (await sql`select 3 as x`)[0].x + await sql.end() + + return [ + JSON.stringify(['57014', undefined, pinned.cancelledBeforeAwaitedAtMax1, 3]), + JSON.stringify([error.code, query.string, calls, next]) + ] +}) + +t('a query cancelled before it is awaited is never built and files an idle connection busy with max: 2 warm', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 2 }) + await sql`select 1` + const query = sql`select 2 as x` + const calls = counted(query) + await query.cancel() + const error = await query.catch(e => e) + await new Promise(setImmediate) + const stats = sql.stats() + const next = (await sql`select 3 as x`)[0].x + await sql.end() + + return [ + JSON.stringify(['57014', undefined, pinned.cancelledBeforeAwaitedAtMax2, { busyCount: 1, idleCount: 0 }, 3]), + JSON.stringify([error.code, query.string, calls, { busyCount: stats.busyCount, idleCount: stats.idleCount }, next]) + ] +}) + +t('a query cancelled before it is awaited is never built and opens its connection idle with max: 2 cold', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 2 }) + const query = sql`select 2 as x` + const calls = counted(query) + await query.cancel() + const error = await query.catch(e => e) + await until(() => sql.stats().connectingCount === 0) + const stats = sql.stats() + const next = (await sql`select 3 as x`)[0].x + await sql.end() + + return [ + JSON.stringify(['57014', undefined, pinned.cancelledBeforeAwaitedAtMax2, { busyCount: 0, idleCount: 1 }, 3]), + JSON.stringify([error.code, query.string, calls, { busyCount: stats.busyCount, idleCount: stats.idleCount }, next]) + ] +}) + +t('a reservation queued behind plain queries on a connection that is opening gets it after them', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 1 }) + const order = [] + const first = sql`select 1 as x`.then(() => order.push('first')) + const second = sql`select 2 as x`.then(() => order.push('second')) + await 1 + const reserved = await sql.reserve() + const held = sql.stats().reservedCount + const third = await reserved`select 3 as x`.then(x => (order.push('reserved'), x[0].x)) + await Promise.all([first, second]) + reserved.release() + const after = (await sql`select 4 as x`)[0].x + await sql.end() + + return [ + JSON.stringify([['first', 'second', 'reserved'], 1, 3, 4]), + JSON.stringify([order, held, third, after]) + ] +}) + +t('a pool closed while its first query is connecting runs that query and reopens for the next one', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 1 }) + const first = sql`select 1 as x`.execute() + await 1 + const closing = sql.close() + const ran = (await first)[0].x + await closing + const next = (await sql`select 2 as x`)[0].x + await sql.end() + + return [ + JSON.stringify([1, 2]), + JSON.stringify([ran, next]) + ] +}) + +t('a query cancelled in the queue of a reserved connection settles once', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 1, max_pipeline: 0 }) + const reserved = await sql.reserve() + const running = reserved`select pg_sleep(0.1)`.execute() + const doomed = reserved`select 2 as x` + const calls = counted(doomed) + doomed.execute() + await new Promise(setImmediate) + await doomed.cancel() + const code = await doomed.then(() => 'resolved', e => e.code) + await running + const next = (await reserved`select 3 as x`)[0].x + reserved.release() + await sql.end() + + return [ + JSON.stringify([pinned.cancelledInReservedQueue, '57014', 3]), + JSON.stringify([calls, code, next]) + ] +}) + +t('a query cancelled in the queue of a transaction settles once', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 1, max_pipeline: 0 }) + let calls + const code = await sql.begin(async tx => { + const running = tx`select pg_sleep(0.1)`.execute() + const doomed = tx`select 2 as x` + calls = counted(doomed) + doomed.execute() + await new Promise(setImmediate) + await doomed.cancel() + await running + }).then(() => 'resolved', e => e.code) + await sql.end() + + return [ + JSON.stringify([pinned.cancelledInTransactionQueue, '57014']), + JSON.stringify([calls, code]) + ] +}) + +t('a cursor whose callback throws a string rejects with that string', async() => { + const sql = postgres({ ...options, max: 1 }) + const thrown = 'boom' + const rejected = await sql`select generate_series(1, 3) as x`.cursor(1, () => { throw thrown }).then(() => 'resolved', e => e) + await sql.end() + + return [thrown, rejected] +}) From 50cd3794e578e6bdd694073ca37f95d2514e0989 Mon Sep 17 00:00:00 2001 From: Oleg Komarov Date: Sun, 25 Oct 2026 21:55:57 +0000 Subject: [PATCH 2/4] refactor: give every request one lifecycle, one router and one settle path (#73) Native tracing channels need single places to hook: where a request starts, where it is routed, where it gets a connection, where it becomes active and where it settles. The pool and query side had none. A query was resolved or rejected from some thirty places, several running twice for the same query, the routing decision was written twice (handler and lease) with small differences, and the connection placed a query in two places. This restructures that with no change in what the driver does, except for the one difference below. A request, a Query or a lease, carries a stage (New, Queued, Opening, Sent, Active, Settled) and is moved by step, succeed and fail in query.js. A request settles once: later calls do nothing. fail only settles; queryError still decorates the error and wraps a thrown non-object exactly as on main, so errors the pool raises or a cursor callback throws stay raw. The COPY hand-out stays a direct resolve of the stream (deliver) because dd-trace ends a COPY span on the second resolve. The four resolve and reject arrows are untouched. handler and lease commit after route, which takes a connection, starts an acquisition or queues the request and returns the connection, null or the refusal, but never settles or executes anything. assign is the one place a pool request gets a connection, for queries and leases alike. A lease is created first with the request shape and is its own waiter in the pool queue, so the waiter object and its closure are gone. The connection places queries in one activate function, and an ending connection's opener now goes through onopen like every other opener, with an explicit argument saying the connection is draining. The three function handler declarations and the other shapes dd-trace rewrites are unchanged. The one deliberate difference: resolve and reject run once per query (twice for COPY) instead of twice on some paths. Only code that wraps them sees it. The pinned counts that change: - sql`begin` on a pool rejected with UNSAFE_TRANSACTION and then resolved: one resolve and one reject become one reject. - A query cancelled before it is awaited at max: 1 rejected three times, from the cancel, from BindComplete reading the statement of a query that was never built and from ReadyForQuery. It rejects once. - A query cancelled in the queue of a reserved connection rejects once instead of three times, and so does one cancelled in the queue of a transaction. BindComplete now returns early for a query without a statement, which removes the TypeError that went through protocolError for a refused statement. The tracing comparison no longer runs the Sentry variant that widened Sentry's postgres range. Sentry's range never covers 4.x, so that variant emulated a setup no user has and made Sentry's wrapping of handle, Connection, execute and connect look like constraints on this code. The sentry-auto and sentry-manual runs stay, and dd-trace's range has no upper bound, so its runs and shape constraints are unchanged. The test checker follows the request stages: request edges, every routed request and lease settling, one hand-over per request and fresh exactly for the opener. New tests pin one call for describe, cursors, forEach, simple, unsafe and file queries, pipelined, reserved and retried queries, build failures and a destroyed pool, and the requests scenarios assert each route's stage sequence and hand-over. --- src/connection.js | 58 +++++----- src/index.js | 134 +++++++++++++++-------- src/query.js | 35 +++++- tests-startup/case.js | 36 ++++--- tests-startup/invariants.js | 40 +++++++ tests-startup/requests.js | 130 ++++++++++++++++++++++ tests-startup/run.js | 5 +- tests-startup/startup.js | 1 + tests-tracing/run.js | 7 +- tests-tracing/sentry-range.mjs | 6 -- tests/index.js | 191 +++++++++++++++++++++++++++++++-- 11 files changed, 536 insertions(+), 107 deletions(-) create mode 100644 tests-startup/requests.js delete mode 100644 tests-tracing/sentry-range.mjs diff --git a/src/connection.js b/src/connection.js index 121c7bea..081a3161 100644 --- a/src/connection.js +++ b/src/connection.js @@ -10,7 +10,7 @@ import Result from './result.js' import Queue from './queue.js' import clampedTimeout from './timeout.js' import { SSLRequest, tlsConfig, cancelRequest } from './transport.js' -import { Query, CLOSE } from './query.js' +import { Query, CLOSE, Stage, step, succeed, fail } from './query.js' import b from './bytes.js' export { Connection } @@ -245,7 +245,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose get accepting() { return accepting() }, get copying() { return stream !== null }, get copyHeld() { return stream !== null && !stream.writableEnded }, - get acquiring() { return acquisition && !acquisition.owner.cancelled ? 1 : 0 }, + get acquiring() { return acquisition && acquisition.owner.stage !== Stage.Settled ? 1 : 0 }, count: 0, id } @@ -524,13 +524,13 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose lifeTimer.start() if (ending) { - if (owner.cancelled) + if (owner.stage === Stage.Settled) return closing() transition(Phase.Draining) - return execute(owner) + return onopen(connection, owner, true) } - onopen(connection, owner.cancelled ? undefined : owner) + onopen(connection, owner.stage === Stage.Settled ? undefined : owner) } function execute(q) { @@ -551,8 +551,8 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose try { q.state = backend query - ? sent.push(q) - : (query = q, query.active = true) + ? (step(q, Stage.Sent), sent.push(q)) + : activate(q) if (q.cancelled) { q.cancelled = null @@ -720,7 +720,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose function queryError(query, err) { if (query.reserve) - return query.reject(err) + return fail(query, err) if (!err || typeof err !== 'object') err = new Error(typeof err === 'symbol' ? String(err) : err) @@ -732,7 +732,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose args: { value: query.args, enumerable: options.debug }, types: { value: query.statement && query.statement.types, enumerable: options.debug } }).forEach(([key, descriptor]) => Reflect.defineProperty(err, key, descriptor)) - query.reject(err) + fail(query, err) } function endAcquisition(err) { @@ -837,7 +837,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose : errored(errorResponse) } else { query.initialization && query.initialization(results || result) - query.resolve(results || result) + succeed(query, results || result) } } else if (errorResponse) { errored(errorResponse) @@ -851,13 +851,16 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose } function pipelined() { - query = sent.length ? sent.shift() : null - if (query) { - query.active = true - query.cancelled && cancelRequest(options, query.state).then(query.cancelled.resolve, query.cancelled.reject) - } + query = null + return sent.length ? activate(sent.shift()) : null + } - return query + function activate(q) { + query = q + step(q, Stage.Active) + q.active = true + q.cancelled && q.cancelled.resolve && cancelRequest(options, q.state).then(q.cancelled.resolve, q.cancelled.reject) + return q } function initialized() { @@ -907,6 +910,9 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose } function BindComplete() { + if (!query.statement) + return + !result.statement && (result.statement = query.statement) result.columns = query.statement.columns } @@ -955,7 +961,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose result.statement = query.statement if (query.onlyDescribe) - return (query.resolve(query.statement), write(Sync)) + return (succeed(query, query.statement), write(Sync)) } function Authentication(x, type = x.readUInt32BE(5)) { @@ -1049,7 +1055,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose result.statement = query.statement result.statement.columns = [] if (query.onlyDescribe) - return (query.resolve(query.statement), write(Sync)) + return (succeed(query, query.statement), write(Sync)) } function BackendKeyData(x) { @@ -1140,13 +1146,13 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose : (result = new Result(), write(Execute('', current.cursorRows))) } catch (err) { query === current && socket === source && write(Sync) - current.reject(err) + fail(current, err) } } function CloseComplete() { result.count && query.cursorFn(result) - query.resolve(result) + succeed(query, result) } function CopyInResponse() { @@ -1166,16 +1172,14 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose stream = null } }) - query.resolve(stream) - connection.owner && connection.owner.next() + deliver(query, stream) } function CopyOutResponse() { stream = new Stream.Readable({ read() { copyPaused = false; socket.resume() } }) - query.resolve(stream) - connection.owner && connection.owner.next() + deliver(query, stream) } /* c8 ignore next 3 */ @@ -1197,7 +1201,11 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose final = callback } }) - query.resolve(stream) + deliver(query, stream) + } + + function deliver(q, value) { + q.resolve(value) connection.owner && connection.owner.next() } diff --git a/src/index.js b/src/index.js index db93ccaa..def166db 100644 --- a/src/index.js +++ b/src/index.js @@ -23,13 +23,15 @@ import { import { Connection, defaultBackoff } from './connection.js' import { cancelRequest } from './transport.js' import clampedTimeout from './timeout.js' -import { Query, CLOSE } from './query.js' +import { Query, CLOSE, Stage, step, succeed, fail } from './query.js' import Queue from './queue.js' import { Errors, PostgresError, callback } from './errors.js' import Subscribe from './subscribe.js' import largeObject from './large.js' +const check = globalThis[Symbol.for('postgres.js:check')] const Lease = { Active: 0, Settling: 1, Released: 2, Ended: 3, Closed: 4 } +const noop = () => { /* noop */ } Object.assign(Postgres, { PostgresError, @@ -140,7 +142,7 @@ function Postgres(a, b) { const query = new Query([], args, (query) => { fs.readFile(path, 'utf8', (err, string) => { if (err) - return query.reject(err) + return fail(query, err) query.strings = [string] handler(query) @@ -261,23 +263,36 @@ function Postgres(a, b) { } async function lease(auto) { + const l = newLease(auto) + check && check('routed', l) + const c = route(l) + if (c && !(c instanceof Error)) + return (assign(c, l, false), l) + if (ending) - throw Errors.connection('CONNECTION_ENDED', options) + throw (fail(l, c), c) - const l = { state: null, connection: null, error: null, onclose: null, queue: Queue() } - const idle = takeOpen() - idle - ? own(idle, l) - : auto && !closed.length && busy.length - ? own(busy.shift(), l) - : await new Promise((resolve, reject) => { - const query = { reserve: c => resolve(own(c, l)), reject } - closed.length - ? connect(closed.shift(), query) - : allHeldByCopy() - ? reject(copyInProgress()) - : queries.push(query) - }) + await new Promise((resolve, reject) => { + l.resolve = resolve + l.reject = reject + c && fail(l, c) + }) + return l + } + + function newLease(auto) { + const l = { + stage: Stage.New, + state: null, + connection: null, + error: null, + onclose: null, + queue: Queue(), + auto, + resolve: noop, + reject: noop, + reserve: true + } return l } @@ -300,8 +315,8 @@ function Postgres(a, b) { l.state === expected ? c.copying || (c.queue !== full && c.accepting) ? c.execute(q) || move(c, full) - : (move(c, full), q.queue = l.queue, l.queue.push(q)) - : q.reject(leaseError(l)) + : (move(c, full), step(q, Stage.Queued), q.queue = l.queue, l.queue.push(q)) + : fail(q, leaseError(l)) } function leaseError(l) { @@ -318,7 +333,7 @@ function Postgres(a, b) { l.state = state while (l.queue.length) - l.queue.shift().reject(leaseError(l)) + fail(l.queue.shift(), leaseError(l)) const c = l.connection if (c.owner !== l) @@ -476,22 +491,48 @@ function Postgres(a, b) { } function handler(query) { + const c = route(query) + if (c === null) + return + + c instanceof Error + ? fail(query, c) + : go(c, query) + } + + function route(r) { if (ending) - return query.reject(Errors.connection('CONNECTION_ENDED', options, options)) + return Errors.connection('CONNECTION_ENDED', options, options) const idle = takeOpen() if (idle) - return go(idle, query) + return idle + + if (r.reserve && r.auto && !closed.length && busy.length) + return busy.shift() if (closed.length) - return connect(closed.shift(), query) + return (connect(closed.shift(), r), null) + + const c = r.reserve ? null : takeBusy() + if (c) + return c + + if (allHeldByCopy()) + return copyInProgress() + + step(r, Stage.Queued) + queries.push(r) + return null + } + + function assign(c, r, fresh) { + check && check('handover', r, fresh, c.active + c.pipelined) + if (!r.reserve) + return c.execute(r) - const c = takeBusy() - c - ? go(c, query) - : allHeldByCopy() - ? query.reject(copyInProgress()) - : queries.push(query) + own(c, r) + succeed(r, r) } function allHeldByCopy() { @@ -527,7 +568,7 @@ function Postgres(a, b) { } function go(c, query) { - return c.execute(query) + return assign(c, query, false) ? move(c, busy) : move(c, full) } @@ -542,7 +583,7 @@ function Postgres(a, b) { } else { query.queue || options.max === 1 || queries.remove(query) query.cancelled = true - query.reject(Errors.generic('57014', 'canceling statement due to user request')) + fail(query, Errors.generic('57014', 'canceling statement due to user request')) resolve() } }) @@ -560,7 +601,7 @@ function Postgres(a, b) { ])).then(() => { clearTimeout(timer) while (queries.length) - queries.shift().reject(Errors.connection('CONNECTION_CLOSED', options)) + fail(queries.shift(), Errors.connection('CONNECTION_CLOSED', options)) }) } @@ -579,14 +620,15 @@ function Postgres(a, b) { async function destroy(resolve) { while (queries.length) - queries.shift().reject(Errors.connection('CONNECTION_DESTROYED', options)) + fail(queries.shift(), Errors.connection('CONNECTION_DESTROYED', options)) await Promise.all(connections.map(c => c.terminate())) resolve() } - function connect(c, query) { + function connect(c, r) { + step(r, Stage.Opening) move(c, connecting) - c.connect(query) + c.connect(r) return c } @@ -594,9 +636,9 @@ function Postgres(a, b) { move(c, ended) } - function onopen(c, initial) { - if (initial && initial.reserve) - return initial.reserve(c) + function onopen(c, initial, draining) { + if (draining || initial && initial.reserve) + return assign(c, initial, true) if (!initial && !c.accepting) return move(c, full) @@ -605,14 +647,14 @@ function Postgres(a, b) { return move(c, open) let max = Math.ceil(queries.length / (connecting.length + 1)) - , ready = !initial || c.execute(initial) + , ready = !initial || assign(c, initial, true) while (ready && queries.length && max-- > 0) { const query = queries.shift() if (query.reserve) - return query.reserve(c) + return assign(c, query, false) - ready = c.execute(query) + ready = assign(c, query, false) } ready @@ -629,8 +671,8 @@ function Postgres(a, b) { while (ready && queries.length) { const query = queries.shift() query.reserve - ? query.reject(Errors.connection('CONNECTION_ENDED', options)) - : (drained = true, ready = c.execute(query)) + ? fail(query, Errors.connection('CONNECTION_ENDED', options)) + : (drained = true, ready = assign(c, query, false)) } drained && move(c, ended) return drained @@ -644,7 +686,7 @@ function Postgres(a, b) { l.error = e || Errors.connection('CONNECTION_CLOSED', options) c.owner = null while (l.queue.length) - l.queue.shift().reject(Errors.connection('CONNECTION_CLOSED', options)) + fail(l.queue.shift(), Errors.connection('CONNECTION_CLOSED', options)) l.onclose && l.onclose(l.error) } @@ -664,9 +706,9 @@ function Postgres(a, b) { while (queries.length) { const query = queries.shift() if (query.reserve) { - query.reject(Errors.connection('CONNECTION_ENDED', options)) + fail(query, Errors.connection('CONNECTION_ENDED', options)) } else if (reconnectFailed) { - query.reject(e === undefined ? Errors.connection('CONNECTION_CLOSED', options) : e) + fail(query, e === undefined ? Errors.connection('CONNECTION_CLOSED', options) : e) } else { reconnecting = c connect(c, query) diff --git a/src/query.js b/src/query.js index c1777a90..ccaa9137 100644 --- a/src/query.js +++ b/src/query.js @@ -3,6 +3,38 @@ const originCache = new Map() , originError = Symbol('OriginError') export const CLOSE = {} +export const Stage = { New: 0, Queued: 1, Opening: 2, Sent: 3, Active: 4, Settled: 5 } + +const check = globalThis[Symbol.for('postgres.js:check')] +const stageNames = Object.keys(Stage) + +export function step(r, next) { + const from = r.stage + if (from === Stage.Settled) + return + + check && check('step', r, stageNames[from], stageNames[next]) + r.stage = next +} + +export function succeed(r, value) { + if (r.stage === Stage.Settled) + return + + check && check('requestSettled', r, stageNames[r.stage]) + r.stage = Stage.Settled + r.resolve(value) +} + +export function fail(r, error) { + if (r.stage === Stage.Settled) + return + + check && check('requestSettled', r, stageNames[r.stage]) + r.stage = Stage.Settled + r.reject(error) +} + export class Query extends Promise { constructor(strings, args, handler, canceller, options = {}) { let resolve @@ -22,6 +54,7 @@ export class Query extends Promise { this.state = null this.statement = null + this.stage = Stage.New // dd-trace's load-time rewrite only accepts single-expression arrows here this.resolve = x => (this.active = false, this.settled = true, resolve(x)) @@ -146,7 +179,7 @@ export class Query extends Promise { } async handle() { - !this.executed && (this.executed = true) && await 1 && this.handler(this) + !this.executed && (this.executed = true) && await 1 && (check && check('routed', this), this.handler(this)) } execute() { diff --git a/tests-startup/case.js b/tests-startup/case.js index 6f838f2b..44034571 100644 --- a/tests-startup/case.js +++ b/tests-startup/case.js @@ -9,13 +9,18 @@ import { parameters } from './parameters.js' import { compat } from './compat.js' import { cf } from './cf.js' import { copy } from './copy.js' +import { requests } from './requests.js' import { install, verify, violations } from './invariants.js' import { bounded, quiet } from './bounded.js' install() const name = process.argv[2] -const finish = () => (verify(), process.send({ completed: name })) +const finish = async() => { + await new Promise(setImmediate) + verify() + process.send({ completed: name }) +} async function main() { const { default: postgres } = await import(process.argv[3] === 'cjs' ? '../cjs/src/index.js' : '../src/index.js') @@ -42,7 +47,7 @@ async function main() { frames(type => combined.push(type))(input) assert.deepStrictEqual(combined, ['Q', 'Z']) assert.throws(() => frames(() => { /* Invalid lengths must fail before callback. */ })(Buffer.from([81, 0, 0, 0, 3])), /Invalid protocol/) - finish() + await finish() return } if (name.startsWith('startup:')) { @@ -52,52 +57,57 @@ async function main() { || scenario.startsWith('backoff-') ? lifecycle : startup await run(scenario, postgres, event => process.send({ event })) - finish() + await finish() return } if (name.startsWith('phase:')) { await phases(name.slice(6), postgres, event => process.send({ event })) - finish() + await finish() return } if (name === 'integration') { await integration(postgres) - finish() + await finish() return } if (name.startsWith('compat:')) { await compat(name.slice(7), postgres) - finish() + await finish() return } if (name.startsWith('copy:')) { await copy(name.slice(5), postgres) - finish() + await finish() return } if (name.startsWith('cf:')) { await cf(name.slice(3)) - finish() + await finish() return } if (name.startsWith('lease:')) { await leases(name.slice(6), postgres, event => process.send({ event })) - finish() + await finish() + return + } + if (name.startsWith('requests:')) { + await requests(name.slice(9), postgres, event => process.send({ event })) + await finish() return } if (name.startsWith('report:')) { await reports(name.slice(7), postgres) - finish() + await finish() return } if (name.startsWith('parameters:')) { await parameters(name.slice(11), postgres, event => process.send({ event })) - finish() + await finish() return } if (name.startsWith('ownership:')) { await ownership(name.slice(10), postgres, event => process.send({ event })) - finish() + await finish() return } const server = await peer({ catalogError: name === 'catalog-error', onEvent: event => process.send({ event }) }) @@ -125,7 +135,7 @@ async function main() { await quiet(server.close(), failed) process.send({ events: server.events }) } - finish() + await finish() } main().catch(error => { diff --git a/tests-startup/invariants.js b/tests-startup/invariants.js index 17718d97..987c41e4 100644 --- a/tests-startup/invariants.js +++ b/tests-startup/invariants.js @@ -20,8 +20,26 @@ const edges = { Closing: ['Closed'] } +const requestEdges = { + New: ['Queued', 'Opening', 'Sent', 'Active', 'Settled'], + Queued: ['Opening', 'Sent', 'Active', 'Settled'], + Opening: ['Sent', 'Active', 'Settled'], + Sent: ['Active', 'Settled'], + Active: ['Sent', 'Settled'] +} + export const violations = [] +const routed = new Set() +const handed = new Set() + +export const handovers = [] +export const seen = [] +export const history = new WeakMap() + +const visit = (request, stage) => (history.get(request) || history.set(request, ['New']).get(request)).push(stage) +const stages = ['New', 'Queued', 'Opening', 'Sent', 'Active', 'Settled'] + const connections = [] const phase = c => c[Symbol.for('postgres.js:phase')] const where = () => new Error().stack.split('\n').slice(4, 7).join(' <- ') @@ -38,6 +56,25 @@ export function install() { if (kind === 'created') return a.closed && connections.push([c, a]) + if (kind === 'routed') + return seen.push(c), stages[c.stage] === 'Settled' || routed.add(c) + + if (kind === 'requestSettled') { + routed.delete(c) + visit(c, 'Settled') + return requestEdges[a].includes('Settled') || violations.push('illegal request edge ' + a + ' -> Settled at ' + where()) + } + + if (kind === 'handover') { + handed.has(c) && violations.push('request handed over twice at ' + where()) + handed.add(c) + handovers.push({ request: c, fresh: a, behind: b }) + return (stages[c.stage] === 'Opening') === a || violations.push('hand-over fresh=' + a + ' for stage ' + c.stage + ' at ' + where()) + } + + if (kind === 'step') + return visit(c, b), requestEdges[a].includes(b) || violations.push('illegal request edge ' + a + ' -> ' + b + ' at ' + where()) + if (kind === 'unhandled') return violations.push('unhandled ' + b + ' in ' + a + ' at ' + where()) @@ -48,8 +85,11 @@ export function install() { } } +const describe = q => [(q.strings || []).join('?'), q.executed, !!q.state, !!q.queue, q.cancelled].join(' ') + export function verify() { connections.forEach(([c, queues]) => inspect(c, queues)) + routed.size && violations.push(routed.size + ' routed request(s) never settled: ' + [...routed].map(describe).join('; ')) if (violations.length) throw new Error('Invariant violated: ' + violations.join('; ')) } diff --git a/tests-startup/requests.js b/tests-startup/requests.js new file mode 100644 index 00000000..7411588d --- /dev/null +++ b/tests-startup/requests.js @@ -0,0 +1,130 @@ +import assert from 'assert' +import { peer } from './peer.js' +import { settle, until, startups } from './startup.js' +import { handovers, history, seen } from './invariants.js' + +export const requestNames = ['idle', 'opens', 'sent-ahead', 'drained-at-open', 'refused-ending', 'refused-copy', 'cancelled-queued', + 'lease-idle', 'lease-busy', 'lease-queued', 'lease-opens', 'lease-reconnect', 'close-opening'] + +const turn = () => new Promise(resolve => setImmediate(resolve)) +const select = (client, text = 'select 42 as marker') => client.unsafe(text, [], { simple: true }) +const lease = () => seen.find(x => x.reserve) +const visited = (request, stage) => (history.get(request) || []).includes(stage) + +function expectSeen(request, steps, handed) { + assert.deepStrictEqual(history.get(request), steps) + assert.deepStrictEqual(handovers.filter(x => x.request === request).map(x => [x.fresh, x.behind]), handed) +} + +export async function requests(name, postgres, onEvent) { + const closed = Promise.withResolvers() + const server = await peer({ holdStartup: ['drained-at-open', 'close-opening'].includes(name), onEvent }) + const sql = postgres({ host: '127.0.0.1', port: server.port, user: 'fixture', database: 'fixture', ssl: false, + max: 1, fetch_types: false, connect_timeout: 1, onclose: () => closed.resolve(), + ...(['cancelled-queued', 'lease-queued'].includes(name) ? { max_pipeline: 0 } : {}) }) + try { + if (name === 'idle') { + await select(sql) + const query = select(sql) + assert.strictEqual((await query)[0].marker, 42) + expectSeen(query, ['New', 'Active', 'Settled'], [[false, 0]]) + } else if (name === 'opens') { + const query = select(sql) + assert.strictEqual((await query)[0].marker, 42) + expectSeen(query, ['New', 'Opening', 'Active', 'Settled'], [[true, 0]]) + } else if (name === 'sent-ahead') { + server.hold('stall') + const running = settle(select(sql, 'select 1 -- stall')) + await until(() => server.heldStatement()) + const ahead = select(sql).execute() + await until(() => handovers.some(x => x.request === ahead)) + server.releaseStatement() + assert.strictEqual((await ahead)[0].marker, 42) + assert.strictEqual(await running, 'resolved') + expectSeen(ahead, ['New', 'Sent', 'Active', 'Settled'], [[false, 1]]) + } else if (name === 'drained-at-open') { + const first = select(sql).execute() + const second = select(sql).execute() + await until(() => startups(server) === 1) + server.releaseStartup() + assert.strictEqual((await first)[0].marker, 42) + assert.strictEqual((await second)[0].marker, 42) + expectSeen(first, ['New', 'Opening', 'Active', 'Settled'], [[true, 0]]) + expectSeen(second, ['New', 'Queued', 'Sent', 'Active', 'Settled'], [[false, 1]]) + } else if (name === 'refused-ending') { + await sql.end() + const query = select(sql) + assert.strictEqual(await settle(query), 'rejected:CONNECTION_ENDED') + expectSeen(query, ['New', 'Settled'], []) + } else if (name === 'refused-copy') { + const copy = await sql.unsafe('copy test from stdin').writable() + copy.on('error', () => undefined) + const query = select(sql) + assert.strictEqual(await settle(query), 'rejected:COPY_IN_PROGRESS') + expectSeen(query, ['New', 'Settled'], []) + } else if (name === 'cancelled-queued') { + server.hold('stall') + settle(select(sql, 'select 1 -- stall')) + await until(() => server.heldStatement()) + const query = select(sql).execute() + await until(() => visited(query, 'Queued')) + await query.cancel() + assert.strictEqual(await settle(query), 'rejected:57014') + expectSeen(query, ['New', 'Queued', 'Settled'], []) + } else if (name === 'lease-idle') { + await select(sql) + const reserved = await sql.reserve() + expectSeen(lease(), ['New', 'Settled'], [[false, 0]]) + reserved.release() + } else if (name === 'lease-busy') { + server.hold('stall') + const running = settle(select(sql, 'select 1 -- stall')) + await until(() => server.heldStatement()) + const transaction = sql.begin(async() => undefined) + await until(() => handovers.some(x => x.request.reserve)) + expectSeen(lease(), ['New', 'Settled'], [[false, 1]]) + server.releaseStatement() + await transaction + assert.strictEqual(await running, 'resolved') + } else if (name === 'lease-queued') { + server.hold('stall') + settle(select(sql, 'select 1 -- stall')) + await until(() => server.heldStatement()) + const reserving = sql.reserve() + await until(() => lease() && visited(lease(), 'Queued')) + server.releaseStatement() + const reserved = await reserving + expectSeen(lease(), ['New', 'Queued', 'Settled'], [[false, 0]]) + reserved.release() + } else if (name === 'lease-opens') { + const reserved = await sql.reserve() + expectSeen(lease(), ['New', 'Opening', 'Settled'], [[true, 0]]) + reserved.release() + } else if (name === 'lease-reconnect') { + await select(sql) + server.disconnect() + await closed.promise + const reserved = await sql.reserve() + expectSeen(lease(), ['New', 'Opening', 'Settled'], [[true, 0]]) + reserved.release() + } else { + assert.strictEqual(name, 'close-opening') + const first = select(sql).execute() + const second = select(sql).execute() + await until(() => startups(server) === 1) + const closing = sql.close() + await turn() + server.releaseStartup() + assert.strictEqual((await first)[0].marker, 42) + await until(() => startups(server) === 2) + server.releaseStartup() + assert.strictEqual((await second)[0].marker, 42) + await closing + assert.deepStrictEqual(handovers.map(x => [x.request === first, x.request === second, x.fresh, x.behind]), + [[true, false, true, 0], [false, true, true, 0]]) + } + } finally { + await sql.end({ timeout: 0 }) + await server.close() + } +} diff --git a/tests-startup/run.js b/tests-startup/run.js index 08e0ce84..2f9293d7 100644 --- a/tests-startup/run.js +++ b/tests-startup/run.js @@ -3,6 +3,7 @@ import assert from 'assert' import { fork } from 'child_process' import { fileURLToPath } from 'url' import { leaseNames } from './lease.js' +import { requestNames } from './requests.js' import { reportNames } from './reports.js' import { parameterNames } from './parameters.js' import { compatNames } from './compat.js' @@ -135,7 +136,7 @@ async function main() { } if (process.argv.includes('--regressions')) { for (const name of [...startupNames.map(x => 'startup:' + x), ...phaseNames.map(x => 'phase:' + x), ...leaseNames.map(x => 'lease:' + x), - ...parameterNames.map(x => 'parameters:' + x), + ...requestNames.map(x => 'requests:' + x), ...parameterNames.map(x => 'parameters:' + x), ...compatNames.map(x => 'compat:' + x), ...cfNames.map(x => 'cf:' + x), ...copyNames.map(x => 'copy:' + x)]) { const result = await run(name) console.log(JSON.stringify(result)) @@ -145,7 +146,7 @@ async function main() { } for (const name of ['frames', 'cold-query', 'cold-query-no-fetch', 'cold-reserve', 'cold-reserve-no-fetch', ...ownershipNames.map(x => 'ownership:' + x), ...startupNames.map(x => 'startup:' + x), - ...phaseNames.map(x => 'phase:' + x), ...leaseNames.map(x => 'lease:' + x), + ...phaseNames.map(x => 'phase:' + x), ...leaseNames.map(x => 'lease:' + x), ...requestNames.map(x => 'requests:' + x), ...parameterNames.map(x => 'parameters:' + x), ...compatNames.map(x => 'compat:' + x), ...cfNames.map(x => 'cf:' + x), ...copyNames.map(x => 'copy:' + x)]) { const result = await run(name) diff --git a/tests-startup/startup.js b/tests-startup/startup.js index b58cd070..3c028b97 100644 --- a/tests-startup/startup.js +++ b/tests-startup/startup.js @@ -523,6 +523,7 @@ export async function phases(name, postgres, onEvent) { await sleep(500) assert(calls - before < 20, 'Factory called ' + (calls - before) + ' times in 500 ms') await sql.end({ timeout: 0 }) + await until(() => sql.stats().listenCount === 0) } else if (name === 'fin-inflight' || name === 'rst-inflight') { const sql = make({ connect_timeout: 2 }) await marker(sql) diff --git a/tests-tracing/run.js b/tests-tracing/run.js index 77790943..d942348b 100644 --- a/tests-tracing/run.js +++ b/tests-tracing/run.js @@ -40,9 +40,6 @@ try { results[key(run, variant)] = execute(run, dir) } - for (const run of runs.filter(x => x.mode === 'sentry-auto')) - results[key(run, 'fork with sentry-range')] = execute({ ...run, flags: ['--import', './sentry-range.mjs', ...run.flags] }, variants.fork) - const differences = report(results) process.exitCode = differences ? 1 : 0 } finally { @@ -55,7 +52,7 @@ function install(name, spec) { mkdirSync(dir) writeFileSync(path.join(dir, 'package.json'), JSON.stringify({ private: true, dependencies: { postgres: spec, ...tracers } })) execFileSync('npm', ['install', '--ignore-scripts', '--no-audit', '--no-fund', '--no-package-lock', '--silent'], { cwd: dir, stdio: 'inherit' }) - for (const file of ['harness.mjs', 'entry.mjs', 'entry.cjs', 'sentry-range.mjs']) + for (const file of ['harness.mjs', 'entry.mjs', 'entry.cjs']) copyFileSync(path.join(here, file), path.join(dir, file)) return dir } @@ -166,8 +163,6 @@ function report(results) { function known(group, variant, scenario) { if (group.startsWith('sentry-auto') && variant === 'fork') return 'expected: Sentry instruments postgres <4 only' - if (group.startsWith('sentry-auto') && scenario === 'savepoint') - return 'savepoint names are sent inline, not as a parameter' if (group.startsWith('dd-dbm') && ['commit', 'rollback', 'savepoint'].includes(scenario)) return 'transaction control is sent unprepared, so dd-trace adds its SQL comment' } diff --git a/tests-tracing/sentry-range.mjs b/tests-tracing/sentry-range.mjs deleted file mode 100644 index 5075a78a..00000000 --- a/tests-tracing/sentry-range.mjs +++ /dev/null @@ -1,6 +0,0 @@ -import { SENTRY_RUNTIME_INSTRUMENTATIONS } from '@sentry/server-utils/orchestrion/config' - -for (const instrumentation of SENTRY_RUNTIME_INSTRUMENTATIONS) { - if (instrumentation.module.name === 'postgres') - instrumentation.module.versionRange = '>=3.0.0 <5' -} diff --git a/tests/index.js b/tests/index.js index f525f5ae..d70b2bbe 100644 --- a/tests/index.js +++ b/tests/index.js @@ -6,6 +6,7 @@ import fs from 'fs' import crypto from 'crypto' import postgres from '../src/index.js' +import { Stage } from '../src/query.js' import { vercelPool } from '../src/vercel.js' const delay = ms => new Promise(r => setTimeout(r, ms)) @@ -5832,11 +5833,26 @@ for (const [name, thrown] of unextensibleThrows) { const pinned = { copyOut: { resolve: 2, reject: 0 }, copyIn: { resolve: 2, reject: 0 }, - unsafeTransaction: { resolve: 1, reject: 1 }, - cancelledBeforeAwaitedAtMax1: { resolve: 0, reject: 3 }, + unsafeTransaction: { resolve: 0, reject: 1 }, + cancelledBeforeAwaitedAtMax1: { resolve: 0, reject: 1 }, cancelledBeforeAwaitedAtMax2: { resolve: 0, reject: 1 }, - cancelledInReservedQueue: { resolve: 0, reject: 3 }, - cancelledInTransactionQueue: { resolve: 0, reject: 3 } + describe: { resolve: 1, reject: 0 }, + cursorCallback: { resolve: 1, reject: 0 }, + cursorClosed: { resolve: 1, reject: 0 }, + cursorCallbackThrows: { resolve: 0, reject: 1 }, + cursorServerError: { resolve: 0, reject: 1 }, + forEach: { resolve: 1, reject: 0 }, + simple: { resolve: 1, reject: 0 }, + unsafe: { resolve: 1, reject: 0 }, + file: { resolve: 1, reject: 0 }, + pipelined: { resolve: 1, reject: 0 }, + reserved: { resolve: 1, reject: 0 }, + retried: { resolve: 1, reject: 0 }, + buildFailureIdle: { resolve: 0, reject: 1 }, + buildFailureBehind: { resolve: 0, reject: 1 }, + cancelledInReservedQueue: { resolve: 0, reject: 1 }, + cancelledInTransactionQueue: { resolve: 0, reject: 1 }, + poolEnding: { resolve: 0, reject: 1 } } function counted(query) { @@ -5984,6 +6000,133 @@ t('a pool closed while its first query is connecting runs that query and reopens ] }) +const settledOnce = async(name, make, run = q => q) => { + const sql = postgres({ ...options, max: 1 }) + const query = make(sql) + const calls = counted(query) + await run(query).then(() => 'resolved', e => e.code || e.message) + await sql`select 1` + await sql.end() + return [JSON.stringify(pinned[name]), JSON.stringify(calls)] +} + +t('a described query settles once', async() => + settledOnce('describe', sql => sql`select ${ 1 }::int as x`.describe()) +) + +t('a cursor with a callback settles once', async() => + settledOnce('cursorCallback', sql => sql`select generate_series(1, 3) as x`, q => q.cursor(2, noop)) +) + +t('a cursor with a callback that closes it settles once', async() => + settledOnce('cursorClosed', sql => sql`select generate_series(1, 3) as x`, q => q.cursor(1, () => sql.CLOSE)) +) + +t('a cursor whose callback throws settles once', async() => + settledOnce('cursorCallbackThrows', sql => sql`select generate_series(1, 3) as x`, q => q.cursor(1, () => { throw new Error('boom') })) +) + +t('a cursor whose callback throws a string rejects with that string', async() => { + const sql = postgres({ ...options, max: 1 }) + const thrown = 'boom' + const rejected = await sql`select generate_series(1, 3) as x`.cursor(1, () => { throw thrown }).then(() => 'resolved', e => e) + await sql.end() + + return [thrown, rejected] +}) + +t('a cursor that meets a server error settles once', async() => + settledOnce('cursorServerError', sql => sql`select 1 / (x - 2) as y from generate_series(1, 3) x`, q => q.cursor(1, noop)) +) + +t('forEach settles once', async() => + settledOnce('forEach', sql => sql`select generate_series(1, 3) as x`, q => q.forEach(noop)) +) + +t('a simple query settles once', async() => + settledOnce('simple', sql => sql`select 1 as x`.simple()) +) + +t('an unsafe query settles once', async() => + settledOnce('unsafe', sql => sql.unsafe('select $1::int as x', [1])) +) + +t('a query from a file settles once', async() => + settledOnce('file', sql => sql.file(rel('select.sql'))) +) + +t('pipelined queries each settle once', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 1 }) + const queries = [1, 2, 3].map(x => sql`select ${ x }::int as x`) + const calls = queries.map(counted) + await Promise.all(queries) + await sql.end() + + return [ + JSON.stringify(Array(3).fill(pinned.pipelined)), + JSON.stringify(calls) + ] +}) + +t('a query on a reserved connection settles once', async() => { + const sql = postgres({ ...options, max: 1 }) + const reserved = await sql.reserve() + const query = reserved`select 1 as x` + const calls = counted(query) + await query + reserved.release() + await sql.end() + + return [JSON.stringify(pinned.reserved), JSON.stringify(calls)] +}) + +t('a retried query settles once', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 1 }) + const run = () => sql`select ${ 1 }::int as x` + await run() + await sql`deallocate all` + const query = run() + const calls = counted(query) + const rows = await query + await sql.end() + + return [ + JSON.stringify([pinned.retried, 1]), + JSON.stringify([calls, rows[0].x]) + ] +}) + +t('a query that fails to build on an idle connection settles once', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 1 }) + await sql`select 1` + const query = sql.unsafe('select 1', Array(70000).fill(1)) + const calls = counted(query) + const code = await query.then(() => 'resolved', e => e.code) + const next = (await sql`select 2 as x`)[0].x + await sql.end() + + return [ + JSON.stringify([pinned.buildFailureIdle, 'MAX_PARAMETERS_EXCEEDED', 2]), + JSON.stringify([calls, code, next]) + ] +}) + +t('a query that fails to build behind a running query settles once', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 1 }) + await sql`select 1` + const running = sql`select 1 as x`.execute() + const query = sql.unsafe('select 1', Array(70000).fill(1)) + const calls = counted(query) + const code = await query.then(() => 'resolved', e => e.code) + const ran = (await running)[0].x + await sql.end() + + return [ + JSON.stringify([pinned.buildFailureBehind, 'MAX_PARAMETERS_EXCEEDED', 1]), + JSON.stringify([calls, code, ran]) + ] +}) + t('a query cancelled in the queue of a reserved connection settles once', { timeout: 10 }, async() => { const sql = postgres({ ...options, max: 1, max_pipeline: 0 }) const reserved = await sql.reserve() @@ -6025,11 +6168,43 @@ t('a query cancelled in the queue of a transaction settles once', { timeout: 10 ] }) -t('a cursor whose callback throws a string rejects with that string', async() => { +t('queries still waiting when the pool is destroyed settle once', { timeout: 10 }, async() => { + const sql = postgres({ ...options, max: 1, max_pipeline: 0 }) + const running = sql`select pg_sleep(0.1)` + const waiting = sql`select 2 as x` + const calls = [counted(running), counted(waiting)] + const outcomes = Promise.all([running, waiting].map(q => q.then(() => 'resolved', e => e.code))) + await new Promise(setImmediate) + await sql.end({ timeout: 0 }) + + return [ + JSON.stringify([[pinned.poolEnding, pinned.poolEnding], ['CONNECTION_DESTROYED', 'CONNECTION_DESTROYED']]), + JSON.stringify([calls, await outcomes]) + ] +}) + +t('a for await cursor is settled once its loop has ended', async() => { const sql = postgres({ ...options, max: 1 }) - const thrown = 'boom' - const rejected = await sql`select generate_series(1, 3) as x`.cursor(1, () => { throw thrown }).then(() => 'resolved', e => e) + const query = sql`select generate_series(1, 3) as x` + let batches = 0 + for await (const rows of query.cursor(2)) + batches += rows.length + const stage = query.stage await sql.end() - return [thrown, rejected] + return [JSON.stringify([Stage.Settled, 3]), JSON.stringify([stage, batches])] +}) + +t('a for await cursor is settled once its loop was left', async() => { + const sql = postgres({ ...options, max: 1 }) + const query = sql`select generate_series(1, 3) as x` + for await (const rows of query.cursor(1)) { + if (rows.length) + break + } + await sql`select 1` + const stage = query.stage + await sql.end() + + return [Stage.Settled, stage] }) From ef94b750d0c809d4e5b628f106aba4e7f434470c Mon Sep 17 00:00:00 2001 From: Oleg Komarov Date: Sun, 25 Oct 2026 21:56:01 +0000 Subject: [PATCH 3/4] docs: describe requests, the router and the request hooks in the lifecycle (#73) lifecycle.md gains a Requests section: the shape a query and a lease share, the stages and their transitions, the contract that route never settles a request and where aborts and timeouts of a waiting request belong, assign as the one hand-over, early settle while a query still holds its slot, COPY resolving twice through deliver, settled requests still being routed, and where errors are wrapped. The pool callbacks table describes onopen's draining argument, Cancel is described in stage terms, the Test hook section lists the routed, step, requestSettled and handover reports, and the open questions record the quirks that stay as they are. The diff since 3.4.9 is refreshed. --- docs/changes-since-3.4.9.diff | 487 +++++++++++++++++++++++----------- docs/lifecycle.md | 65 ++++- 2 files changed, 397 insertions(+), 155 deletions(-) diff --git a/docs/changes-since-3.4.9.diff b/docs/changes-since-3.4.9.diff index 3c8f9a75..4e75cfdd 100644 --- a/docs/changes-since-3.4.9.diff +++ b/docs/changes-since-3.4.9.diff @@ -1,5 +1,5 @@ diff --git a/src/connection.js b/src/connection.js -index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f47b7e2bf6 100644 +index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461dccdacf35 100644 --- a/src/connection.js +++ b/src/connection.js @@ -4,24 +4,41 @@ import crypto from 'crypto' @@ -12,9 +12,10 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 +import { Errors, callback } from './errors.js' import Result from './result.js' import Queue from './queue.js' +-import { Query, CLOSE } from './query.js' +import clampedTimeout from './timeout.js' +import { SSLRequest, tlsConfig, cancelRequest } from './transport.js' - import { Query, CLOSE } from './query.js' ++import { Query, CLOSE, Stage, step, succeed, fail } from './query.js' import b from './bytes.js' -export default Connection @@ -82,7 +83,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 , errorResponse = null , result = new Result() , incoming = Buffer.alloc(0) -@@ -86,82 +111,442 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -86,102 +111,478 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose , statements = {} , statementId = Math.random().toString(36).slice(2) , statementCount = 1 @@ -233,7 +234,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 + get accepting() { return accepting() }, + get copying() { return stream !== null }, + get copyHeld() { return stream !== null && !stream.writableEnded }, -+ get acquiring() { return acquisition && !acquisition.owner.cancelled ? 1 : 0 }, ++ get acquiring() { return acquisition && acquisition.owner.stage !== Stage.Settled ? 1 : 0 }, count: 0, id } @@ -388,9 +389,9 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 + listen(socket) + } catch (err) { + afterFailure(err, 'protocol') -+ } -+ } -+ + } + } + + function authenticate() { + try { + statements = {} @@ -519,9 +520,9 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 + ms && (closeTimer = clampedTimeout(() => (closeTimer = null, dispatch('closeTimeout')), ms)) + } else { + socket.destroy() - } - } - ++ } ++ } ++ + function handoff() { + const { owner, ending } = acquisition + transition(Phase.Ready) @@ -531,13 +532,13 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 + lifeTimer.start() + + if (ending) { -+ if (owner.cancelled) ++ if (owner.stage === Stage.Settled) + return closing() + transition(Phase.Draining) -+ return execute(owner) ++ return onopen(connection, owner, true) + } + -+ onopen(connection, owner.cancelled ? undefined : owner) ++ onopen(connection, owner.stage === Stage.Settled ? undefined : owner) + } + function execute(q) { @@ -545,34 +546,36 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 - return queryError(q, Errors.connection('CONNECTION_DESTROYED', options)) + return dispatch('execute', q) + } - -- if (stream) -- return queryError(q, Errors.generic('COPY_IN_PROGRESS', 'You cannot execute queries during copy')) ++ + function submit(q) { + if (stream) { + queryError(q, Errors.generic('COPY_IN_PROGRESS', 'You cannot execute queries during copy')) + return true + } -- if (q.cancelled) -- return +- if (stream) +- return queryError(q, Errors.generic('COPY_IN_PROGRESS', 'You cannot execute queries during copy')) + if (q.cancelled && !connection.owner && max !== 1) + return true -+ + +- if (q.cancelled) +- return + q.owner === undefined && (q.owner = connection.owner) try { q.state = backend -@@ -169,19 +554,35 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose - ? sent.push(q) - : (query = q, query.active = true) - + query +- ? sent.push(q) +- : (query = q, query.active = true) ++ ? (step(q, Stage.Sent), sent.push(q)) ++ : activate(q) ++ + if (q.cancelled) { + q.cancelled = null + abort(q, Errors.generic('57014', 'canceling statement due to user request')) + return accepting() + } -+ + build(q) - return write(toBuffer(q)) - && !q.describeFirst @@ -697,7 +700,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 while (incoming.length > 4) { length = incoming.readUInt32BE(1) if (length >= incoming.length) { -@@ -323,74 +688,34 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -323,138 +688,61 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose try { handle(incoming.subarray(0, length + 1)) } catch (e) { @@ -786,19 +789,26 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 } function queryError(query, err) { -@@ -401,7 +726,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose - err = new Error(err) + if (query.reserve) +- return query.reject(err) ++ return fail(query, err) - 'query' in err || 'parameters' in err || Object.defineProperties(err, { + if (!err || typeof err !== 'object') +- err = new Error(err) ++ err = new Error(typeof err === 'symbol' ? String(err) : err) + +- 'query' in err || 'parameters' in err || Object.defineProperties(err, { - stack: { value: err.stack + query.origin.replace(/.*\n/, '\n'), enumerable: options.debug }, ++ 'query' in err || 'parameters' in err || Object.entries({ + stack: { value: err.stack + query.origin.replace(/.*\n/, '\n'), enumerable: options.debug, writable: true, configurable: true }, query: { value: query.string, enumerable: options.debug }, parameters: { value: query.parameters, enumerable: options.debug }, args: { value: query.args, enumerable: options.debug }, -@@ -410,51 +735,14 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose - query.reject(err) - } - + types: { value: query.statement && query.statement.types, enumerable: options.debug } +- }) +- query.reject(err) +- } +- - function end() { - return ending || ( - !connection.reserved && onend(connection), @@ -806,8 +816,10 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 - ? (terminate(), new Promise(r => socket && socket.readyState !== 'closed' ? socket.once('close', r) : r())) - : ending = new Promise(r => ended = r) - ) -- } -- ++ }).forEach(([key, descriptor]) => Reflect.defineProperty(err, key, descriptor)) ++ fail(query, err) + } + - function terminate() { - terminated = true - if (stream || query || initial || sent.length) @@ -882,7 +894,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 } function ParameterStatus(x) { -@@ -528,19 +818,25 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -528,20 +818,26 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose backendParameters[k] = v if (options.parameters[k] !== v) { options.parameters[k] = v @@ -906,11 +918,13 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 ? retry(query, errorResponse) : errored(errorResponse) } else { +- query.resolve(results || result) + query.initialization && query.initialization(results || result) - query.resolve(results || result) ++ succeed(query, results || result) } } else if (errorResponse) { -@@ -549,42 +845,34 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose + errored(errorResponse) +@@ -549,42 +845,37 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose query = results = errorResponse = null result = new Result() @@ -936,20 +950,22 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 - options.shared.retries = retries = 0 - initial = null - return +- } + function pipelined() { -+ query = sent.length ? sent.shift() : null -+ if (query) { -+ query.active = true -+ query.cancelled && cancelRequest(options, query.state).then(query.cancelled.resolve, query.cancelled.reject) - } ++ query = null ++ return sent.length ? activate(sent.shift()) : null ++ } - while (sent.length && (query = sent.shift()) && (query.active = true, query.cancelled)) - Connection(options).cancel(query.state, query.cancelled.resolve, query.cancelled.reject) -+ return query ++ function activate(q) { ++ query = q ++ step(q, Stage.Active) ++ q.active = true ++ q.cancelled && q.cancelled.resolve && cancelRequest(options, q.state).then(q.cancelled.resolve, q.cancelled.reject) ++ return q + } - -- if (query) -- return // Consider opening if able and sent.length < 50 ++ + function initialized() { + if (target_session_attrs) { + if (!backendParameters.in_hot_standby || !backendParameters.default_transaction_read_only) @@ -958,7 +974,9 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 + if (reason) + return mismatched(reason) + } -+ + +- if (query) +- return // Consider opening if able and sent.length < 50 + if (needsTypes) + return fetchArrayTypes() @@ -975,7 +993,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 } function CommandComplete(x) { -@@ -602,7 +890,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -602,7 +893,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose final && (final(), final = null) @@ -984,7 +1002,17 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 return errored(Errors.generic('UNSAFE_TRANSACTION', 'Only use sql.begin, sql.reserved or max: 1')) if (query.options.simple) -@@ -654,7 +942,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -619,6 +910,9 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose + } + + function BindComplete() { ++ if (!query.statement) ++ return ++ + !result.statement && (result.statement = query.statement) + result.columns = query.statement.columns + } +@@ -654,7 +948,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose const number = x.readUInt16BE(index + 4) const type = x.readUInt32BE(index + 6) query.statement.columns[i] = { @@ -993,8 +1021,12 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 ? transform.column.from(x.toString('utf8', start, index - 1)) : x.toString('utf8', start, index - 1), parser: parsers[type], -@@ -670,8 +958,9 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose - return (query.resolve(query.statement), write(Sync)) +@@ -667,11 +961,12 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose + + result.statement = query.statement + if (query.onlyDescribe) +- return (query.resolve(query.statement), write(Sync)) ++ return (succeed(query, query.statement), write(Sync)) } - async function Authentication(x, type = x.readUInt32BE(5)) { @@ -1005,7 +1037,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 type === 3 ? AuthenticationCleartextPassword : type === 5 ? AuthenticationMD5Password : type === 10 ? SASL : -@@ -679,18 +968,20 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -679,18 +974,20 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose type === 12 ? SASLFinal : type !== 0 ? UnknownAuth : noop @@ -1029,7 +1061,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 const payload = 'md5' + ( await md5( Buffer.concat([ -@@ -699,40 +990,42 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -699,40 +996,42 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose ]) ) ) @@ -1063,10 +1095,10 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 - parseInt(res.i), 32, - 'sha256' - ) +- +- const clientKey = await hmac(saltedPassword, 'Client Key') + const { clientKey, storedKey, serverKey } = await scramKeys(await Pass(), res.s, res.i) -- const clientKey = await hmac(saltedPassword, 'Client Key') -- - const auth = 'n=*,r=' + nonce + ',' + const auth = 'n=*,r=' + clientNonce + ',' + 'r=' + res.r + ',s=' + res.s + ',i=' + res.i @@ -1086,7 +1118,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 write( b().p().str(payload).end() ) -@@ -742,8 +1035,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -742,8 +1041,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose if (x.toString('utf8', 9).split(b.N, 1)[0].slice(2) === serverSignature) return /* c8 ignore next 5 */ @@ -1096,7 +1128,16 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 } function Pass() { -@@ -765,48 +1057,47 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -757,7 +1055,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose + result.statement = query.statement + result.statement.columns = [] + if (query.onlyDescribe) +- return (query.resolve(query.statement), write(Sync)) ++ return (succeed(query, query.statement), write(Sync)) + } + + function BackendKeyData(x) { +@@ -765,48 +1063,47 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose backend.secret = x.readUInt32BE(9) } @@ -1168,7 +1209,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 } function ErrorResponse(x) { -@@ -814,12 +1105,11 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -814,12 +1111,11 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose (query.cursorFn || query.describeFirst) && write(Sync) errorResponse = Errors.postgres(parseError(x)) } else { @@ -1182,7 +1223,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 q.retried = error execute(q) } -@@ -830,22 +1120,27 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -830,28 +1126,33 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose let index = 9 while (x[index++] !== 0); @@ -1212,11 +1253,18 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 - write(Sync) - query.reject(err) + query === current && socket === source && write(Sync) -+ current.reject(err) ++ fail(current, err) } } -@@ -862,7 +1157,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose + function CloseComplete() { + result.count && query.cursorFn(result) +- query.resolve(result) ++ succeed(query, result) + } + + function CopyInResponse() { +@@ -862,7 +1163,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose }, destroy(error, callback) { callback(error) @@ -1225,11 +1273,12 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 stream = null }, final(callback) { -@@ -872,27 +1167,29 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -871,28 +1172,28 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose + stream = null } }) - query.resolve(stream) -+ connection.owner && connection.owner.next() +- query.resolve(stream) ++ deliver(query, stream) } function CopyOutResponse() { @@ -1237,8 +1286,8 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 - read() { socket.resume() } + read() { copyPaused = false; socket.resume() } }) - query.resolve(stream) -+ connection.owner && connection.owner.next() +- query.resolve(stream) ++ deliver(query, stream) } /* c8 ignore next 3 */ @@ -1258,10 +1307,16 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 stream = null }, final(callback) { -@@ -901,22 +1198,36 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -900,23 +1201,41 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose + final = callback } }) - query.resolve(stream) +- query.resolve(stream) ++ deliver(query, stream) ++ } ++ ++ function deliver(q, value) { ++ q.resolve(value) + connection.owner && connection.owner.next() } @@ -1298,7 +1353,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 } /* c8 ignore next 3 */ -@@ -945,20 +1256,21 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -945,20 +1264,21 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose } /* Messages */ @@ -1327,7 +1382,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 prev = b.i b.inc(4).str(x).i32(b.i - prev - 4, prev) -@@ -966,7 +1278,27 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -966,7 +1286,27 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose b.i16(0) @@ -1356,7 +1411,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 } function Parse(str, parameters, types, name = '') { -@@ -994,7 +1326,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -994,7 +1334,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose } function StartupMessage() { @@ -1365,7 +1420,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 Object.entries(Object.assign({ user, database, -@@ -1019,6 +1351,33 @@ function parseError(x) { +@@ -1019,6 +1359,33 @@ function parseError(x) { return error } @@ -1399,7 +1454,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..4e05655b08eb1c8981ba627f49d650f4 function md5(x) { return crypto.createHash('md5').update(x).digest('hex') } -@@ -1042,21 +1401,44 @@ function xor(a, b) { +@@ -1042,21 +1409,44 @@ function xor(a, b) { function timer(fn, seconds) { seconds = typeof seconds === 'function' ? seconds() : seconds if (!seconds) @@ -1485,7 +1540,7 @@ index 0ff83c428bec774e11417b8e1f033dc3305c18cf..023c3ba1bd113e6f5508ab079efcf220 code: x, errno: x, diff --git a/src/index.js b/src/index.js -index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd02329497fd7 100644 +index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b87378acdb 100644 --- a/src/index.js +++ b/src/index.js @@ -3,10 +3,12 @@ import fs from 'fs' @@ -1501,27 +1556,30 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 toPascal, pascal, toCamel, -@@ -18,13 +20,17 @@ import { +@@ -18,13 +20,19 @@ import { fromKebab } from './types.js' -import Connection from './connection.js' +-import { Query, CLOSE } from './query.js' +import { Connection, defaultBackoff } from './connection.js' +import { cancelRequest } from './transport.js' +import clampedTimeout from './timeout.js' - import { Query, CLOSE } from './query.js' ++import { Query, CLOSE, Stage, step, succeed, fail } from './query.js' import Queue from './queue.js' -import { Errors, PostgresError } from './errors.js' +import { Errors, PostgresError, callback } from './errors.js' import Subscribe from './subscribe.js' import largeObject from './large.js' ++const check = globalThis[Symbol.for('postgres.js:check')] +const Lease = { Active: 0, Settling: 1, Released: 2, Ended: 3, Closed: 4 } ++const noop = () => { /* noop */ } + Object.assign(Postgres, { PostgresError, toPascal, -@@ -51,6 +57,7 @@ function Postgres(a, b) { +@@ -51,6 +59,7 @@ function Postgres(a, b) { , subscribe = options.no_subscribe || Subscribe(Postgres, { ...options }) let ending = false @@ -1529,7 +1587,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 const queries = Queue() , connecting = Queue() -@@ -62,7 +69,7 @@ function Postgres(a, b) { +@@ -62,7 +71,7 @@ function Postgres(a, b) { , full = Queue() , queues = { connecting, reserved, closed, ended, open, busy, full } @@ -1538,7 +1596,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 const sql = Sql(handler) -@@ -75,10 +82,12 @@ function Postgres(a, b) { +@@ -75,10 +84,12 @@ function Postgres(a, b) { PostgresError, options, reserve, @@ -1552,7 +1610,16 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 }) return sql -@@ -144,6 +153,56 @@ function Postgres(a, b) { +@@ -131,7 +142,7 @@ function Postgres(a, b) { + const query = new Query([], args, (query) => { + fs.readFile(path, 'utf8', (err, string) => { + if (err) +- return query.reject(err) ++ return fail(query, err) + + query.strings = [string] + handler(query) +@@ -144,6 +155,56 @@ function Postgres(a, b) { } } @@ -1609,7 +1676,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 async function listen(name, fn, onlisten) { const listener = { fn, onlisten } -@@ -153,6 +212,7 @@ function Postgres(a, b) { +@@ -153,6 +214,7 @@ function Postgres(a, b) { idle_timeout: null, max_lifetime: null, fetch_types: false, @@ -1617,7 +1684,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 onclose() { Object.entries(listen.channels).forEach(([name, { listeners }]) => { delete listen.channels[name] -@@ -160,7 +220,7 @@ function Postgres(a, b) { +@@ -160,7 +222,7 @@ function Postgres(a, b) { }) }, onnotify(c, x) { @@ -1626,7 +1693,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 } })) -@@ -170,7 +230,7 @@ function Postgres(a, b) { +@@ -170,7 +232,7 @@ function Postgres(a, b) { if (exists) { channels[name].listeners.push(listener) const result = await channels[name].result @@ -1635,7 +1702,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 return { state: result.state, unlisten } } -@@ -178,7 +238,7 @@ function Postgres(a, b) { +@@ -178,7 +240,7 @@ function Postgres(a, b) { sql.unsafe('"' + name.replace(/"/g, '""') + '"') }`, listeners: [listener] } const result = await channels[name].result @@ -1644,7 +1711,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 return { state: result.state, unlisten } async function unlisten() { -@@ -200,62 +260,146 @@ function Postgres(a, b) { +@@ -200,62 +262,159 @@ function Postgres(a, b) { return await sql`select pg_notify(${ channel }, ${ '' + payload })` } @@ -1658,23 +1725,41 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 - closed.length && connect(closed.shift(), query) - }) + async function lease(auto) { ++ const l = newLease(auto) ++ check && check('routed', l) ++ const c = route(l) ++ if (c && !(c instanceof Error)) ++ return (assign(c, l, false), l) + +- move(c, reserved) +- c.reserved = () => queue.length +- ? c.execute(queue.shift()) +- : move(c, reserved) +- c.reserved.release = true + if (ending) -+ throw Errors.connection('CONNECTION_ENDED', options) ++ throw (fail(l, c), c) + -+ const l = { state: null, connection: null, error: null, onclose: null, queue: Queue() } -+ const idle = takeOpen() -+ idle -+ ? own(idle, l) -+ : auto && !closed.length && busy.length -+ ? own(busy.shift(), l) -+ : await new Promise((resolve, reject) => { -+ const query = { reserve: c => resolve(own(c, l)), reject } -+ closed.length -+ ? connect(closed.shift(), query) -+ : allHeldByCopy() -+ ? reject(copyInProgress()) -+ : queries.push(query) -+ }) ++ await new Promise((resolve, reject) => { ++ l.resolve = resolve ++ l.reject = reject ++ c && fail(l, c) ++ }) ++ return l ++ } ++ ++ function newLease(auto) { ++ const l = { ++ stage: Stage.New, ++ state: null, ++ connection: null, ++ error: null, ++ onclose: null, ++ queue: Queue(), ++ auto, ++ resolve: noop, ++ reject: noop, ++ reserve: true ++ } + return l + } + @@ -1697,8 +1782,8 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 + l.state === expected + ? c.copying || (c.queue !== full && c.accepting) + ? c.execute(q) || move(c, full) -+ : (move(c, full), q.queue = l.queue, l.queue.push(q)) -+ : q.reject(leaseError(l)) ++ : (move(c, full), step(q, Stage.Queued), q.queue = l.queue, l.queue.push(q)) ++ : fail(q, leaseError(l)) + } + + function leaseError(l) { @@ -1709,18 +1794,13 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 + : Errors.generic('TRANSACTION_ENDED', 'Transaction handle used after its transaction ended') + } -- move(c, reserved) -- c.reserved = () => queue.length -- ? c.execute(queue.shift()) -- : move(c, reserved) -- c.reserved.release = true + function stop(l, state) { + if (l.state === Lease.Released || l.state === Lease.Ended) + return null - ++ + l.state = state + while (l.queue.length) -+ l.queue.shift().reject(leaseError(l)) ++ fail(l.queue.shift(), leaseError(l)) + + const c = l.connection + if (c.owner !== l) @@ -1780,10 +1860,8 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 + throw e + }) + return scope(fn) - } - -- async function scope(c, fn, name) { -- const sql = Sql(handler) ++ } ++ + async function finish(statement) { + let result + l.state = Lease.Settling @@ -1805,8 +1883,10 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 + function terminate() { + const c = stop(l, Lease.Ended) + c && c.terminate() -+ } -+ + } + +- async function scope(c, fn, name) { +- const sql = Sql(handler) + async function scope(fn, name) { + const sql = Sql(track) sql.savepoint = savepoint @@ -1825,7 +1905,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 try { result = await new Promise((resolve, reject) => { const x = fn(sql) -@@ -265,17 +409,27 @@ function Postgres(a, b) { +@@ -265,17 +424,27 @@ function Postgres(a, b) { if (uncaughtError) throw uncaughtError } catch (e) { @@ -1859,7 +1939,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 } return result -@@ -285,23 +439,18 @@ function Postgres(a, b) { +@@ -285,23 +454,18 @@ function Postgres(a, b) { return savepoint(sql => sql.apply(sql, arguments)) arguments.length === 1 && (fn = name, name = null) @@ -1889,7 +1969,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 } } -@@ -310,7 +459,7 @@ function Postgres(a, b) { +@@ -310,7 +474,7 @@ function Postgres(a, b) { queue.push(c) c.queue = queue queue === open @@ -1898,28 +1978,59 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 : c.idleTimer.cancel() return c } -@@ -330,15 +479,51 @@ function Postgres(a, b) { +@@ -327,38 +491,101 @@ function Postgres(a, b) { + } + + function handler(query) { ++ const c = route(query) ++ if (c === null) ++ return ++ ++ c instanceof Error ++ ? fail(query, c) ++ : go(c, query) ++ } ++ ++ function route(r) { if (ending) - return query.reject(Errors.connection('CONNECTION_ENDED', options, options)) +- return query.reject(Errors.connection('CONNECTION_ENDED', options, options)) ++ return Errors.connection('CONNECTION_ENDED', options, options) - if (open.length) - return go(open.shift(), query) + const idle = takeOpen() + if (idle) -+ return go(idle, query) ++ return idle ++ ++ if (r.reserve && r.auto && !closed.length && busy.length) ++ return busy.shift() if (closed.length) - return connect(closed.shift(), query) +- return connect(closed.shift(), query) ++ return (connect(closed.shift(), r), null) ++ ++ const c = r.reserve ? null : takeBusy() ++ if (c) ++ return c ++ ++ if (allHeldByCopy()) ++ return copyInProgress() ++ ++ step(r, Stage.Queued) ++ queries.push(r) ++ return null ++ } - busy.length - ? go(busy.shift(), query) - : queries.push(query) -+ const c = takeBusy() -+ c -+ ? go(c, query) -+ : allHeldByCopy() -+ ? query.reject(copyInProgress()) -+ : queries.push(query) ++ function assign(c, r, fresh) { ++ check && check('handover', r, fresh, c.active + c.pipelined) ++ if (!r.reserve) ++ return c.execute(r) ++ ++ own(c, r) ++ succeed(r, r) + } + + function allHeldByCopy() { @@ -1955,7 +2066,10 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 } function go(c, query) { -@@ -348,17 +533,18 @@ function Postgres(a, b) { +- return c.execute(query) ++ return assign(c, query, false) + ? move(c, busy) + : move(c, full) } function cancel(query) { @@ -1978,13 +2092,13 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 + } else { + query.queue || options.max === 1 || queries.remove(query) + query.cancelled = true -+ query.reject(Errors.generic('57014', 'canceling statement due to user request')) ++ fail(query, Errors.generic('57014', 'canceling statement due to user request')) + resolve() + } }) } -@@ -368,13 +554,23 @@ function Postgres(a, b) { +@@ -368,13 +595,23 @@ function Postgres(a, b) { await 1 let timer @@ -2001,7 +2115,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 + ])).then(() => { + clearTimeout(timer) + while (queries.length) -+ queries.shift().reject(Errors.connection('CONNECTION_CLOSED', options)) ++ fail(queries.shift(), Errors.connection('CONNECTION_CLOSED', options)) + }) + } + @@ -2015,26 +2129,36 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 } async function close() { -@@ -382,9 +578,9 @@ function Postgres(a, b) { +@@ -382,15 +619,16 @@ function Postgres(a, b) { } async function destroy(resolve) { - await Promise.all(connections.map(c => c.terminate())) while (queries.length) - queries.shift().reject(Errors.connection('CONNECTION_DESTROYED', options)) +- queries.shift().reject(Errors.connection('CONNECTION_DESTROYED', options)) ++ fail(queries.shift(), Errors.connection('CONNECTION_DESTROYED', options)) + await Promise.all(connections.map(c => c.terminate())) resolve() } -@@ -398,12 +594,18 @@ function Postgres(a, b) { +- function connect(c, query) { ++ function connect(c, r) { ++ step(r, Stage.Opening) + move(c, connecting) +- c.connect(query) ++ c.connect(r) + return c + } + +@@ -398,19 +636,25 @@ function Postgres(a, b) { move(c, ended) } - function onopen(c) { - if (queries.length === 0) -+ function onopen(c, initial) { -+ if (initial && initial.reserve) -+ return initial.reserve(c) ++ function onopen(c, initial, draining) { ++ if (draining || initial && initial.reserve) ++ return assign(c, initial, true) + + if (!initial && !c.accepting) + return move(c, full) @@ -2044,11 +2168,20 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 let max = Math.ceil(queries.length / (connecting.length + 1)) - , ready = true -+ , ready = !initial || c.execute(initial) ++ , ready = !initial || assign(c, initial, true) while (ready && queries.length && max-- > 0) { const query = queries.shift() -@@ -418,12 +620,60 @@ function Postgres(a, b) { + if (query.reserve) +- return query.reserve(c) ++ return assign(c, query, false) + +- ready = c.execute(query) ++ ready = assign(c, query, false) + } + + ready +@@ -418,12 +662,60 @@ function Postgres(a, b) { : move(c, full) } @@ -2061,8 +2194,8 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 + while (ready && queries.length) { + const query = queries.shift() + query.reserve -+ ? query.reject(Errors.connection('CONNECTION_ENDED', options)) -+ : (drained = true, ready = c.execute(query)) ++ ? fail(query, Errors.connection('CONNECTION_ENDED', options)) ++ : (drained = true, ready = assign(c, query, false)) + } + drained && move(c, ended) + return drained @@ -2080,7 +2213,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 + l.error = e || Errors.connection('CONNECTION_CLOSED', options) + c.owner = null + while (l.queue.length) -+ l.queue.shift().reject(Errors.connection('CONNECTION_CLOSED', options)) ++ fail(l.queue.shift(), Errors.connection('CONNECTION_CLOSED', options)) + + l.onclose && l.onclose(l.error) + } @@ -2100,9 +2233,9 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 + while (queries.length) { + const query = queries.shift() + if (query.reserve) { -+ query.reject(Errors.connection('CONNECTION_ENDED', options)) ++ fail(query, Errors.connection('CONNECTION_ENDED', options)) + } else if (reconnectFailed) { -+ query.reject(e === undefined ? Errors.connection('CONNECTION_CLOSED', options) : e) ++ fail(query, e === undefined ? Errors.connection('CONNECTION_CLOSED', options) : e) + } else { + reconnecting = c + connect(c, query) @@ -2113,7 +2246,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 } } -@@ -453,16 +703,17 @@ function parseOptions(a, b) { +@@ -453,16 +745,17 @@ function parseOptions(a, b) { connect_timeout : 30, max_lifetime : max_lifetime, max_pipeline : 100, @@ -2133,7 +2266,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 host : Array.isArray(host) ? host : host.split(',').map(x => x.split(':')[0]), port : Array.isArray(port) ? port : host.split(',').map(x => parseInt(x.split(':')[1] || port)), path : o.path || host.indexOf('/') > -1 && host + '/.s.PGSQL.' + port, -@@ -472,8 +723,8 @@ function parseOptions(a, b) { +@@ -472,8 +765,8 @@ function parseOptions(a, b) { ...Object.entries(defaults).reduce( (acc, [k, d]) => { const value = k in o ? o[k] : k in query @@ -2144,7 +2277,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 acc[k] = typeof value === 'string' && ints.includes(k) ? +value : value -@@ -488,16 +739,26 @@ function parseOptions(a, b) { +@@ -488,16 +781,26 @@ function parseOptions(a, b) { }, types : o.types || {}, target_session_attrs: tsa(o, url, env), @@ -2172,7 +2305,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 } function tsa(o, url, env) { -@@ -508,8 +769,12 @@ function tsa(o, url, env) { +@@ -508,8 +811,12 @@ function tsa(o, url, env) { throw new Error('target_session_attrs ' + x + ' is not supported') } @@ -2188,12 +2321,53 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..db93ccaa423e3162f42f99c9e52cd023 function max_lifetime() { diff --git a/src/query.js b/src/query.js -index 0d44a15cd9e42beaf11d4be6ccde60223e09508a..c1777a904c2f214a041fb8af0b56f0ac38418081 100644 +index 0d44a15cd9e42beaf11d4be6ccde60223e09508a..ccaa913747ef7da487f65712166038a254d4ffc9 100644 --- a/src/query.js +++ b/src/query.js -@@ -23,10 +23,12 @@ export class Query extends Promise { +@@ -3,6 +3,38 @@ const originCache = new Map() + , originError = Symbol('OriginError') + + export const CLOSE = {} ++export const Stage = { New: 0, Queued: 1, Opening: 2, Sent: 3, Active: 4, Settled: 5 } ++ ++const check = globalThis[Symbol.for('postgres.js:check')] ++const stageNames = Object.keys(Stage) ++ ++export function step(r, next) { ++ const from = r.stage ++ if (from === Stage.Settled) ++ return ++ ++ check && check('step', r, stageNames[from], stageNames[next]) ++ r.stage = next ++} ++ ++export function succeed(r, value) { ++ if (r.stage === Stage.Settled) ++ return ++ ++ check && check('requestSettled', r, stageNames[r.stage]) ++ r.stage = Stage.Settled ++ r.resolve(value) ++} ++ ++export function fail(r, error) { ++ if (r.stage === Stage.Settled) ++ return ++ ++ check && check('requestSettled', r, stageNames[r.stage]) ++ r.stage = Stage.Settled ++ r.reject(error) ++} ++ + export class Query extends Promise { + constructor(strings, args, handler, canceller, options = {}) { + let resolve +@@ -22,11 +54,14 @@ export class Query extends Promise { + this.state = null this.statement = null ++ this.stage = Stage.New - this.resolve = x => (this.active = false, resolve(x)) - this.reject = x => (this.active = false, reject(x)) @@ -2206,7 +2380,7 @@ index 0d44a15cd9e42beaf11d4be6ccde60223e09508a..c1777a904c2f214a041fb8af0b56f0ac this.cancelled = null this.executed = false this.signature = '' -@@ -50,7 +52,14 @@ export class Query extends Promise { +@@ -50,7 +85,14 @@ export class Query extends Promise { } cancel() { @@ -2222,6 +2396,15 @@ index 0d44a15cd9e42beaf11d4be6ccde60223e09508a..c1777a904c2f214a041fb8af0b56f0ac } simple() { +@@ -137,7 +179,7 @@ export class Query extends Promise { + } + + async handle() { +- !this.executed && (this.executed = true) && await 1 && this.handler(this) ++ !this.executed && (this.executed = true) && await 1 && (check && check('routed', this), this.handler(this)) + } + + execute() { diff --git a/src/subscribe.js b/src/subscribe.js index 4f8934cc8277fc58d2c37838cfb1afc315bc0744..0fd5d4201123e4c08d85fd1c46396baa60ba53cf 100644 --- a/src/subscribe.js diff --git a/docs/lifecycle.md b/docs/lifecycle.md index 91bfcf03..68245b7b 100644 --- a/docs/lifecycle.md +++ b/docs/lifecycle.md @@ -138,6 +138,49 @@ An asynchronous result can arrive after the phase or attempt that started it is - **Socket identity.** The message loop in `data()` stops if handling a message replaced the socket. A suspended cursor's continuation checks that both the query and the socket are still current. - **The idle timer** belongs to the pool, which starts it when it files a connection in `open` and cancels it on any other move. +## Requests + +A request is what the pool routes: a `Query`, or a lease waiting for a connection. A `Query` is also the unit a connection runs. There is no wrapper object, because the tracers read the query itself, so both kinds carry the same fields: + +| Field | Query | Lease | +|---|---|---| +| `stage` | set in the constructor | set when the lease is created | +| `resolve`, `reject` | the arrows set in the constructor | from the promise it waits on; no-ops when a connection is handed over at once | +| `reserve` | absent | `true`, the marker that tells a lease from a query | +| `queue` | the lease queue it waits in, if any | its own statement queue | + +`Stage`, `step`, `succeed` and `fail` are exported from `src/query.js`. `step` writes the stage unless the request is Settled. `succeed` and `fail` settle a request once: they do nothing for a request that is already Settled, and they look `resolve` and `reject` up when called. + +| Stage | A query is | A lease is | +|---|---|---| +| New | built, not routed | created | +| Queued | in the pool queue, or in a lease's queue | in the pool queue | +| Opening | the opener of a connection | the same | +| Sent | admitted by a connection and waiting for its turn | not used | +| Active | the connection's current query | not used | +| Settled | resolved or rejected | handed a connection, or refused | + +| From | To | Caused by | +|---|---|---| +| New | Queued | `route()` finds no free connection; a lease statement queues behind a full or non-accepting connection | +| New, Queued | Opening | `connect()` starts an acquisition for it | +| New, Queued, Opening | Sent or Active | the connection admits it (`submit`): Active when nothing is current, Sent otherwise | +| Sent | Active | its turn (`pipelined` calls `activate`) | +| Active | Sent | a stale-plan retry sends it again at the back | +| any but Settled | Settled | `succeed` or `fail` | + +`route(r)` decides where a request goes and does not settle it. It takes a connection (an idle one, or for a plain query a closed slot first and then a busy one; for a lease that may use a busy connection, only when no slot is closed), starts an acquisition, or queues the request, and writes the Queued or Opening stage when it does. It returns the connection to use, `null` when the request now waits, or the refusal error (`CONNECTION_ENDED` while the pool is ending, `COPY_IN_PROGRESS` when every connection holds a COPY). `handler()` and `lease()` commit after it returns: they hand the connection over with `assign`, or settle the request with the refusal. That is the contract: **`route` never settles a request**, and nothing in it can execute or activate one, so everything that can settle or activate synchronously runs after it. Anything that withdraws a waiting request, such as an abort or a pool-wait timeout, belongs next to that commit step or in `cancel()`, not in `route`. + +`assign(c, r, fresh)` is the one place a pool request gets a connection. `fresh` is true only for the opener of `c` (`onopen`'s `initial`), and the number of requests already on the connection is read before the request is executed. A lease takes its connection and settles through the same call. Lease statements are not pool requests: `send` and the lease's `next` stay its own dispatcher. + +**Early settle while holding the slot.** `describe()`, closing a cursor, a protocol error, `UNSAFE_TRANSACTION` and a build failure settle the request before ReadyForQuery. The connection keeps the query as current until ReadyForQuery, which calls `succeed` or `fail` again and does nothing. The abort statement, `retried` and the barrier are untouched. + +**COPY.** `deliver(q, stream)` hands out the stream with a direct `q.resolve(stream)`, then calls `owner.next()`. The request stays Active and is settled at its ReadyForQuery or by `endSession`, so `resolve` runs twice for COPY. dd-trace ends a COPY span on the second call, so folding the hand-out into `succeed` would leave every COPY span open. + +**Settled requests are still routed.** A query cancelled before it is awaited, or while `file()` reads its file, is routed when it is awaited: `step` leaves the stage Settled, and the connection skips it (`submit` returns early for a cancelled query without an owner and not at `max: 1`) or, at `max: 1` and on leases, writes the refused statement in its place. + +**Errors.** `queryError` decorates an error with the query's details and fails the request. It wraps a thrown non-object in an `Error`, which covers a query that fails while being built or sent. Pool-side failures, a cursor callback that throws and the queries rejected after a failed reconnect while ending are raw, and `fail` wraps nothing. + ## Leases `reserve()` and `begin()` take a connection out of the pool through a lease. The lease's state says what the handle is doing now. @@ -182,15 +225,15 @@ Each connection sits in exactly one pool queue, and the queue it is in must be o | Owned, statement in flight | `full`; `reserved` while a COPY is running, once the server has opened its stream | | Draining or Closing, unowned | `ended` | -**Admission.** Replies are matched to queries by position, so nothing may be written while the server is partway through an exchange. The connection records the one query nothing may be written behind, its barrier: a statement that asks for its parameter types first (one with a value whose type is not known; with `parameter_types: 'client'`, one with an untyped array), a named statement's first run on a connection when it has values (so identical queries pipelined behind it reuse the statement instead of each preparing their own; a first run without values holds nothing, as in Postgres.js, because a round trip on every first run costs more than the duplicate statements a burst of identical queries leaves open until the connection closes; a prepared re-run that hits a stale-plan error is retried only when nothing is held behind it, so with `prepare: true` a re-run with an unrelated first run pipelined behind it rejects instead of retrying, once per statement per connection), a cursor, or a simple query whose text contains the word `copy`, set when it is written and cleared at its ReadyForQuery (and in `endSession`). `connection.accepting` is true when the connection is idle, or has no barrier and room under `max_pipeline`, and `execute()` returns false when the connection stops accepting or the socket needs draining (and true after the COPY guard rejects a statement). The pool reads it: `handler()` takes a `busy` connection only if it accepts and files the others in `full`, and a lease sends only to a connection that accepts, otherwise queues the statement and files the connection in `full`. A barrier is always the last query in the line, so it lifts when the connection goes idle, and the existing `onopen` and `owner.next()` calls are the signal that it accepts again. A retry after a plan-invalidation error is made only when no barrier is queued behind the failing statement; otherwise the statement rejects with its plan error. +**Admission.** Replies are matched to queries by position, so nothing may be written while the server is partway through an exchange. The connection records the one query nothing may be written behind, its barrier: a statement that asks for its parameter types first (one with a value whose type is not known; with `parameter_types: 'client'`, one with an untyped array), a named statement's first run on a connection when it has values (so identical queries pipelined behind it reuse the statement instead of each preparing their own; a first run without values holds nothing, as in Postgres.js, because a round trip on every first run costs more than the duplicate statements a burst of identical queries leaves open until the connection closes; a prepared re-run that hits a stale-plan error is retried only when nothing is held behind it, so with `prepare: true` a re-run with an unrelated first run pipelined behind it rejects instead of retrying, once per statement per connection), a cursor, or a simple query whose text contains the word `copy`, set when it is written and cleared at its ReadyForQuery (and in `endSession`). `connection.accepting` is true when the connection is idle, or has no barrier and room under `max_pipeline`, and `execute()` returns false when the connection stops accepting or the socket needs draining (and true after the COPY guard rejects a statement). The pool reads it: `route()` takes a `busy` connection only if it accepts and files the others in `full`, and a lease sends only to a connection that accepts, otherwise queues the statement and files the connection in `full`. A barrier is always the last query in the line, so it lifts when the connection goes idle, and the existing `onopen` and `owner.next()` calls are the signal that it accepts again. A retry after a plan-invalidation error is made only when no barrier is queued behind the failing statement; otherwise the statement rejects with its plan error. -COPY is recognised from the text because the client cannot know a simple query is a COPY until the server answers. A false positive only stops pipelining behind that query. When the server opens a COPY stream the connection calls `owner.next()`, so statements a lease queued before that are rejected with `COPY_IN_PROGRESS`, as are statements sent while the stream is open. Queries sent through the pool never go to a connection with a COPY in flight. When every connection has an open COPY stream whose writable has not been ended (`connection.copyHeld`), `handler()` and `lease()` reject with `COPY_IN_PROGRESS` instead of queueing, since only that COPY finishing could free a connection; work already queued keeps waiting. `release()` of a handle whose connection is partway through an exchange files it in `full` instead of handing it pool queries; the next ReadyForQuery picks it up. +COPY is recognised from the text because the client cannot know a simple query is a COPY until the server answers. A false positive only stops pipelining behind that query. When the server opens a COPY stream the connection calls `owner.next()`, so statements a lease queued before that are rejected with `COPY_IN_PROGRESS`, as are statements sent while the stream is open. Queries sent through the pool never go to a connection with a COPY in flight. When every connection has an open COPY stream whose writable has not been ended (`connection.copyHeld`), `route()` refuses with `COPY_IN_PROGRESS` instead of queueing, since only that COPY finishing could free a connection; work already queued keeps waiting. `release()` of a handle whose connection is partway through an exchange files it in `full` instead of handing it pool queries; the next ReadyForQuery picks it up. The connection drives its own queue through four callbacks: | Callback | When | The pool | |---|---|---| -| `onopen(c, request)` | hand-off; a ReadyForQuery with nothing pipelined and no owner; a released lease; socket `drain` | hands `c` to a waiting reservation, files it in `open`, or runs the request and up to its share of queued queries and files it `busy` or `full` | +| `onopen(c, request, draining)` | hand-off; a ReadyForQuery with nothing pipelined and no owner; a released lease; socket `drain` | hands `c` to a waiting reservation, files it in `open`, or runs the request and up to its share of queued queries and files it `busy` or `full`. With `draining` set, the request is the opener of a connection that was told to end while opening: it is handed over fresh and nothing else happens, so the connection is not moved and takes no queued queries | | `onend(c)` | the connection starts ending | files it in `ended` | | `ondrain(c)` | a Draining connection has gone idle | if the pool is ending, runs queued plain queries on it (rejecting queued reservations with `CONNECTION_ENDED`) and keeps it Draining; otherwise lets it close | | `onclose(c, err)` | `enterClosed` | files it in `closed`, marks its lease Closed, and either starts the next queued request on it or, while ending, handles the queue as described below | @@ -210,6 +253,7 @@ The connection drives its own queue through four callbacks: **Cancel.** +- **Stages:** a cancel before the query is sent settles it (`fail`, stage Settled) whatever its stage was; a Sent query is only marked and keeps its stage until its own response; the current query is Active until its response. - **A query not yet written:** rejected with 57014 at once. If it belongs to a lease, or the pool has `max: 1`, it stays in its queue, and when it reaches the connection the connection writes the refused statement from a failed build in its place, so an open transaction fails. Otherwise it is removed from the pool queue, or skipped if it reaches a connection. - **A query pipelined behind another:** marked, and its CancelRequest is sent once it becomes the current query. It is settled by its own response. - **The current query:** the CancelRequest is sent at once. @@ -227,6 +271,17 @@ The connection drives its own queue through four callbacks: | `unhandled` | `dispatch` found no entry | always a violation | | `settled` | after each outermost `dispatch` | the connection's queue is one its phase and owner allow | +`src/query.js` and `src/index.js` read the hook once when they load and report requests with the request as the second argument: + +| Kind | Reported | Checked by `tests-startup/invariants.js` | +|---|---|---| +| `routed` | a query starts being handled, or a lease is created | records an unsettled request for a final check; a scenario fails if one never settles | +| `step` | a request changes stage | the edge is one of the request edges above | +| `requestSettled` | `succeed` or `fail` settles a request | the stage it settles from allows Settled | +| `handover` | `assign` gives a request a connection, with whether it was fresh and how many requests were already on the connection | a request is handed over once, and fresh exactly when it was Opening | + +The checker keeps the hand-overs in `handovers` for scenarios that assert them. + With the hook set, `connection[Symbol.for('postgres.js:phase')]` returns the phase name. Every scenario in `tests-startup` installs the hook and fails if any violation was recorded. ## Kinds of tests @@ -245,3 +300,7 @@ To check a test against upstream, copy the tree, replace `src/` with `git show 4 1. `cancelRequest` always dials the first host and port, which is wrong after a multi-host failover has moved the session to another host. 2. `onopen` takes a share of queued queries as `ceil(queries / (connecting + 1))` while the handed-off connection is still counted in `connecting`, so it counts itself twice. The formula comes from upstream. 3. A function-valued `idle_timeout` or `max_lifetime` is evaluated once per connection, not once per session. +4. A query cancelled before it is awaited is still routed when it is awaited. With several connections it can open a closed slot for nothing or be skipped by `submit`, and at `max: 1` it writes the refused statement. +5. `go()` files an idle connection `busy` after `submit` skipped a cancelled query, so a connection with nothing on it counts as busy until the next query. +6. `cancel()` on a `for await` cursor after the loop ended returns a promise that never settles, because the cursor arrows never set `settled` and the query is no longer in any line. +7. `sql.end({ timeout: 0 })` can resolve before the listen pool's own destroy timer has fired, so the listen pool's re-listen query settles after `end()` returned. From 6dfd342dc33bb0798cfea8b03cc3c591cf0c6f7c Mon Sep 17 00:00:00 2001 From: Oleg Komarov Date: Sun, 25 Oct 2026 23:31:22 +0000 Subject: [PATCH 4/4] feat: publish query, connection, pool and transaction tracing channels (#73) The driver now publishes diagnostics_channel events that APM tools can subscribe to without patching it. Nothing is published, and nothing is allocated, while a channel has no subscriber. TracingChannels, each following tracePromise order (start, end, error, asyncStart, asyncEnd) and settling once: - postgres:query, one per query, started in Query.handle in the caller's async context so a bindStore transform sees it. The text and statement name are filled in when the query is built for a connection. - postgres:connect, one per connection acquisition, from the socket attempt through the first ReadyForQuery. - postgres:pool:connect, one per wait for a connection: every plain query inside its query span, and every sql.reserve() and sql.begin(). - postgres:transaction, for sql.begin() and sql.savepoint(), with result.committed once known. Plain channels: postgres:pool:release when a reserved connection or transaction lets go of its connection, and postgres:pool:remove when a connection closes. Release carries an error only when the connection is terminated instead of returned healthy. The payload follows the field names of brianc/node-postgres#3650: query { text, name } and client { database, host, port, user, ssl, processID } on queries, connection {...} on connect, pool { totalCount, idleCount, waitingCount, maxSize } then client { processID, reused } on the pool span, and { client: { processID }, error } on release and remove. The pool span splits the wait. It starts when the request is routed. assign() records handoverTime, the moment a connection took the request over, and queuedBehind, how many queries that connection already had running or waiting. A query's span ends when the connection makes it its active query, so the time from handoverTime to the end is spent behind those queries, and the time before it is the wait for a connection. A request that never reached a connection (refused, cancelled in the queue, connection attempt failed) fails the pool span first and then itself. Once handed over, the pool span resolves, and a later failure fails only the query span. Not published: parameter values, in any payload; a send event; a channel for LISTEN or subscriptions. Internal queries (type fetching, session checks) are not traced. Each hook sits on a single transition of the request lifecycle: Query.handle, build, succeed/fail, assign, activate, the connection's acquisition and close, and the lease release. Types, docs/api.md, a workerd scenario and tests/tracing.js cover it. Workers CPU A/B, 150 rounds each (2026-10-25/26, from a temporary subscriber option, not kept): with no subscriber, no difference from the request-lifecycle commit or from main, on the Supabase pooler (median and p95 within 1 ms, rank test p 0.17 to 0.91) or over Hyperdrive (p 0.18 to 0.31). With every channel subscribed through bindStore, the cost is under 1 ms per request: Supabase pooler median 4/4 ms, p95 5/6 ms, p 0.0001; Hyperdrive median 13/13 ms, p95 19/19 ms, p 0.015. --- README.md | 2 + docs/api.md | 163 ++++++ docs/changes-since-3.4.9.diff | 643 +++++++++++++++++++----- docs/lifecycle.md | 15 + src/connection.js | 56 ++- src/index.js | 72 ++- src/query.js | 26 +- src/tracing.js | 150 ++++++ tests-startup/README.md | 2 +- tests-startup/workerd-edge.mjs | 2 +- tests-startup/workerd-run.mjs | 2 +- tests-startup/workerd-worker.js | 33 ++ tests-tracing/harness.mjs | 14 + tests-tracing/run.js | 1 + tests-types/index.ts | 9 + tests/index.js | 1 + tests/tracing.js | 856 ++++++++++++++++++++++++++++++++ transpile.deno.js | 7 +- types/index.d.ts | 82 +++ 19 files changed, 1986 insertions(+), 150 deletions(-) create mode 100644 src/tracing.js create mode 100644 tests/tracing.js diff --git a/README.md b/README.md index 50dca684..d9cb665b 100644 --- a/README.md +++ b/README.md @@ -11,6 +11,7 @@ - **Correctness fixes.** Queries get the right results, transactions stay isolated, and rollbacks are reported as failures. - **Fewer hangs and crashes.** Fixes for stuck queries, shutdown hangs and crashes after disconnects. - **Pool monitoring.** See busy connections, idle connections and waiting queries with `sql.stats()`. +- **Tracing without patches.** Queries, connections and transactions publish [`diagnostics_channel` events](docs/api.md#tracing-channels) for APM and OpenTelemetry subscribers, and nothing is built while no one subscribes. - **Faster queries behind poolers.** Removes an extra network round trip for supported values (opt-in). - **Vercel Fluid Compute support.** Reuse connections between requests and close idle ones before suspension to avoid connection leaks. - **Cloudflare Workers on the cheapest path.** Connects through Cloudflare's own `cloudflare:sockets` API, which costs less CPU per connection than workerd's `node:net`, tested locally and on Cloudflare's network with Neon, Supabase and Hyperdrive. @@ -115,6 +116,7 @@ With `prepare: false`, parameterized queries can pay for an extra network round ### New features - **See pool pressure.** [`sql.stats()`](docs/api.md#pool-stats) reports busy and idle connections and waiting queries. +- **Trace queries natively.** [`postgres:query`, `postgres:connect`, `postgres:pool:connect` and `postgres:transaction`](docs/api.md#tracing-channels) are `diagnostics_channel` tracing channels, published only when something subscribes. - **Handle serverless suspension.** Expired idle connections are replaced on resume; the [Vercel Fluid Compute adapter](docs/api.md#vercel-fluid-compute) keeps instances alive until idle connections close. - **Automatic cleanup.** [`await using`](docs/api.md#teardown--cleanup) closes a pool and `using` releases a reserved connection when its scope ends. Requires Node.js 24+ or TypeScript 5.2+. - **Cloudflare Workers fixes.** On [Workers](docs/api.md#cloudflare-workers-support), `COPY TO` streams and `subscribe()` pause and resume the socket ([#975](https://github.com/porsager/postgres/issues/975)), `ssl: 'prefer'` falls back to plaintext when the server declines TLS, and a certificate from a private CA fails at once with [`TLS_CLOSED`](docs/api.md#tls_closed) instead of a timeout ([#1213](https://github.com/porsager/postgres/issues/1213)). diff --git a/docs/api.md b/docs/api.md index 3f36a330..b79771de 100644 --- a/docs/api.md +++ b/docs/api.md @@ -19,6 +19,7 @@ The full API of [@steadybrew/postgresjs](../README.md). Installing, switching fr * [Custom Types](#custom-types) * [Teardown / Cleanup](#teardown--cleanup) * [Reserving connections](#reserving-connections) +* [Tracing channels](#tracing-channels) * [Error handling](#error-handling) * [TypeScript support](#typescript-support) * [Migration tools](#migration-tools) @@ -1509,6 +1510,168 @@ await reserved`select * from users` After release, queries through that reserved handle reject with [`CONNECTION_RELEASED`](#connection_released). Call `sql.reserve()` again to acquire a new handle. A reserved handle whose connection has closed rejects with `CONNECTION_CLOSED` until it is released, and cannot be reused after reconnect. +## Tracing channels + +The driver publishes `diagnostics_channel` events for queries, connections, pool checkouts and transactions, so an APM or OpenTelemetry integration can subscribe without patching the driver. The names and fields follow the tracing channels of node-postgres, so a subscriber written for one driver reads the other with few changes. Nothing is built or published while no one subscribes: a query costs one `hasSubscribers` check. + +### TracingChannels + +These publish `start`, `end`, `asyncStart`, `asyncEnd` and `error`. + +| Channel | Fires for | +|---|---| +| `postgres:query` | Each query: from the call that runs it until the server answers or the query fails | +| `postgres:connect` | Each connection acquisition: socket, TLS, authentication, startup and type fetching, up to the connection serving queries. Retries and other hosts stay inside one span. | +| `postgres:pool:connect` | Each wait for a connection: `sql.reserve()`, `sql.begin()` and every plain pooled query that has a `postgres:query` subscriber. For a plain query it is a child of the query span and ends when the connection starts running the query. Statements sent on a reserved connection or in a transaction do not publish it. | +| `postgres:transaction` | `sql.begin()` and, nested in it, each `sql.savepoint()` | + +### Plain channels + +These publish one message. Subscribe with `dc.channel(name).subscribe(callback)`. + +| Channel | Fires for | +|---|---| +| `postgres:pool:release` | A reserved connection or a transaction gives its connection back. `error` is set only when the connection is terminated instead of returned healthy, as `release(err)` does in node-postgres: a failed commit or rollback, or a lost connection. A `BEGIN` that fails with something other than a server error terminates the connection afterwards and publishes no error. A callback that threw and rolled back cleanly does not set it | +| `postgres:pool:remove` | A connection closes, including a failed connection attempt | + +### How they fit together + +```text +postgres:pool:connect sql.reserve() acquires a connection + └─ postgres:connect only if the acquisition had to open the connection +postgres:pool:release reserved.release() gives the connection back + +postgres:transaction sql.begin() + ├─ postgres:pool:connect the wait for a connection + │ └─ postgres:connect only if the acquisition had to open the connection + ├─ postgres:query each statement, BEGIN and COMMIT included + └─ postgres:transaction each sql.savepoint(), with its own statements +postgres:pool:release the connection goes back to the pool + +postgres:query a plain pooled query + └─ postgres:pool:connect the wait for a connection + └─ postgres:connect only if the query had to open the connection + +postgres:pool:remove whenever a connection closes +``` + +A plain query publishes `postgres:query` and, inside it, `postgres:pool:connect`. The pool span ends when the connection makes the query its active query, so a query that waits behind others on a busy connection, or in the pool's queue, is waiting inside it. A wait that never reached a connection fails the pool span, and then the query: the pool is ending, a `COPY` holds every connection, the query is cancelled in the pool's queue, or the connection attempt fails. Once a connection has taken the query over (`handoverTime` is set), the pool span resolves, and whatever happens next, such as a build error, a cancel or a lost connection, fails only the query span. + +The `TracingChannel`s publish in the order Node's `tracePromise` does: `start` and `end` in the caller's synchronous code, then for a failure `error`, and for both outcomes `asyncStart` and `asyncEnd`, with `context.result` or `context.error` set first. `start` is published with `runStores`, so a store bound to it, such as an `AsyncLocalStorage` span context, is current in the code that starts the call. Every query publishes `asyncStart` and `asyncEnd` exactly once. That includes cursors read with `for await` or a callback, `forEach`, `COPY` streams (once the copy is over), `describe()`, `simple()`, `unsafe()`, `file()`, pipelined queries, retried queries and queries cancelled before they were sent. The driver's own startup queries (type fetching, `target_session_attrs`) are not published; they belong to the connect span. + +On `postgres:query` and `sql.begin()`'s `postgres:transaction`, the `result` and `error` keys do not exist until they are set, so a subscriber can tell a finished call from a started one by `'result' in context || 'error' in context`. The other contexts have no such key on success, so use the channel's `asyncEnd`. + +A query that is cancelled before it is awaited publishes nothing, because it never starts. + +## Context payloads + +The types are `QueryTraceContext`, `ConnectTraceContext`, `PoolConnectTraceContext`, `TransactionTraceContext`, `PoolReleaseMessage` and `PoolRemoveMessage`. No payload contains parameter values. + +### postgres:query + +| Field | Set | +|---|---| +| `query.text` | when the query is written to a connection: SQL with `$n` placeholders | +| `query.name` | when the query is written: the prepared statement name, undefined for an unnamed statement | +| `client.database`, `client.user` | at `start` | +| `client.host`, `client.port` | at `start` when one host is configured, otherwise when the query is written. For a Unix socket the path is the host and there is no port. | +| `client.ssl` | at `start` from the `ssl` option; when the query is written, whether the connection is encrypted | +| `client.processID` | when the query is written: the backend process id, which `postgres:pool:connect` and `postgres:pool:remove` also report | +| `result` | before `asyncStart`: the `Result` with `command` and `count` (an array of them for a multi-statement simple query); for `describe()` the statement; for a `COPY` stream the `Result` of the finished copy, not the stream | +| `error` | before `error`: the query's own rejection. It carries `query` and `parameters`, which are enumerable only under `debug`, so a subscriber that records the error can leak values; read `error.code` and `error.message` instead | + +The text is known only after the driver has serialized the query for a connection, so read it at `asyncEnd` or `error`, or rename the span then. The `postgres:pool:connect` span inside a plain query is the wait for a connection, and the rest of the query span is the time on the server. + +### postgres:connect + +| Field | Set | +|---|---| +| `connection.database`, `connection.user` | at `start` | +| `connection.host`, `connection.port` | at `start` when one host is configured; updated as each attempt opens its socket | +| `connection.ssl` | at `start` from the `ssl` option; before `asyncStart`, whether the connection is encrypted | +| `error` | before `error`: the failure that ends the acquisition | + +### postgres:pool:connect + +| Field | Set | +|---|---| +| `pool.totalCount`, `pool.idleCount`, `pool.waitingCount` | at `start`, as `sql.stats()` reports them | +| `pool.maxSize` | at `start`: the `max` option | +| `handoverTime` | before `asyncStart`, once a connection took the call over: the epoch milliseconds at which it did | +| `queuedBehind` | with `handoverTime`: how many queries the connection already had running or waiting when it took the call over | +| `client.processID` | with `handoverTime` | +| `client.reused` | with `handoverTime`: false when this call had to open the connection; a call that waited while another call opened it reports true | +| `error` | before `error`: a connection error, `CONNECTION_ENDED` after `sql.end()`, `COPY_IN_PROGRESS`, or the cancellation or connection error of a plain query that settled before a connection took it over | + +`handoverTime` minus the time of `start` is the wait for a connection, which is what OpenTelemetry's `db.client.connection.wait_time` measures. For a plain query with `queuedBehind` above 0, the time from `handoverTime` to `asyncStart` was spent behind those queries on the same connection. A lease span ends at the hand-over, so the time behind those queries falls inside the lease's first statement. Take the `start` time yourself in the `start` subscriber. On Cloudflare Workers `performance.now()` advances only after I/O, so within a request both times can be equal. + +```js +import dc from 'node:diagnostics_channel' +import { trace } from '@opentelemetry/api' + +const pool = dc.tracingChannel('postgres:pool:connect') + +pool.subscribe({ + start(context) { + context.span = trace.getActiveSpan() + }, + end() {}, + asyncStart() {}, + asyncEnd(context) { + if (context.handoverTime === undefined) + return + + context.span?.addEvent('connection handed over', { 'postgres.queued_behind': context.queuedBehind }, context.handoverTime) + }, + error() {} +}) +``` + +### postgres:transaction + +| Field | Set | +|---|---| +| `client` | as in `postgres:query`; the connection fields are filled in once the transaction has its connection | +| `options` | at `start`: the mode string given to `sql.begin()`; undefined for a savepoint | +| `savepoint` | at `start` for `sql.savepoint()`: the savepoint name as sent, such as `s0_name` | +| `prepared` | when `sql.prepare(name)` is called | +| `result` | before `asyncStart` for `sql.begin()`: `{ committed }`, false when the transaction was prepared | +| `error` | before `error` | + +### postgres:pool:release + +`{ client: { processID }, error }`. `error` is set only when the connection is terminated instead of going back to the pool healthy, as `release(err)` does in node-postgres: a commit or rollback that failed, or a connection that was lost, though a `BEGIN` that fails with something other than a server error terminates the connection afterwards and publishes no error. It is undefined after a normal release, including after a callback that threw and rolled back cleanly, and when the server answered a commit with a rollback. `processID` is that of the connection the lease took, even if the connection was lost and reconnected since. + +### postgres:pool:remove + +`{ client: { processID }, error }`. `error` is undefined for a normal close and is not part of the node-postgres message. + +## Example + +```js +import dc from 'node:diagnostics_channel' + +const channel = dc.tracingChannel('postgres:query') + +channel.subscribe({ + start(context) { + context.startedAt = performance.now() + }, + end() {}, + asyncStart() {}, + asyncEnd(context) { + console.log(context.query.text, context.result?.count, performance.now() - context.startedAt) + }, + error(context) { + console.error(context.query.text, context.error) + } +}) +``` + +To make a span current for the code that runs the query, bind an `AsyncLocalStorage` to the start channel with `channel.start.bindStore(storage, context => span)`. + +On Node.js the channels need Node 22 or newer, as the package does. On a runtime without `diagnostics_channel.tracingChannel` nothing is published. On Cloudflare Workers the module needs the `nodejs_compat` flag, which the driver requires already. + ## Error handling Errors are all thrown to related queries and never globally. Errors coming from database itself are always in the [native Postgres format](https://www.postgresql.org/docs/current/errcodes-appendix.html), and the same goes for any [Node.js errors](https://nodejs.org/api/errors.html#errors_common_system_errors) eg. coming from the underlying connection. diff --git a/docs/changes-since-3.4.9.diff b/docs/changes-since-3.4.9.diff index 4e75cfdd..bf0faf83 100644 --- a/docs/changes-since-3.4.9.diff +++ b/docs/changes-since-3.4.9.diff @@ -1,8 +1,8 @@ diff --git a/src/connection.js b/src/connection.js -index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461dccdacf35 100644 +index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..777f05e05fb6c7937ff11995538e2723628fb7ee 100644 --- a/src/connection.js +++ b/src/connection.js -@@ -4,24 +4,41 @@ import crypto from 'crypto' +@@ -4,24 +4,54 @@ import crypto from 'crypto' import Stream from 'stream' import { performance } from 'perf_hooks' @@ -17,8 +17,22 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d +import { SSLRequest, tlsConfig, cancelRequest } from './transport.js' +import { Query, CLOSE, Stage, step, succeed, fail } from './query.js' import b from './bytes.js' - +- -export default Connection ++import { ++ connectChannel, ++ watched, ++ run, ++ publishResolved, ++ publishRejected, ++ connectContext, ++ connectAttempt, ++ connectSecured, ++ queryBuilt, ++ poolEnded, ++ poolRemoved ++} from './tracing.js' ++ +export { Connection } let uid = 1 @@ -49,7 +63,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d const retryRoutines = new Set([ 'FetchPreparedStatement', 'RevalidateCachedQuery', -@@ -49,7 +66,7 @@ const errorFields = { +@@ -49,7 +79,7 @@ const errorFields = { 82 : 'routine' // R } @@ -58,7 +72,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d const { sslnegotiation, ssl, -@@ -72,12 +89,20 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -72,12 +102,20 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose const sent = Queue() , id = uid++ , backend = { pid: null, secret: null } @@ -83,7 +97,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d , errorResponse = null , result = new Result() , incoming = Buffer.alloc(0) -@@ -86,102 +111,478 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -86,102 +124,509 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose , statements = {} , statementId = Math.random().toString(36).slice(2) , statementCount = 1 @@ -91,6 +105,8 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d , remaining = 0 , hostIndex = 0 - , retries = 0 ++ , serverIndex = 0 ++ , secured = false , length = 0 - , delay = 0 , rows = 0 @@ -232,6 +248,8 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d + get active() { return query ? 1 : 0 }, + get pipelined() { return sent.length }, + get accepting() { return accepting() }, ++ get session() { return session() }, ++ get processID() { return backend.pid }, + get copying() { return stream !== null }, + get copyHeld() { return stream !== null && !stream.writableEnded }, + get acquiring() { return acquisition && acquisition.owner.stage !== Stage.Settled ? 1 : 0 }, @@ -299,12 +317,32 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d + return backoffSeconds(backoff, options.shared.retries) * 1000 + } + ++ function serverAddress() { ++ return options.path || host[serverIndex] ++ } ++ ++ function serverPort() { ++ return options.path ? undefined : port[serverIndex] ++ } ++ ++ function session() { ++ return { host: serverAddress(), port: serverPort(), ssl: secured, processID: backend.pid } ++ } ++ + function standbyPass() { + return target_session_attrs === 'prefer-standby' && host.length > 1 && acquisition.pass === 'standby' + } + + function acquire(owner) { -+ acquisition = { owner, ending: false, pass: 'standby', hostsTried: 0, attempting: null, mismatches: [], lastError: null } ++ acquisition = { owner, ending: false, pass: 'standby', hostsTried: 0, attempting: null, mismatches: [], lastError: null, trace: undefined } ++ if (!watched(connectChannel)) ++ return startAcquisition() ++ ++ acquisition.trace = connectContext(options) ++ run(connectChannel, acquisition.trace, startAcquisition) ++ } ++ ++ function startAcquisition() { + const wait = inheritedBackoff ? inheritedBackoff.at + inheritedBackoff.delay - performance.now() : 0 + inheritedBackoff = null + wait > 0 ? enterBackoff(wait) : enterConnecting() @@ -347,6 +385,9 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d + function attach(created) { + listen(created) + socket = created ++ serverIndex = hostIndex ++ secured = false ++ acquisition.trace && connectAttempt(acquisition.trace, serverAddress(), serverPort()) + acquisition.attempting = options.socket ? 'custom socket' : options.path || host[hostIndex] + ':' + port[hostIndex] + + if (options.socket) @@ -385,13 +426,14 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d + const config = tlsConfig(options, raw) + raw.removeAllListeners() + socket = tls.connect(config) ++ secured = true + socket.on('secureConnect', () => dispatch('secure')) + listen(socket) + } catch (err) { + afterFailure(err, 'protocol') - } - } - ++ } ++ } ++ + function authenticate() { + try { + statements = {} @@ -449,7 +491,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d + + delay = backoffMs() + } -+ } + } + + clearTimeout(attemptTimer) + attemptTimer = null @@ -496,8 +538,10 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d + acquisition = null + endWaiters = [] + transition(Phase.Closed) ++ a && a.trace && publishRejected(connectChannel, a.trace, err) + a && queryError(a.owner, err) + waiters.forEach(resolve => resolve()) ++ poolRemoved(a ? undefined : backend.pid, reported) + onclose(connection, reported) + } + @@ -524,10 +568,11 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d + } + + function handoff() { -+ const { owner, ending } = acquisition ++ const { owner, ending, trace } = acquisition + transition(Phase.Ready) + clearAcquisitionTimers() + acquisition = null ++ trace && (connectSecured(trace, secured), publishResolved(connectChannel, trace)) + options.shared.retries = 0 + lifeTimer.start() + @@ -539,27 +584,27 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d + } + + onopen(connection, owner.stage === Stage.Settled ? undefined : owner) -+ } -+ + } + function execute(q) { - if (terminated) - return queryError(q, Errors.connection('CONNECTION_DESTROYED', options)) + return dispatch('execute', q) + } -+ + +- if (stream) +- return queryError(q, Errors.generic('COPY_IN_PROGRESS', 'You cannot execute queries during copy')) + function submit(q) { + if (stream) { + queryError(q, Errors.generic('COPY_IN_PROGRESS', 'You cannot execute queries during copy')) + return true + } -- if (stream) -- return queryError(q, Errors.generic('COPY_IN_PROGRESS', 'You cannot execute queries during copy')) -+ if (q.cancelled && !connection.owner && max !== 1) -+ return true - - if (q.cancelled) - return ++ if (q.cancelled && !connection.owner && max !== 1) ++ return true ++ + q.owner === undefined && (q.owner = connection.owner) try { @@ -610,7 +655,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d function toBuffer(q) { if (q.parameters.length >= 65534) throw Errors.generic('MAX_PARAMETERS_EXCEEDED', 'Max number of parameters (65534) exceeded') -@@ -206,7 +607,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -206,7 +651,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose function prepared(q) { return Buffer.concat([ @@ -619,7 +664,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d q.cursorFn ? Execute('', q.cursorRows) : ExecuteUnnamed -@@ -234,13 +635,16 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -234,13 +679,17 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose q.signature = q.prepare && types + string q.onlyDescribe && (delete statements[q.signature]) q.parameters = q.parameters || parameters @@ -635,10 +680,11 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d - typeof options.debug === 'function' && options.debug(id, string, parameters, types) + typeof options.debug === 'function' && callback(options.debug, id, string, parameters, types) ++ q.trace && queryBuilt(q, session()) } function write(x, fn) { -@@ -252,52 +656,12 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -252,52 +701,12 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose } function nextWrite(fn) { @@ -692,7 +738,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d function data(x) { if (incomings) { incomings.push(x) -@@ -312,6 +676,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -312,6 +721,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose ? x : Buffer.concat([incoming, x], incoming.length + x.length) @@ -700,7 +746,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d while (incoming.length > 4) { length = incoming.readUInt32BE(1) if (length >= incoming.length) { -@@ -323,138 +688,61 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -323,138 +733,61 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose try { handle(incoming.subarray(0, length + 1)) } catch (e) { @@ -867,7 +913,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d } /* Handlers */ -@@ -495,6 +783,8 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -495,6 +828,8 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose let column let value @@ -876,7 +922,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d const row = query.isRaw ? new Array(query.statement.columns.length) : {} for (let i = 0; i < query.statement.columns.length; i++) { column = query.statement.columns[i] -@@ -514,13 +804,13 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -514,13 +849,13 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose query.isRaw ? (row[i] = query.isRaw === true ? value @@ -894,7 +940,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d } function ParameterStatus(x) { -@@ -528,20 +818,26 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -528,20 +863,26 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose backendParameters[k] = v if (options.parameters[k] !== v) { options.parameters[k] = v @@ -924,7 +970,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d } } else if (errorResponse) { errored(errorResponse) -@@ -549,42 +845,37 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -549,42 +890,38 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose query = results = errorResponse = null result = new Result() @@ -955,17 +1001,18 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d + query = null + return sent.length ? activate(sent.shift()) : null + } - -- while (sent.length && (query = sent.shift()) && (query.active = true, query.cancelled)) -- Connection(options).cancel(query.state, query.cancelled.resolve, query.cancelled.reject) ++ + function activate(q) { + query = q + step(q, Stage.Active) + q.active = true ++ q.pool && poolEnded(q) + q.cancelled && q.cancelled.resolve && cancelRequest(options, q.state).then(q.cancelled.resolve, q.cancelled.reject) + return q + } -+ + +- while (sent.length && (query = sent.shift()) && (query.active = true, query.cancelled)) +- Connection(options).cancel(query.state, query.cancelled.resolve, query.cancelled.reject) + function initialized() { + if (target_session_attrs) { + if (!backendParameters.in_hot_standby || !backendParameters.default_transaction_read_only) @@ -993,7 +1040,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d } function CommandComplete(x) { -@@ -602,7 +893,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -602,7 +939,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose final && (final(), final = null) @@ -1002,7 +1049,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d return errored(Errors.generic('UNSAFE_TRANSACTION', 'Only use sql.begin, sql.reserved or max: 1')) if (query.options.simple) -@@ -619,6 +910,9 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -619,6 +956,9 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose } function BindComplete() { @@ -1012,7 +1059,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d !result.statement && (result.statement = query.statement) result.columns = query.statement.columns } -@@ -654,7 +948,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -654,7 +994,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose const number = x.readUInt16BE(index + 4) const type = x.readUInt32BE(index + 6) query.statement.columns[i] = { @@ -1021,7 +1068,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d ? transform.column.from(x.toString('utf8', start, index - 1)) : x.toString('utf8', start, index - 1), parser: parsers[type], -@@ -667,11 +961,12 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -667,11 +1007,12 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose result.statement = query.statement if (query.onlyDescribe) @@ -1037,7 +1084,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d type === 3 ? AuthenticationCleartextPassword : type === 5 ? AuthenticationMD5Password : type === 10 ? SASL : -@@ -679,18 +974,20 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -679,18 +1020,20 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose type === 12 ? SASLFinal : type !== 0 ? UnknownAuth : noop @@ -1061,7 +1108,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d const payload = 'md5' + ( await md5( Buffer.concat([ -@@ -699,40 +996,42 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -699,40 +1042,42 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose ]) ) ) @@ -1118,7 +1165,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d write( b().p().str(payload).end() ) -@@ -742,8 +1041,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -742,8 +1087,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose if (x.toString('utf8', 9).split(b.N, 1)[0].slice(2) === serverSignature) return /* c8 ignore next 5 */ @@ -1128,7 +1175,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d } function Pass() { -@@ -757,7 +1055,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -757,7 +1101,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose result.statement = query.statement result.statement.columns = [] if (query.onlyDescribe) @@ -1137,7 +1184,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d } function BackendKeyData(x) { -@@ -765,48 +1063,47 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -765,48 +1109,49 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose backend.secret = x.readUInt32BE(9) } @@ -1154,8 +1201,9 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d order by b.oid - `], [], execute) - types.forEach(({ oid, typarray }) => addArrayType(oid, typarray)) -- } -- ++ `, types => types.forEach(({ oid, typarray }) => addArrayType(options, oid, typarray))) + } + - function addArrayType(oid, typarray) { - if (!!options.parsers[typarray] && !!options.serializers[typarray]) return - const parser = options.parsers[oid] @@ -1163,9 +1211,8 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d - options.parsers[typarray] = (xs) => arrayParser(xs, parser, typarray) - options.parsers[typarray].array = true - options.serializers[typarray] = (xs) => arraySerializer(xs, options.serializers[oid], options, typarray) -+ `, types => types.forEach(({ oid, typarray }) => addArrayType(options, oid, typarray))) - } - +- } +- - function tryNext(x, xs) { + function mismatchReason(x, xs) { return ( @@ -1201,15 +1248,17 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d + + function initialize(string, resolve, simple = false) { + const attempt = generation -+ const q = new Query([string], [], q => attempt === generation ++ const run = q => attempt === generation + ? execute(q) -+ : queryError(q, Errors.connection('CONNECTION_CLOSED', options)), null, { simple }) ++ : queryError(q, Errors.connection('CONNECTION_CLOSED', options)) ++ run.options = options ++ const q = new Query([string], [], run, null, { simple }) + q.initialization = resolve + q.catch(noop) } function ErrorResponse(x) { -@@ -814,12 +1111,11 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -814,12 +1159,11 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose (query.cursorFn || query.describeFirst) && write(Sync) errorResponse = Errors.postgres(parseError(x)) } else { @@ -1223,7 +1272,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d q.retried = error execute(q) } -@@ -830,28 +1126,33 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -830,28 +1174,33 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose let index = 9 while (x[index++] !== 0); @@ -1264,7 +1313,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d } function CopyInResponse() { -@@ -862,7 +1163,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -862,7 +1211,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose }, destroy(error, callback) { callback(error) @@ -1273,7 +1322,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d stream = null }, final(callback) { -@@ -871,28 +1172,28 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -871,28 +1220,28 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose stream = null } }) @@ -1307,7 +1356,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d stream = null }, final(callback) { -@@ -900,23 +1201,41 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -900,23 +1249,41 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose final = callback } }) @@ -1353,7 +1402,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d } /* c8 ignore next 3 */ -@@ -945,20 +1264,21 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -945,20 +1312,21 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose } /* Messages */ @@ -1382,7 +1431,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d prev = b.i b.inc(4).str(x).i32(b.i - prev - 4, prev) -@@ -966,7 +1286,27 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -966,7 +1334,27 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose b.i16(0) @@ -1411,7 +1460,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d } function Parse(str, parameters, types, name = '') { -@@ -994,7 +1334,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose +@@ -994,7 +1382,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose } function StartupMessage() { @@ -1420,7 +1469,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d Object.entries(Object.assign({ user, database, -@@ -1019,6 +1359,33 @@ function parseError(x) { +@@ -1019,6 +1407,33 @@ function parseError(x) { return error } @@ -1454,7 +1503,7 @@ index 1b1cccde43b4570d5d071d6ffaab2669b3c2065a..081a31610d6af0b770929e8cac0d461d function md5(x) { return crypto.createHash('md5').update(x).digest('hex') } -@@ -1042,21 +1409,44 @@ function xor(a, b) { +@@ -1042,21 +1457,44 @@ function xor(a, b) { function timer(fn, seconds) { seconds = typeof seconds === 'function' ? seconds() : seconds if (!seconds) @@ -1540,7 +1589,7 @@ index 0ff83c428bec774e11417b8e1f033dc3305c18cf..023c3ba1bd113e6f5508ab079efcf220 code: x, errno: x, diff --git a/src/index.js b/src/index.js -index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b87378acdb 100644 +index c7fba3dace20173f4cb13f3f138bb6d213b43683..808e12d64e3d678246443c8c4ee11453d575c50d 100644 --- a/src/index.js +++ b/src/index.js @@ -3,10 +3,12 @@ import fs from 'fs' @@ -1556,7 +1605,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 toPascal, pascal, toCamel, -@@ -18,13 +20,19 @@ import { +@@ -18,12 +20,32 @@ import { fromKebab } from './types.js' @@ -1571,15 +1620,28 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 +import { Errors, PostgresError, callback } from './errors.js' import Subscribe from './subscribe.js' import largeObject from './large.js' - ++import { ++ transactionChannel, ++ poolConnectChannel, ++ watched, ++ run, ++ traceAsync, ++ transactionContext, ++ transactionSession, ++ transactionCommitted, ++ poolContext, ++ poolSpan, ++ poolHandover, ++ poolReleased ++} from './tracing.js' ++ +const check = globalThis[Symbol.for('postgres.js:check')] +const Lease = { Active: 0, Settling: 1, Released: 2, Ended: 3, Closed: 4 } +const noop = () => { /* noop */ } -+ + Object.assign(Postgres, { PostgresError, - toPascal, -@@ -51,6 +59,7 @@ function Postgres(a, b) { +@@ -51,6 +73,7 @@ function Postgres(a, b) { , subscribe = options.no_subscribe || Subscribe(Postgres, { ...options }) let ending = false @@ -1587,7 +1649,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 const queries = Queue() , connecting = Queue() -@@ -62,7 +71,7 @@ function Postgres(a, b) { +@@ -62,7 +85,7 @@ function Postgres(a, b) { , full = Queue() , queues = { connecting, reserved, closed, ended, open, busy, full } @@ -1596,7 +1658,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 const sql = Sql(handler) -@@ -75,10 +84,12 @@ function Postgres(a, b) { +@@ -75,16 +98,18 @@ function Postgres(a, b) { PostgresError, options, reserve, @@ -1610,8 +1672,19 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 }) return sql -@@ -131,7 +142,7 @@ function Postgres(a, b) { - const query = new Query([], args, (query) => { + + function Sql(handler) { +- handler.debug = options.debug ++ handler.options = options + + Object.entries(options.types).reduce((acc, [name, type]) => { + acc[name] = (x) => new Parameter(x, type.to) +@@ -128,15 +153,17 @@ function Postgres(a, b) { + + function file(path, args = [], options = {}) { + arguments.length === 2 && !Array.isArray(args) && (options = args, args = []) +- const query = new Query([], args, (query) => { ++ const read = query => { fs.readFile(path, 'utf8', (err, string) => { if (err) - return query.reject(err) @@ -1619,7 +1692,15 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 query.strings = [string] handler(query) -@@ -144,6 +155,56 @@ function Postgres(a, b) { + }) +- }, cancel, { ++ } ++ read.options = handler.options ++ const query = new Query([], args, read, cancel, { + ...options, + simple: 'simple' in options ? options.simple : args.length === 0 + }) +@@ -144,6 +171,56 @@ function Postgres(a, b) { } } @@ -1676,7 +1757,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 async function listen(name, fn, onlisten) { const listener = { fn, onlisten } -@@ -153,6 +214,7 @@ function Postgres(a, b) { +@@ -153,6 +230,7 @@ function Postgres(a, b) { idle_timeout: null, max_lifetime: null, fetch_types: false, @@ -1684,7 +1765,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 onclose() { Object.entries(listen.channels).forEach(([name, { listeners }]) => { delete listen.channels[name] -@@ -160,7 +222,7 @@ function Postgres(a, b) { +@@ -160,7 +238,7 @@ function Postgres(a, b) { }) }, onnotify(c, x) { @@ -1693,7 +1774,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 } })) -@@ -170,7 +232,7 @@ function Postgres(a, b) { +@@ -170,7 +248,7 @@ function Postgres(a, b) { if (exists) { channels[name].listeners.push(listener) const result = await channels[name].result @@ -1702,7 +1783,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 return { state: result.state, unlisten } } -@@ -178,7 +240,7 @@ function Postgres(a, b) { +@@ -178,7 +256,7 @@ function Postgres(a, b) { sql.unsafe('"' + name.replace(/"/g, '""') + '"') }`, listeners: [listener] } const result = await channels[name].result @@ -1711,7 +1792,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 return { state: result.state, unlisten } async function unlisten() { -@@ -200,62 +262,159 @@ function Postgres(a, b) { +@@ -200,62 +278,175 @@ function Postgres(a, b) { return await sql`select pg_notify(${ channel }, ${ '' + payload })` } @@ -1727,15 +1808,10 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 + async function lease(auto) { + const l = newLease(auto) + check && check('routed', l) -+ const c = route(l) ++ const c = watched(poolConnectChannel) ? routeTraced(l) : route(l) + if (c && !(c instanceof Error)) + return (assign(c, l, false), l) - -- move(c, reserved) -- c.reserved = () => queue.length -- ? c.execute(queue.shift()) -- : move(c, reserved) -- c.reserved.release = true ++ + if (ending) + throw (fail(l, c), c) + @@ -1753,6 +1829,9 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 + state: null, + connection: null, + error: null, ++ processID: undefined, ++ trace: undefined, ++ pool: undefined, + onclose: null, + queue: Queue(), + auto, @@ -1765,6 +1844,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 + + function own(c, l) { + l.connection = c ++ l.processID = c.processID + l.state = Lease.Active + c.owner = l + l.next = () => { @@ -1793,15 +1873,22 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 + ? Errors.generic('CONNECTION_RELEASED', 'Reserved connection used after release()') + : Errors.generic('TRANSACTION_ENDED', 'Transaction handle used after its transaction ended') + } - -+ function stop(l, state) { ++ ++ function stop(l, state, error) { + if (l.state === Lease.Released || l.state === Lease.Ended) + return null -+ + +- move(c, reserved) +- c.reserved = () => queue.length +- ? c.execute(queue.shift()) +- : move(c, reserved) +- c.reserved.release = true ++ const lost = l.state === Lease.Closed + l.state = state + while (l.queue.length) + fail(l.queue.shift(), leaseError(l)) -+ + ++ poolReleased(l.processID, lost ? l.error : error) + const c = l.connection + if (c.owner !== l) + return null @@ -1834,10 +1921,21 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 } } - async function begin(options, fn) { - !fn && (fn = options, options = '') +- async function begin(options, fn) { +- !fn && (fn = options, options = '') - const queries = Queue() ++ function begin(mode, fn) { ++ !fn && (fn = mode, mode = '') ++ if (!watched(transactionChannel)) ++ return transact(mode, fn) ++ ++ const trace = transactionContext(options, { mode }) ++ return traceAsync(transactionChannel, trace, () => transact(mode, fn, trace)) ++ } ++ ++ async function transact(mode, fn, trace) { + const l = await lease(true) ++ trace && transactionSession(trace, l.connection.session) let savepoints = 0 - , connection , prepare = null @@ -1855,7 +1953,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 + return await Promise.race([work, closing]) + + async function transaction() { -+ await Sql(handler).unsafe('begin ' + options.replace(/[^a-z ]/ig, ''), []).execute().catch(e => { ++ await Sql(handler).unsafe('begin ' + mode.replace(/[^a-z ]/ig, ''), []).execute().catch(e => { + e instanceof PostgresError && release() + throw e + }) @@ -1868,7 +1966,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 + try { + result = await statement(Sql(q => handler(q, Lease.Settling))) + } catch (e) { -+ terminate() ++ terminate(e) + throw e + } + release() @@ -1878,15 +1976,15 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 + function release() { + const c = stop(l, Lease.Ended) + c && c.release() -+ } -+ -+ function terminate() { -+ const c = stop(l, Lease.Ended) -+ c && c.terminate() } - async function scope(c, fn, name) { - const sql = Sql(handler) ++ function terminate(error) { ++ const c = stop(l, Lease.Ended, error) ++ c && c.terminate() ++ } ++ + async function scope(fn, name) { + const sql = Sql(track) sql.savepoint = savepoint @@ -1896,6 +1994,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 + throw Errors.generic('INVALID_TRANSACTION_NAME', 'sql.prepare requires a non-empty string without null bytes') + + prepare = 'E\'' + x.replace(/\\/g, '\\\\').replace(/'/g, '\'\'') + '\'' ++ trace && (trace.prepared = x) + } let uncaughtError , result @@ -1905,7 +2004,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 try { result = await new Promise((resolve, reject) => { const x = fn(sql) -@@ -265,17 +424,27 @@ function Postgres(a, b) { +@@ -265,17 +456,29 @@ function Postgres(a, b) { if (uncaughtError) throw uncaughtError } catch (e) { @@ -1936,15 +2035,20 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 + uncaughtError && { cause: uncaughtError } + ) + } ++ ++ trace && transactionCommitted(trace, prepare === null) } return result -@@ -285,23 +454,18 @@ function Postgres(a, b) { +@@ -285,23 +488,21 @@ function Postgres(a, b) { return savepoint(sql => sql.apply(sql, arguments)) arguments.length === 1 && (fn = name, name = null) - return scope(c, fn, 's' + savepoints++ + (name ? '_' + name : '')) -+ return scope(fn, 's' + savepoints++ + (name ? '_' + name : '')) ++ const id = 's' + savepoints++ + (name ? '_' + name : '') ++ return watched(transactionChannel) ++ ? traceAsync(transactionChannel, transactionContext(options, { savepoint: id, session: l.connection.session }), () => scope(fn, id)) ++ : scope(fn, id) } - function handler(q) { @@ -1969,7 +2073,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 } } -@@ -310,7 +474,7 @@ function Postgres(a, b) { +@@ -310,7 +511,7 @@ function Postgres(a, b) { queue.push(c) c.queue = queue queue === open @@ -1978,11 +2082,13 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 : c.idleTimer.cancel() return c } -@@ -327,38 +491,101 @@ function Postgres(a, b) { +@@ -327,38 +528,110 @@ function Postgres(a, b) { } function handler(query) { -+ const c = route(query) ++ const c = query.trace && watched(poolConnectChannel) ++ ? routeTraced(query) ++ : route(query) + if (c === null) + return + @@ -1991,6 +2097,12 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 + : go(c, query) + } + ++ function routeTraced(r) { ++ const context = poolContext(stats()) ++ poolSpan(r, context) ++ return run(poolConnectChannel, context, route, r) ++ } ++ + function route(r) { if (ending) - return query.reject(Errors.connection('CONNECTION_ENDED', options, options)) @@ -2020,12 +2132,10 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 + queries.push(r) + return null + } - -- busy.length -- ? go(busy.shift(), query) -- : queries.push(query) ++ + function assign(c, r, fresh) { + check && check('handover', r, fresh, c.active + c.pipelined) ++ r.pool && poolHandover(r, c, fresh) + if (!r.reserve) + return c.execute(r) + @@ -2036,7 +2146,10 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 + function allHeldByCopy() { + return connections.every(c => c.copyHeld) + } -+ + +- busy.length +- ? go(busy.shift(), query) +- : queries.push(query) + function copyInProgress() { + return Errors.generic('COPY_IN_PROGRESS', 'You cannot execute queries during copy') + } @@ -2098,7 +2211,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 }) } -@@ -368,13 +595,23 @@ function Postgres(a, b) { +@@ -368,13 +641,23 @@ function Postgres(a, b) { await 1 let timer @@ -2129,7 +2242,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 } async function close() { -@@ -382,15 +619,16 @@ function Postgres(a, b) { +@@ -382,15 +665,16 @@ function Postgres(a, b) { } async function destroy(resolve) { @@ -2150,7 +2263,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 return c } -@@ -398,19 +636,25 @@ function Postgres(a, b) { +@@ -398,19 +682,25 @@ function Postgres(a, b) { move(c, ended) } @@ -2181,7 +2294,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 } ready -@@ -418,12 +662,60 @@ function Postgres(a, b) { +@@ -418,12 +708,60 @@ function Postgres(a, b) { : move(c, full) } @@ -2246,7 +2359,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 } } -@@ -453,16 +745,17 @@ function parseOptions(a, b) { +@@ -453,16 +791,17 @@ function parseOptions(a, b) { connect_timeout : 30, max_lifetime : max_lifetime, max_pipeline : 100, @@ -2266,7 +2379,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 host : Array.isArray(host) ? host : host.split(',').map(x => x.split(':')[0]), port : Array.isArray(port) ? port : host.split(',').map(x => parseInt(x.split(':')[1] || port)), path : o.path || host.indexOf('/') > -1 && host + '/.s.PGSQL.' + port, -@@ -472,8 +765,8 @@ function parseOptions(a, b) { +@@ -472,8 +811,8 @@ function parseOptions(a, b) { ...Object.entries(defaults).reduce( (acc, [k, d]) => { const value = k in o ? o[k] : k in query @@ -2277,7 +2390,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 acc[k] = typeof value === 'string' && ints.includes(k) ? +value : value -@@ -488,16 +781,26 @@ function parseOptions(a, b) { +@@ -488,16 +827,26 @@ function parseOptions(a, b) { }, types : o.types || {}, target_session_attrs: tsa(o, url, env), @@ -2305,7 +2418,7 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 } function tsa(o, url, env) { -@@ -508,8 +811,12 @@ function tsa(o, url, env) { +@@ -508,8 +857,12 @@ function tsa(o, url, env) { throw new Error('target_session_attrs ' + x + ' is not supported') } @@ -2321,10 +2434,14 @@ index c7fba3dace20173f4cb13f3f138bb6d213b43683..def166dbcac16bf0ccdd7516f3f5b0b8 function max_lifetime() { diff --git a/src/query.js b/src/query.js -index 0d44a15cd9e42beaf11d4be6ccde60223e09508a..ccaa913747ef7da487f65712166038a254d4ffc9 100644 +index 0d44a15cd9e42beaf11d4be6ccde60223e09508a..62d6927aeceb5071d16dbcced2833dd31b34ab1d 100644 --- a/src/query.js +++ b/src/query.js -@@ -3,6 +3,38 @@ const originCache = new Map() +@@ -1,8 +1,44 @@ ++import { queryChannel, watched, traceQuery, traceSucceeded, traceFailed } from './tracing.js' ++ + const originCache = new Map() + , originStackCache = new Map() , originError = Symbol('OriginError') export const CLOSE = {} @@ -2348,6 +2465,7 @@ index 0d44a15cd9e42beaf11d4be6ccde60223e09508a..ccaa913747ef7da487f65712166038a2 + + check && check('requestSettled', r, stageNames[r.stage]) + r.stage = Stage.Settled ++ r.trace && traceSucceeded(r, value) + r.resolve(value) +} + @@ -2357,13 +2475,14 @@ index 0d44a15cd9e42beaf11d4be6ccde60223e09508a..ccaa913747ef7da487f65712166038a2 + + check && check('requestSettled', r, stageNames[r.stage]) + r.stage = Stage.Settled ++ r.trace && traceFailed(r, error) + r.reject(error) +} + export class Query extends Promise { constructor(strings, args, handler, canceller, options = {}) { let resolve -@@ -22,11 +54,14 @@ export class Query extends Promise { +@@ -22,22 +58,27 @@ export class Query extends Promise { this.state = null this.statement = null @@ -2379,8 +2498,23 @@ index 0d44a15cd9e42beaf11d4be6ccde60223e09508a..ccaa913747ef7da487f65712166038a2 + this.settled = false this.cancelled = null this.executed = false ++ this.trace = undefined ++ this.pool = undefined this.signature = '' -@@ -50,7 +85,14 @@ export class Query extends Promise { + +- this[originError] = this.handler.debug ++ this[originError] = this.handler.options.debug + ? new Error() + : this.tagged && cachedError(this.strings) + } + + get origin() { +- return (this.handler.debug ++ return (this.handler.options.debug + ? this[originError].stack + : this.tagged && originStackCache.has(this.strings) + ? originStackCache.get(this.strings) +@@ -50,7 +91,14 @@ export class Query extends Promise { } cancel() { @@ -2396,15 +2530,36 @@ index 0d44a15cd9e42beaf11d4be6ccde60223e09508a..ccaa913747ef7da487f65712166038a2 } simple() { -@@ -137,7 +179,7 @@ export class Query extends Promise { +@@ -136,8 +184,14 @@ export class Query extends Promise { + return this } - async handle() { +- async handle() { - !this.executed && (this.executed = true) && await 1 && this.handler(this) -+ !this.executed && (this.executed = true) && await 1 && (check && check('routed', this), this.handler(this)) ++ handle() { ++ if (this.executed) ++ return ++ ++ this.executed = true ++ return watched(queryChannel) && this.stage === Stage.New && !this.initialization ++ ? traceQuery(this, dispatch) ++ : dispatch(this) } execute() { +@@ -161,6 +215,12 @@ export class Query extends Promise { + } + } + ++async function dispatch(q) { ++ await 1 ++ check && check('routed', q) ++ q.handler(q) ++} ++ + function cachedError(xs) { + if (originCache.has(xs)) + return originCache.get(xs) diff --git a/src/subscribe.js b/src/subscribe.js index 4f8934cc8277fc58d2c37838cfb1afc315bc0744..0fd5d4201123e4c08d85fd1c46396baa60ba53cf 100644 --- a/src/subscribe.js @@ -2719,6 +2874,162 @@ index 0000000000000000000000000000000000000000..bcdf4c1894e0f84957d7ff3890bea9d8 +export default function clampedTimeout(fn, ms) { + return setTimeout(fn, Math.min(ms, maxDelay)) +} +diff --git a/src/tracing.js b/src/tracing.js +new file mode 100644 +index 0000000000000000000000000000000000000000..d1ee363ad9776abb87b4b07f444fa3f7a12fb1fe +--- /dev/null ++++ b/src/tracing.js +@@ -0,0 +1,150 @@ ++import dc from 'diagnostics_channel' ++import { performance } from 'perf_hooks' ++ ++const supported = Boolean(dc) && typeof dc.tracingChannel === 'function' ++ ++export const queryChannel = supported ? dc.tracingChannel('postgres:query') : undefined ++export const connectChannel = supported ? dc.tracingChannel('postgres:connect') : undefined ++export const transactionChannel = supported ? dc.tracingChannel('postgres:transaction') : undefined ++export const poolConnectChannel = supported ? dc.tracingChannel('postgres:pool:connect') : undefined ++const poolReleaseChannel = supported ? dc.channel('postgres:pool:release') : undefined ++const poolRemoveChannel = supported ? dc.channel('postgres:pool:remove') : undefined ++ ++export function watched(channel) { ++ return channel !== undefined && (channel.hasSubscribers ?? channel.start.hasSubscribers) ++} ++ ++export function run(channel, context, fn, ...args) { ++ try { ++ return channel.start.runStores(context, fn, undefined, ...args) ++ } finally { ++ channel.end.publish(context) ++ } ++} ++ ++export function publishResolved(channel, context) { ++ channel.asyncStart.publish(context) ++ channel.asyncEnd.publish(context) ++} ++ ++export function publishRejected(channel, context, error) { ++ context.error = error ++ channel.error.publish(context) ++ publishResolved(channel, context) ++} ++ ++export function traceAsync(channel, context, fn) { ++ return run(channel, context, fn).then( ++ result => (publishResolved(channel, context), result), ++ error => { ++ publishRejected(channel, context, error) ++ throw error ++ } ++ ) ++} ++ ++function serverOf({ host, port, path }) { ++ return path ++ ? { host: path, port: undefined } ++ : host && host.length === 1 ++ ? { host: host[0], port: port[0] } ++ : { host: undefined, port: undefined } ++} ++ ++function clientOf(config) { ++ return { database: config.database, ...serverOf(config), user: config.user, ssl: Boolean(config.ssl), processID: undefined } ++} ++ ++export function connectContext(config) { ++ const { database, host, port, user, ssl } = clientOf(config) ++ return { connection: { database, host, port, user, ssl } } ++} ++ ++export function connectAttempt(context, host, port) { ++ context.connection.host = host ++ context.connection.port = port ++} ++ ++export function connectSecured(context, ssl) { ++ context.connection.ssl = ssl ++} ++ ++export function transactionContext(config, { mode, savepoint, session }) { ++ return { client: { ...clientOf(config), ...session }, options: mode, savepoint, prepared: undefined } ++} ++ ++export function transactionSession(context, session) { ++ Object.assign(context.client, session) ++} ++ ++export function transactionCommitted(context, committed) { ++ context.result = { committed } ++} ++ ++export function poolContext({ totalCount, idleCount, waitingCount, max }) { ++ return { pool: { totalCount, idleCount, waitingCount, maxSize: max } } ++} ++ ++export function poolSpan(r, context) { ++ r.pool = context ++ r.reserve && (r.trace = true) ++} ++ ++export function poolHandover(r, c, fresh) { ++ const context = r.pool ++ context.handoverTime = performance.timeOrigin + performance.now() ++ context.queuedBehind = c.active + c.pipelined ++ context.client = { processID: c.processID, reused: !fresh } ++} ++ ++export function poolEnded(r) { ++ const context = r.pool ++ r.pool = undefined ++ publishResolved(poolConnectChannel, context) ++} ++ ++function poolFailed(r, error) { ++ const context = r.pool ++ r.pool = undefined ++ context.handoverTime === undefined ++ ? publishRejected(poolConnectChannel, context, error) ++ : publishResolved(poolConnectChannel, context) ++} ++ ++export function poolReleased(processID, error) { ++ watched(poolReleaseChannel) && poolReleaseChannel.publish({ client: { processID }, error }) ++} ++ ++export function poolRemoved(processID, error) { ++ watched(poolRemoveChannel) && poolRemoveChannel.publish({ client: { processID }, error }) ++} ++ ++export function traceQuery(q, fn) { ++ q.trace = { query: { text: undefined, name: undefined }, client: clientOf(q.handler.options) } ++ return run(queryChannel, q.trace, fn, q) ++} ++ ++export function queryBuilt(q, session) { ++ const context = q.trace ++ context.query.text = q.string ++ context.query.name = q.statement.name || undefined ++ Object.assign(context.client, session) ++} ++ ++export function traceSucceeded(r, value) { ++ r.pool && poolEnded(r) ++ const context = r.trace ++ r.trace = undefined ++ if (r.reserve) ++ return ++ ++ context.result = value ++ publishResolved(queryChannel, context) ++} ++ ++export function traceFailed(r, error) { ++ r.pool && poolFailed(r, error) ++ const context = r.trace ++ r.trace = undefined ++ r.reserve || publishRejected(queryChannel, context, error) ++} diff --git a/src/transport.js b/src/transport.js new file mode 100644 index 0000000000000000000000000000000000000000..990ba27822fbfaca189a3a973c87ba10e58f1ec2 @@ -2949,7 +3260,7 @@ index 0000000000000000000000000000000000000000..e8a4bddf7c0f4b6c55ec7c5f33865888 + } +} diff --git a/types/index.d.ts b/types/index.d.ts -index 13c3432f761e2c2ee5b7dc1bdafe93e49f993dc7..7574d4b038b922d31236b0e9bfc3d27f5d18fe75 100644 +index 13c3432f761e2c2ee5b7dc1bdafe93e49f993dc7..805307527402ef0237ab7bdbec785192ea81915b 100644 --- a/types/index.d.ts +++ b/types/index.d.ts @@ -1,4 +1,4 @@ @@ -3131,8 +3442,92 @@ index 13c3432f761e2c2ee5b7dc1bdafe93e49f993dc7..7574d4b038b922d31236b0e9bfc3d27f } interface TransactionSql = {}> extends ISql { -@@ -729,6 +800,12 @@ declare namespace postgres { - +@@ -727,8 +798,96 @@ declare namespace postgres { + prepare(name: string): Promise>; + } + ++ /** The connection a traced call runs on. Host, port and ssl are those of the connection once it is known. */ ++ interface TraceClient { ++ database: string; ++ host: string | undefined; ++ port: number | undefined; ++ user: string; ++ ssl: boolean; ++ /** Backend process id; set once the call is written to a connection */ ++ processID: number | undefined; ++ } ++ ++ /** Context of the `postgres:query` tracing channel. `query` and the connection fields of `client` are set when the query is written to a connection, after `start`. */ ++ interface QueryTraceContext { ++ query: { ++ /** SQL text with `$n` placeholders as sent to the server */ ++ text: string | undefined; ++ /** Prepared statement name; undefined for an unnamed statement */ ++ name: string | undefined; ++ }; ++ client: TraceClient; ++ /** Set before `asyncStart` when the query succeeded: the `Result`, one for each statement of a multi-statement simple query, the statement for `describe()`, or for a `COPY` the `Result` of the finished copy */ ++ result?: ResultMeta | ResultMeta[] | Statement; ++ /** Set before `error` when the query failed: the query's own rejection, which can be any thrown value */ ++ error?: unknown; ++ } ++ ++ /** Context of the `postgres:connect` tracing channel, one span for each connection acquisition. */ ++ interface ConnectTraceContext { ++ connection: Omit; ++ error?: Error; ++ } ++ ++ /** Context of the `postgres:pool:connect` tracing channel: every wait for a connection, for `sql.reserve()`, `sql.begin()` and plain pooled queries. */ ++ interface PoolConnectTraceContext { ++ pool: { ++ totalCount: number; ++ idleCount: number; ++ waitingCount: number; ++ maxSize: number; ++ }; ++ /** Epoch milliseconds at which the connection took the call over; set before `asyncStart` once a connection took the call over. `handoverTime` minus the `start` time is the wait for a connection. */ ++ handoverTime?: number; ++ /** Queries the connection already had running or waiting when it took this one over. For a plain query, the time from `handoverTime` to `asyncStart` is spent behind them; a lease span ends at the hand-over, so that time falls inside its first statement. */ ++ queuedBehind?: number; ++ /** Set with `handoverTime` */ ++ client?: { ++ processID: number | undefined; ++ /** False when the acquisition had to open the connection */ ++ reused: boolean; ++ }; ++ /** Set before `error`: why the wait failed, or the error of a request that failed before a connection took it over */ ++ error?: unknown; ++ } ++ ++ /** Context of the `postgres:transaction` tracing channel, for `sql.begin()` and `sql.savepoint()`. */ ++ interface TransactionTraceContext { ++ client: TraceClient; ++ /** The mode string passed to `sql.begin()`; undefined for a savepoint */ ++ options: string | undefined; ++ /** The savepoint name as sent to the server; undefined for `sql.begin()` */ ++ savepoint: string | undefined; ++ /** The name given to `sql.prepare()` */ ++ prepared: string | undefined; ++ /** Set by `sql.begin()` on success: `committed` is false when the transaction was prepared */ ++ result?: { committed: boolean }; ++ error?: unknown; ++ } ++ ++ /** Message of the `postgres:pool:release` channel. */ ++ interface PoolReleaseMessage { ++ client: { processID: number | undefined }; ++ /** Why the connection was terminated instead of returned healthy, such as a failed commit or a lost connection; undefined otherwise, including after a transaction that rolled back cleanly */ ++ error: Error | undefined; ++ } ++ ++ /** Message of the `postgres:pool:remove` channel. */ ++ interface PoolRemoveMessage { ++ client: { processID: number | undefined }; ++ /** The error that closed the connection; undefined for a normal close */ ++ error: Error | undefined; ++ } ++ interface ReservedSql = {}> extends Sql { release(): void; + diff --git a/docs/lifecycle.md b/docs/lifecycle.md index 68245b7b..80e3dae0 100644 --- a/docs/lifecycle.md +++ b/docs/lifecycle.md @@ -260,6 +260,21 @@ The connection drives its own queue through four callbacks: `Query.cancel()` returns a promise that settles when the CancelRequest finishes. A CancelRequest opens its own socket and is not a connection; it does not go through any phase or pool queue. +## Tracing + +`src/tracing.js` owns the `diagnostics_channel` channels; the channels and payloads are described in `docs/api.md`. Every hook sits on one transition above, and a request carries tracing state only while a subscriber watched its channel when it started: `trace` (a query's `postgres:query` context, or `true` on a lease) and `pool` (the `postgres:pool:connect` context, held until the query is Active or the lease is handed over, or the request fails first). + +| Channel | Opens | Gets its fields | Settles | +|---|---|---|---| +| `postgres:query` | `Query.handle()`, when the query is New | `build()` (text, name, session) | `succeed` / `fail` | +| `postgres:pool:connect` | `handler()` for a traced query, `lease()` for a lease, around `route()` | `assign()` (`handoverTime`, `queuedBehind`, `client`) | `activate()` for a query; `succeed` for a lease; `fail`: rejected when the request never reached a connection, resolved when it was already handed over | +| `postgres:connect` | `acquire()` | `attach()`, `upgrade()` | `handoff()` or `enterClosed()` | +| `postgres:transaction` | `begin()` and `savepoint()` | when the lease is taken | when the function settles | +| `postgres:pool:release` | `stop()` | | | +| `postgres:pool:remove` | `enterClosed()` | | | + +Because `route` never settles or activates a request, a pool span's `end` is always published before anything can settle it, and a failing request settles its pool span before its query span (resolving it when the hand-over happened). The COPY hand-out is not a settlement, so a COPY query's span ends at its second resolve. Untraced, a query costs one `hasSubscribers` check in `handle()` and a field read in each of `handler()` (`trace`), `build()` (`trace`), `succeed` and `fail` (`trace`), `assign()` (`pool`) and `activate()` (`pool`), and allocates nothing. A lease adds one check in `lease()` and one read of the connection's process id in `own()`; a connection adds one check per acquisition, and one per release and per close. + ## Test hook `globalThis[Symbol.for('postgres.js:check')]` is read once when a connection is created. When it is unset, each reporting site costs one falsy check. When it is set, the connection calls `check(kind, connection, a, b)`: diff --git a/src/connection.js b/src/connection.js index 081a3161..777f05e0 100644 --- a/src/connection.js +++ b/src/connection.js @@ -12,6 +12,19 @@ import clampedTimeout from './timeout.js' import { SSLRequest, tlsConfig, cancelRequest } from './transport.js' import { Query, CLOSE, Stage, step, succeed, fail } from './query.js' import b from './bytes.js' +import { + connectChannel, + watched, + run, + publishResolved, + publishRejected, + connectContext, + connectAttempt, + connectSecured, + queryBuilt, + poolEnded, + poolRemoved +} from './tracing.js' export { Connection } @@ -113,6 +126,8 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose , statementCount = 1 , remaining = 0 , hostIndex = 0 + , serverIndex = 0 + , secured = false , length = 0 , rows = 0 , copyPaused = false @@ -243,6 +258,8 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose get active() { return query ? 1 : 0 }, get pipelined() { return sent.length }, get accepting() { return accepting() }, + get session() { return session() }, + get processID() { return backend.pid }, get copying() { return stream !== null }, get copyHeld() { return stream !== null && !stream.writableEnded }, get acquiring() { return acquisition && acquisition.owner.stage !== Stage.Settled ? 1 : 0 }, @@ -297,12 +314,32 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose return backoffSeconds(backoff, options.shared.retries) * 1000 } + function serverAddress() { + return options.path || host[serverIndex] + } + + function serverPort() { + return options.path ? undefined : port[serverIndex] + } + + function session() { + return { host: serverAddress(), port: serverPort(), ssl: secured, processID: backend.pid } + } + function standbyPass() { return target_session_attrs === 'prefer-standby' && host.length > 1 && acquisition.pass === 'standby' } function acquire(owner) { - acquisition = { owner, ending: false, pass: 'standby', hostsTried: 0, attempting: null, mismatches: [], lastError: null } + acquisition = { owner, ending: false, pass: 'standby', hostsTried: 0, attempting: null, mismatches: [], lastError: null, trace: undefined } + if (!watched(connectChannel)) + return startAcquisition() + + acquisition.trace = connectContext(options) + run(connectChannel, acquisition.trace, startAcquisition) + } + + function startAcquisition() { const wait = inheritedBackoff ? inheritedBackoff.at + inheritedBackoff.delay - performance.now() : 0 inheritedBackoff = null wait > 0 ? enterBackoff(wait) : enterConnecting() @@ -345,6 +382,9 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose function attach(created) { listen(created) socket = created + serverIndex = hostIndex + secured = false + acquisition.trace && connectAttempt(acquisition.trace, serverAddress(), serverPort()) acquisition.attempting = options.socket ? 'custom socket' : options.path || host[hostIndex] + ':' + port[hostIndex] if (options.socket) @@ -377,6 +417,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose const config = tlsConfig(options, raw) raw.removeAllListeners() socket = tls.connect(config) + secured = true socket.on('secureConnect', () => dispatch('secure')) listen(socket) } catch (err) { @@ -488,8 +529,10 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose acquisition = null endWaiters = [] transition(Phase.Closed) + a && a.trace && publishRejected(connectChannel, a.trace, err) a && queryError(a.owner, err) waiters.forEach(resolve => resolve()) + poolRemoved(a ? undefined : backend.pid, reported) onclose(connection, reported) } @@ -516,10 +559,11 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose } function handoff() { - const { owner, ending } = acquisition + const { owner, ending, trace } = acquisition transition(Phase.Ready) clearAcquisitionTimers() acquisition = null + trace && (connectSecured(trace, secured), publishResolved(connectChannel, trace)) options.shared.retries = 0 lifeTimer.start() @@ -645,6 +689,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose : { string, types, name: q.prepare ? statementId + statementCount++ : '' } typeof options.debug === 'function' && callback(options.debug, id, string, parameters, types) + q.trace && queryBuilt(q, session()) } function write(x, fn) { @@ -859,6 +904,7 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose query = q step(q, Stage.Active) q.active = true + q.pool && poolEnded(q) q.cancelled && q.cancelled.resolve && cancelRequest(options, q.state).then(q.cancelled.resolve, q.cancelled.reject) return q } @@ -1099,9 +1145,11 @@ function Connection(options, queues = {}, { onopen = noop, onend = noop, onclose function initialize(string, resolve, simple = false) { const attempt = generation - const q = new Query([string], [], q => attempt === generation + const run = q => attempt === generation ? execute(q) - : queryError(q, Errors.connection('CONNECTION_CLOSED', options)), null, { simple }) + : queryError(q, Errors.connection('CONNECTION_CLOSED', options)) + run.options = options + const q = new Query([string], [], run, null, { simple }) q.initialization = resolve q.catch(noop) } diff --git a/src/index.js b/src/index.js index def166db..808e12d6 100644 --- a/src/index.js +++ b/src/index.js @@ -28,6 +28,20 @@ import Queue from './queue.js' import { Errors, PostgresError, callback } from './errors.js' import Subscribe from './subscribe.js' import largeObject from './large.js' +import { + transactionChannel, + poolConnectChannel, + watched, + run, + traceAsync, + transactionContext, + transactionSession, + transactionCommitted, + poolContext, + poolSpan, + poolHandover, + poolReleased +} from './tracing.js' const check = globalThis[Symbol.for('postgres.js:check')] const Lease = { Active: 0, Settling: 1, Released: 2, Ended: 3, Closed: 4 } @@ -95,7 +109,7 @@ function Postgres(a, b) { return sql function Sql(handler) { - handler.debug = options.debug + handler.options = options Object.entries(options.types).reduce((acc, [name, type]) => { acc[name] = (x) => new Parameter(x, type.to) @@ -139,7 +153,7 @@ function Postgres(a, b) { function file(path, args = [], options = {}) { arguments.length === 2 && !Array.isArray(args) && (options = args, args = []) - const query = new Query([], args, (query) => { + const read = query => { fs.readFile(path, 'utf8', (err, string) => { if (err) return fail(query, err) @@ -147,7 +161,9 @@ function Postgres(a, b) { query.strings = [string] handler(query) }) - }, cancel, { + } + read.options = handler.options + const query = new Query([], args, read, cancel, { ...options, simple: 'simple' in options ? options.simple : args.length === 0 }) @@ -265,7 +281,7 @@ function Postgres(a, b) { async function lease(auto) { const l = newLease(auto) check && check('routed', l) - const c = route(l) + const c = watched(poolConnectChannel) ? routeTraced(l) : route(l) if (c && !(c instanceof Error)) return (assign(c, l, false), l) @@ -286,6 +302,9 @@ function Postgres(a, b) { state: null, connection: null, error: null, + processID: undefined, + trace: undefined, + pool: undefined, onclose: null, queue: Queue(), auto, @@ -298,6 +317,7 @@ function Postgres(a, b) { function own(c, l) { l.connection = c + l.processID = c.processID l.state = Lease.Active c.owner = l l.next = () => { @@ -327,14 +347,16 @@ function Postgres(a, b) { : Errors.generic('TRANSACTION_ENDED', 'Transaction handle used after its transaction ended') } - function stop(l, state) { + function stop(l, state, error) { if (l.state === Lease.Released || l.state === Lease.Ended) return null + const lost = l.state === Lease.Closed l.state = state while (l.queue.length) fail(l.queue.shift(), leaseError(l)) + poolReleased(l.processID, lost ? l.error : error) const c = l.connection if (c.owner !== l) return null @@ -361,9 +383,18 @@ function Postgres(a, b) { } } - async function begin(options, fn) { - !fn && (fn = options, options = '') + function begin(mode, fn) { + !fn && (fn = mode, mode = '') + if (!watched(transactionChannel)) + return transact(mode, fn) + + const trace = transactionContext(options, { mode }) + return traceAsync(transactionChannel, trace, () => transact(mode, fn, trace)) + } + + async function transact(mode, fn, trace) { const l = await lease(true) + trace && transactionSession(trace, l.connection.session) let savepoints = 0 , prepare = null @@ -372,7 +403,7 @@ function Postgres(a, b) { return await Promise.race([work, closing]) async function transaction() { - await Sql(handler).unsafe('begin ' + options.replace(/[^a-z ]/ig, ''), []).execute().catch(e => { + await Sql(handler).unsafe('begin ' + mode.replace(/[^a-z ]/ig, ''), []).execute().catch(e => { e instanceof PostgresError && release() throw e }) @@ -385,7 +416,7 @@ function Postgres(a, b) { try { result = await statement(Sql(q => handler(q, Lease.Settling))) } catch (e) { - terminate() + terminate(e) throw e } release() @@ -397,8 +428,8 @@ function Postgres(a, b) { c && c.release() } - function terminate() { - const c = stop(l, Lease.Ended) + function terminate(error) { + const c = stop(l, Lease.Ended, error) c && c.terminate() } @@ -410,6 +441,7 @@ function Postgres(a, b) { throw Errors.generic('INVALID_TRANSACTION_NAME', 'sql.prepare requires a non-empty string without null bytes') prepare = 'E\'' + x.replace(/\\/g, '\\\\').replace(/'/g, '\'\'') + '\'' + trace && (trace.prepared = x) } let uncaughtError , result @@ -445,6 +477,8 @@ function Postgres(a, b) { uncaughtError && { cause: uncaughtError } ) } + + trace && transactionCommitted(trace, prepare === null) } return result @@ -454,7 +488,10 @@ function Postgres(a, b) { return savepoint(sql => sql.apply(sql, arguments)) arguments.length === 1 && (fn = name, name = null) - return scope(fn, 's' + savepoints++ + (name ? '_' + name : '')) + const id = 's' + savepoints++ + (name ? '_' + name : '') + return watched(transactionChannel) + ? traceAsync(transactionChannel, transactionContext(options, { savepoint: id, session: l.connection.session }), () => scope(fn, id)) + : scope(fn, id) } function track(q) { @@ -491,7 +528,9 @@ function Postgres(a, b) { } function handler(query) { - const c = route(query) + const c = query.trace && watched(poolConnectChannel) + ? routeTraced(query) + : route(query) if (c === null) return @@ -500,6 +539,12 @@ function Postgres(a, b) { : go(c, query) } + function routeTraced(r) { + const context = poolContext(stats()) + poolSpan(r, context) + return run(poolConnectChannel, context, route, r) + } + function route(r) { if (ending) return Errors.connection('CONNECTION_ENDED', options, options) @@ -528,6 +573,7 @@ function Postgres(a, b) { function assign(c, r, fresh) { check && check('handover', r, fresh, c.active + c.pipelined) + r.pool && poolHandover(r, c, fresh) if (!r.reserve) return c.execute(r) diff --git a/src/query.js b/src/query.js index ccaa9137..62d6927a 100644 --- a/src/query.js +++ b/src/query.js @@ -1,3 +1,5 @@ +import { queryChannel, watched, traceQuery, traceSucceeded, traceFailed } from './tracing.js' + const originCache = new Map() , originStackCache = new Map() , originError = Symbol('OriginError') @@ -23,6 +25,7 @@ export function succeed(r, value) { check && check('requestSettled', r, stageNames[r.stage]) r.stage = Stage.Settled + r.trace && traceSucceeded(r, value) r.resolve(value) } @@ -32,6 +35,7 @@ export function fail(r, error) { check && check('requestSettled', r, stageNames[r.stage]) r.stage = Stage.Settled + r.trace && traceFailed(r, error) r.reject(error) } @@ -64,15 +68,17 @@ export class Query extends Promise { this.settled = false this.cancelled = null this.executed = false + this.trace = undefined + this.pool = undefined this.signature = '' - this[originError] = this.handler.debug + this[originError] = this.handler.options.debug ? new Error() : this.tagged && cachedError(this.strings) } get origin() { - return (this.handler.debug + return (this.handler.options.debug ? this[originError].stack : this.tagged && originStackCache.has(this.strings) ? originStackCache.get(this.strings) @@ -178,8 +184,14 @@ export class Query extends Promise { return this } - async handle() { - !this.executed && (this.executed = true) && await 1 && (check && check('routed', this), this.handler(this)) + handle() { + if (this.executed) + return + + this.executed = true + return watched(queryChannel) && this.stage === Stage.New && !this.initialization + ? traceQuery(this, dispatch) + : dispatch(this) } execute() { @@ -203,6 +215,12 @@ export class Query extends Promise { } } +async function dispatch(q) { + await 1 + check && check('routed', q) + q.handler(q) +} + function cachedError(xs) { if (originCache.has(xs)) return originCache.get(xs) diff --git a/src/tracing.js b/src/tracing.js new file mode 100644 index 00000000..d1ee363a --- /dev/null +++ b/src/tracing.js @@ -0,0 +1,150 @@ +import dc from 'diagnostics_channel' +import { performance } from 'perf_hooks' + +const supported = Boolean(dc) && typeof dc.tracingChannel === 'function' + +export const queryChannel = supported ? dc.tracingChannel('postgres:query') : undefined +export const connectChannel = supported ? dc.tracingChannel('postgres:connect') : undefined +export const transactionChannel = supported ? dc.tracingChannel('postgres:transaction') : undefined +export const poolConnectChannel = supported ? dc.tracingChannel('postgres:pool:connect') : undefined +const poolReleaseChannel = supported ? dc.channel('postgres:pool:release') : undefined +const poolRemoveChannel = supported ? dc.channel('postgres:pool:remove') : undefined + +export function watched(channel) { + return channel !== undefined && (channel.hasSubscribers ?? channel.start.hasSubscribers) +} + +export function run(channel, context, fn, ...args) { + try { + return channel.start.runStores(context, fn, undefined, ...args) + } finally { + channel.end.publish(context) + } +} + +export function publishResolved(channel, context) { + channel.asyncStart.publish(context) + channel.asyncEnd.publish(context) +} + +export function publishRejected(channel, context, error) { + context.error = error + channel.error.publish(context) + publishResolved(channel, context) +} + +export function traceAsync(channel, context, fn) { + return run(channel, context, fn).then( + result => (publishResolved(channel, context), result), + error => { + publishRejected(channel, context, error) + throw error + } + ) +} + +function serverOf({ host, port, path }) { + return path + ? { host: path, port: undefined } + : host && host.length === 1 + ? { host: host[0], port: port[0] } + : { host: undefined, port: undefined } +} + +function clientOf(config) { + return { database: config.database, ...serverOf(config), user: config.user, ssl: Boolean(config.ssl), processID: undefined } +} + +export function connectContext(config) { + const { database, host, port, user, ssl } = clientOf(config) + return { connection: { database, host, port, user, ssl } } +} + +export function connectAttempt(context, host, port) { + context.connection.host = host + context.connection.port = port +} + +export function connectSecured(context, ssl) { + context.connection.ssl = ssl +} + +export function transactionContext(config, { mode, savepoint, session }) { + return { client: { ...clientOf(config), ...session }, options: mode, savepoint, prepared: undefined } +} + +export function transactionSession(context, session) { + Object.assign(context.client, session) +} + +export function transactionCommitted(context, committed) { + context.result = { committed } +} + +export function poolContext({ totalCount, idleCount, waitingCount, max }) { + return { pool: { totalCount, idleCount, waitingCount, maxSize: max } } +} + +export function poolSpan(r, context) { + r.pool = context + r.reserve && (r.trace = true) +} + +export function poolHandover(r, c, fresh) { + const context = r.pool + context.handoverTime = performance.timeOrigin + performance.now() + context.queuedBehind = c.active + c.pipelined + context.client = { processID: c.processID, reused: !fresh } +} + +export function poolEnded(r) { + const context = r.pool + r.pool = undefined + publishResolved(poolConnectChannel, context) +} + +function poolFailed(r, error) { + const context = r.pool + r.pool = undefined + context.handoverTime === undefined + ? publishRejected(poolConnectChannel, context, error) + : publishResolved(poolConnectChannel, context) +} + +export function poolReleased(processID, error) { + watched(poolReleaseChannel) && poolReleaseChannel.publish({ client: { processID }, error }) +} + +export function poolRemoved(processID, error) { + watched(poolRemoveChannel) && poolRemoveChannel.publish({ client: { processID }, error }) +} + +export function traceQuery(q, fn) { + q.trace = { query: { text: undefined, name: undefined }, client: clientOf(q.handler.options) } + return run(queryChannel, q.trace, fn, q) +} + +export function queryBuilt(q, session) { + const context = q.trace + context.query.text = q.string + context.query.name = q.statement.name || undefined + Object.assign(context.client, session) +} + +export function traceSucceeded(r, value) { + r.pool && poolEnded(r) + const context = r.trace + r.trace = undefined + if (r.reserve) + return + + context.result = value + publishResolved(queryChannel, context) +} + +export function traceFailed(r, error) { + r.pool && poolFailed(r, error) + const context = r.trace + r.trace = undefined + r.reserve || publishRejected(queryChannel, context, error) +} diff --git a/tests-startup/README.md b/tests-startup/README.md index cc50b4ac..9a3fc7f5 100644 --- a/tests-startup/README.md +++ b/tests-startup/README.md @@ -77,7 +77,7 @@ The portable integration suite checks all 22 built-in element/array OID pairs ag `npm run test:workerd -- . ` runs the driver in local workerd through `createTestHarness()` from pinned Wrangler 4.151.1, which it installs without saving (requires Node 22 or newer). It imports `@steadybrew/postgresjs` through the package's export map, which the `workerd` condition resolves to the generated `cf/` library over `cloudflare:sockets`. `WORKERD_COMPAT_DATE` sets the worker's `compatibility_date` (default `2025-01-01`); CI runs 2025-01-01, 2025-09-15 and the newest date the bundled runtime accepts. It covers cold reservation, built-in arrays/NULL values with fetching on/off, handled catalog failure, and the Cloudflare timer and socket-close fixes: `timers` (idle_timeout and max_lifetime firing, then a query on a recycled connection), `connect-timeout` (a server that accepts and never answers), `end-timeout` (`sql.end({ timeout: 0.2 })` over an in-flight `pg_sleep`), `end-plain` (several clients each ending within a bound) and `end-while-connecting` (`sql.end({ timeout: 0 })` before the socket opens). `copy-out` reads a `COPY TO` stream with a slow consumer, so the socket must pause and resume ([#975](https://github.com/porsager/postgres/issues/975)); `ssl-prefer-declined` connects with `ssl: 'prefer'` to a server without SSL; `subscribe` delivers one logical replication insert (the cluster needs `wal_level = logical` and a replication `pg_hba` entry); `diagnostics-channel` checks that `node:diagnostics_channel` publishes and traces in workerd. `end-tls` and `tls-untrusted-ca` run only when `WORKERD_TLS_PORT` points at an SSL-enabled PostgreSQL and `WORKERD_TLS_CA` at its certificate (which needs a `subjectAltName` for `127.0.0.1`): `end-tls` runs in a harness whose workerd gets the certificate as `SSL_CERT_FILE`, and `tls-untrusted-ca` in one that does not, so it must fail with the certificate error rather than `CONNECT_TIMEOUT` ([#1213](https://github.com/porsager/postgres/issues/1213)). The run fails if any scenario fails. Each scenario starts from `reset()` (fresh storage and logs), runs one bounded request, and fails on any unhandled rejection or uncaught error in the captured runtime logs; the worker also returns the unhandled rejections it saw in its response, and the runner reports each scenario's close-time rejections as `closeRejections`. A close-time rejection ("Stream was cancelled", from workerd 1.20261008.1 "This socket has been closed", or "Network connection lost" when the connection is dropped rather than closed) is logged on every close on compatibility dates before 2026-03-03 without the `unhandled_rejection_after_microtask_checkpoint` flag; `WORKERD_CLOSE_REJECTIONS=logged` marks those matrix entries, and elsewhere any close-time rejection fails the run. The matrix also runs 2025-01-01 with that flag. `no-end` runs a query and returns without ending the client, then polls `pg_stat_activity` by `application_name` until the backend is gone, failing after 10 s. The worker replaces `setTimeout` with a version that throws on extra arguments, as the Cloudflare runtime does ([#1088](https://github.com/porsager/postgres/issues/1088)). The runner retains logs under its printed temporary artifact directory. -`.github/workflows/workerd-edge.yml` runs the same worker on Cloudflare's network as a Preview of the `postgresjs-edge` Worker, with `tests-startup/workerd-edge.mjs`. On pull requests, on main and on release tags it runs, at compatibility date 2026-10-12, only the scenarios that depend on Cloudflare's network: `diagnostics-channel` in the production runtime, `ssl-verify` (verified TLS and SNI against Neon, which refuses plaintext), `tls-private-ca`, `pooled`, `no-end`, the `abort-*` transactions against Neon, its pooler, the Supabase pooler and Hyperdrive, and the three `hyperdrive*` cases; the others run only in local workerd, which covers them without a network. `workerd-edge-cleanup.yml` deletes a pull request's Preview when it closes. The CPU measurement runs only when dispatched by hand, so it does not appear among a commit's checks. `workerd-ab.yml` compares the `cf/` build of the dispatched branch with that of `ab_base`, which may be a release tag or an upstream tag such as `v3.4.9`: the CPU case turns off the worker's strict `setTimeout`, which upstream's timers fail. Each request connects, runs its queries and ends. The `supabase-false` and `supabase-true` targets run `select 1` unprepared against the Supabase CI project's pooler (plaintext) with `fetch_types` off and on, `neon-false` does the same with TLS against Neon, and `hyperdrive-true` connects through Hyperdrive with `prepare: true` and runs parameterized queries in parallel, as a production Worker does; `all` runs all four. Its `ab_copies` input bundles that many separate copies of each build, and each measured round runs on a copy no earlier round used, so every request measures the build's first use in a warm isolate; it takes a single target, and with 40 copies of each build the Worker is about 8 MB, 2 MB gzipped. Each request's `cpuTimeMs`, `wallTimeMs` and outcome come from Workers Logs, so the token needs Workers Metadata and Workers Content read access at account level. The job reports median, p95 and p99 per build and target, and a one-sided Mann-Whitney rank test each way. With `ab_gate` it is the release gate: it fails when the branch is at least 1 ms worse than `ab_base` at the median or p95 on any target and the rank test gives p < 0.01, or when it is killed for exceeding CPU in 2 percentage points more requests. `cpuTimeMs` is whole milliseconds, so a 1 ms difference alone can be rounding; the rank test uses every request. Failed requests are listed, and fail the job only when one variant loses more than 2% of its rounds. +`.github/workflows/workerd-edge.yml` runs the same worker on Cloudflare's network as a Preview of the `postgresjs-edge` Worker, with `tests-startup/workerd-edge.mjs`. On pull requests, on main and on release tags it runs, at compatibility date 2026-10-12, only the scenarios that depend on Cloudflare's network: `diagnostics-channel` and `tracing-channels` in the production runtime, `ssl-verify` (verified TLS and SNI against Neon, which refuses plaintext), `tls-private-ca`, `pooled`, `no-end`, the `abort-*` transactions against Neon, its pooler, the Supabase pooler and Hyperdrive, and the three `hyperdrive*` cases; the others run only in local workerd, which covers them without a network. `workerd-edge-cleanup.yml` deletes a pull request's Preview when it closes. The CPU measurement runs only when dispatched by hand, so it does not appear among a commit's checks. `workerd-ab.yml` compares the `cf/` build of the dispatched branch with that of `ab_base`, which may be a release tag or an upstream tag such as `v3.4.9`: the CPU case turns off the worker's strict `setTimeout`, which upstream's timers fail. Each request connects, runs its queries and ends. The `supabase-false` and `supabase-true` targets run `select 1` unprepared against the Supabase CI project's pooler (plaintext) with `fetch_types` off and on, `neon-false` does the same with TLS against Neon, and `hyperdrive-true` connects through Hyperdrive with `prepare: true` and runs parameterized queries in parallel, as a production Worker does; `all` runs all four. Its `ab_copies` input bundles that many separate copies of each build, and each measured round runs on a copy no earlier round used, so every request measures the build's first use in a warm isolate; it takes a single target, and with 40 copies of each build the Worker is about 8 MB, 2 MB gzipped. Each request's `cpuTimeMs`, `wallTimeMs` and outcome come from Workers Logs, so the token needs Workers Metadata and Workers Content read access at account level. The job reports median, p95 and p99 per build and target, and a one-sided Mann-Whitney rank test each way. With `ab_gate` it is the release gate: it fails when the branch is at least 1 ms worse than `ab_base` at the median or p95 on any target and the rank test gives p < 0.01, or when it is killed for exceeding CPU in 2 percentage points more requests. `cpuTimeMs` is whole milliseconds, so a 1 ms difference alone can be rounding; the rank test uses every request. Failed requests are listed, and fail the job only when one variant loses more than 2% of its rounds. The scope follows [#1219](https://github.com/porsager/postgres/issues/1219), [#751](https://github.com/porsager/postgres/issues/751), and [#1203](https://github.com/porsager/postgres/issues/1203) reservation ownership; [#1195](https://github.com/porsager/postgres/issues/1195) queued reconnect; [#789](https://github.com/porsager/postgres/issues/789) first-query type registration; [#1192](https://github.com/porsager/postgres/issues/1192) and [#1205](https://github.com/porsager/postgres/issues/1205) internal rejection handling; [#1223](https://github.com/porsager/postgres/issues/1223), [#1193](https://github.com/porsager/postgres/issues/1193), and [#1226](https://github.com/porsager/postgres/issues/1226) retry/state isolation; and [#1164](https://github.com/porsager/postgres/issues/1164) built-in arrays without discovery. Catalog traffic/caching from [#903](https://github.com/porsager/postgres/issues/903) is deferred. diff --git a/tests-startup/workerd-edge.mjs b/tests-startup/workerd-edge.mjs index cd17014b..99dbb410 100644 --- a/tests-startup/workerd-edge.mjs +++ b/tests-startup/workerd-edge.mjs @@ -4,7 +4,7 @@ import { appendFile, cp, mkdir, readFile, writeFile } from 'node:fs/promises' import path from 'node:path' const scenarios = [ - 'diagnostics-channel', 'ssl-verify', 'tls-private-ca', 'pooled', 'no-end', + 'diagnostics-channel', 'tracing-channels', 'ssl-verify', 'tls-private-ca', 'pooled', 'no-end', 'abort-neon', 'abort-neon-pooled', 'abort-supabase-pooler', 'abort-hyperdrive', 'abort-hyperdrive-pooled', 'abort-hyperdrive-supabase', 'hyperdrive', 'hyperdrive-pooled', 'hyperdrive-supabase' ] diff --git a/tests-startup/workerd-run.mjs b/tests-startup/workerd-run.mjs index 5a332075..46d95e9e 100644 --- a/tests-startup/workerd-run.mjs +++ b/tests-startup/workerd-run.mjs @@ -85,7 +85,7 @@ async function main() { : [ 'cold-reserve-false', 'arrays-false', 'arrays-true', 'catalog-error', 'timers', 'connect-timeout', 'end-timeout', 'end-plain', 'end-while-connecting', - 'copy-out', 'ssl-prefer-declined', 'subscribe', 'diagnostics-channel', 'no-end', + 'copy-out', 'ssl-prefer-declined', 'subscribe', 'diagnostics-channel', 'tracing-channels', 'no-end', ...(tlsPort && process.env.WORKERD_TLS_CA ? tlsScenarios : []) ] for (const name of scenarios) { diff --git a/tests-startup/workerd-worker.js b/tests-startup/workerd-worker.js index 8813fe83..eb3c5cae 100644 --- a/tests-startup/workerd-worker.js +++ b/tests-startup/workerd-worker.js @@ -178,6 +178,39 @@ const scenarios = { } return { tracingChannel: Boolean(tracing), events } }, + async 'tracing-channels'(port) { + const dc = await import('node:diagnostics_channel') + const { AsyncLocalStorage } = await import('node:async_hooks') + const storage = new AsyncLocalStorage() + const query = dc.tracingChannel('postgres:query') + const connection = dc.tracingChannel('postgres:connect') + equal([typeof dc.tracingChannel, typeof query.start.runStores, typeof query.start.bindStore], ['function', 'function', 'function']) + const seen = [] + const handlers = (name) => ({ + start: () => seen.push(name + ':start:' + storage.getStore()), + end: () => seen.push(name + ':end'), + asyncStart: () => seen.push(name + ':asyncStart'), + asyncEnd: (context) => seen.push(name + ':asyncEnd:' + (context.query ? context.query.text : context.connection.host)), + error: (context) => seen.push(name + ':error:' + context.error.message) + }) + const subscribed = [[query, handlers('query')], [connection, handlers('connect')]] + query.start.bindStore(storage, () => 'span') + subscribed.forEach(([channel, handler]) => channel.subscribe(handler)) + const sql = client(port, { max: 1 }) + try { + await within(sql`select 1 as x`, 5000, 'traced query') + } finally { + subscribed.forEach(([channel, handler]) => channel.unsubscribe(handler)) + query.start.unbindStore(storage) + await within(sql.end(), 3000, 'end') + } + const address = sql.options.host[0] + equal(seen, [ + 'query:start:span', 'query:end', 'connect:start:span', 'connect:end', 'connect:asyncStart', 'connect:asyncEnd:' + address, + 'query:asyncStart', 'query:asyncEnd:select 1 as x' + ]) + return { seen } + }, async 'tls-private-ca'() { const results = [] for (const ssl of ['require', 'prefer']) { diff --git a/tests-tracing/harness.mjs b/tests-tracing/harness.mjs index 5cff7ebc..ce79bbe3 100644 --- a/tests-tracing/harness.mjs +++ b/tests-tracing/harness.mjs @@ -46,6 +46,20 @@ export const scenarios = { } export async function tracer(mode, events) { + if (mode === 'dd-native') { + const dc = await import('node:diagnostics_channel') + const { AsyncLocalStorage } = await import('node:async_hooks') + const storage = new AsyncLocalStorage() + const noop = () => {} + for (const name of ['query', 'connect', 'pool:connect', 'transaction']) { + const channel = dc.tracingChannel('postgres:' + name) + channel.start.bindStore(storage, () => name) + channel.subscribe({ start: noop, end: noop, asyncStart: noop, asyncEnd: noop, error: noop }) + } + for (const name of ['postgres:pool:release', 'postgres:pool:remove']) + dc.subscribe(name, noop) + } + if (mode.startsWith('dd')) { const { default: dd } = await import('dd-trace') return { diff --git a/tests-tracing/run.js b/tests-tracing/run.js index d942348b..72f03c49 100644 --- a/tests-tracing/run.js +++ b/tests-tracing/run.js @@ -13,6 +13,7 @@ const tracers = { 'dd-trace': '6.20.1', '@sentry/node': '11.7.0', '@sentry/serve const runs = [ { mode: 'dd', type: 'esm', flags: ['--import', 'dd-trace/initialize.mjs'] }, { mode: 'dd', type: 'cjs', flags: ['-r', 'dd-trace/init'] }, + { mode: 'dd-native', type: 'esm', flags: ['--import', 'dd-trace/initialize.mjs'] }, { mode: 'dd-dbm', type: 'esm', flags: ['--import', 'dd-trace/initialize.mjs'], env: { DD_DBM_PROPAGATION_MODE: 'full' } }, { mode: 'sentry-auto', type: 'esm', flags: ['--import', '@sentry/node/import'] }, { mode: 'sentry-auto', type: 'cjs', flags: ['--import', '@sentry/node/import'] }, diff --git a/tests-types/index.ts b/tests-types/index.ts index d1d7c719..b6dd60f2 100644 --- a/tests-types/index.ts +++ b/tests-types/index.ts @@ -27,3 +27,12 @@ new postgres.PostgresError({ code: '23505' }) new postgres.PostgresError('boom') // @ts-expect-error new postgres.PostgresError(42) + +const client: postgres.TraceClient = { database: 'a', host: 'localhost', port: 5432, user: 'b', ssl: false, processID: undefined } +const queryTrace: postgres.QueryTraceContext = { query: { text: undefined, name: undefined }, client } +const connectTrace: postgres.ConnectTraceContext = { connection: { database: 'a', host: 'localhost', port: 5432, user: 'b', ssl: false } } +const poolConnectTrace: postgres.PoolConnectTraceContext = { pool: { totalCount: 1, idleCount: 0, waitingCount: 0, maxSize: 10 }, handoverTime: 1, queuedBehind: 0, client: { processID: 1, reused: true } } +const transactionTrace: postgres.TransactionTraceContext = { client, options: 'read write', savepoint: undefined, prepared: undefined, result: { committed: true } } +const releaseMessage: postgres.PoolReleaseMessage = { client: { processID: 1 }, error: undefined } +const removeMessage: postgres.PoolRemoveMessage = { client: { processID: 1 }, error: undefined } +void [queryTrace, connectTrace, poolConnectTrace, transactionTrace, releaseMessage, removeMessage] diff --git a/tests/index.js b/tests/index.js index d70b2bbe..0e4e5223 100644 --- a/tests/index.js +++ b/tests/index.js @@ -8,6 +8,7 @@ import crypto from 'crypto' import postgres from '../src/index.js' import { Stage } from '../src/query.js' import { vercelPool } from '../src/vercel.js' +import './tracing.js' const delay = ms => new Promise(r => setTimeout(r, ms)) const rel = x => new URL(x, import.meta.url) diff --git a/tests/tracing.js b/tests/tracing.js new file mode 100644 index 00000000..67195724 --- /dev/null +++ b/tests/tracing.js @@ -0,0 +1,856 @@ +import dc from 'diagnostics_channel' +import { AsyncLocalStorage } from 'async_hooks' + +import { t } from './test.js' +import postgres from '../src/index.js' + +const snapshot = context => Object.fromEntries(Object.entries(context)) +const settle = () => new Promise(setImmediate) +const active = async query => { + query.catch(() => undefined) + while (!query.active) + await settle() +} +const sleeper = sql => sql`select pg_sleep(60)`.execute() +const now = () => performance.timeOrigin + performance.now() +const rel = x => new URL(x, import.meta.url) +const stages = ['start', 'end', 'asyncStart', 'asyncEnd', 'error'] + +const options = { + db: 'postgres_js_test', + user: 'postgres_js_test', + idle_timeout: 1, + connect_timeout: 1, + max: 1 +} + +function collect(...names) { + const events = [] + const undo = [] + const ids = new Map() + const id = context => ids.get(context) || (ids.set(context, ids.size + 1), ids.size) + for (const name of names.filter(x => x.startsWith('postgres:'))) { + const handler = context => events.push({ name, stage: 'publish', id: id(context), time: now(), context: snapshot(context) }) + dc.subscribe(name, handler) + undo.push(() => dc.unsubscribe(name, handler)) + } + + for (const name of names.filter(x => !x.startsWith('postgres:'))) { + const channel = dc.tracingChannel('postgres:' + name) + const handlers = Object.fromEntries(stages.map(stage => + [stage, context => events.push({ name, stage, id: id(context), time: now(), context: snapshot(context) })] + )) + channel.subscribe(handlers) + undo.push(() => channel.unsubscribe(handlers)) + } + + return { events, stop: () => undo.forEach(x => x()) } +} + +const of = (events, name) => events.filter(x => x.name === name) +const sequence = (events, name) => of(events, name).map(x => x.stage).join(' ') +const ended = (events, name = 'query') => of(events, name).filter(x => x.stage === 'asyncEnd').map(x => x.context) +const plain = 'start end asyncStart asyncEnd' +const failed = 'start end error asyncStart asyncEnd' +const count = (events, stage, name = 'query') => of(events, name).filter(x => x.stage === stage).length +const settled = (events, name = 'query') => JSON.stringify([count(events, 'start', name), count(events, 'asyncEnd', name)]) +const server = o => ({ host: o.path || o.host[0], port: o.path ? undefined : o.port[0] }) + +async function traced(names, fn) { + const sql = postgres(options) + const { events, stop } = collect(...names) + try { + await fn(sql) + } finally { + stop() + await sql.end() + } + return events +} + +t('Tracing publishes a query in order with the context filled in as it is built', async() => { + const sql = postgres(options) + const { events, stop } = collect('query', 'postgres:pool:remove') + await sql`select ${ 5 }::int as x` + await sql.end() + stop() + const [done] = ended(events) + const [remove] = of(events, 'postgres:pool:remove') + const { host, port } = server(sql.options) + return [ + JSON.stringify([ + plain, 'select $1::int as x', true, 'SELECT', 1, + sql.options.database, sql.options.user, host, port, false, true, false, true + ]), + JSON.stringify([ + sequence(events, 'query'), done.query.text, typeof done.query.name === 'string', + done.result.command, done.result.count, done.client.database, done.client.user, done.client.host, done.client.port, done.client.ssl, + typeof done.client.processID === 'number', 'values' in done, + remove.context.client.processID === done.client.processID + ]) + ] +}) + +t('Tracing names a prepared statement and leaves an unnamed one without a name', async() => { + const events = await traced(['query'], async sql => { + await sql`select 1 as x` + await sql`select 2 as x`.simple() + }) + const [prepared, simple] = ended(events) + return [JSON.stringify([true, null]), JSON.stringify([typeof prepared.query.name === 'string', simple.query.name || null])] +}) + +t('Tracing publishes error before asyncStart and keeps the error on the context', async() => { + const events = await traced(['query'], sql => sql`select 1/0`.catch(() => undefined)) + const [done] = ended(events) + return [failed + '|22012', sequence(events, 'query') + '|' + done.error.code] +}) + +t('Tracing a cursor with a callback settles once', async() => { + const events = await traced(['query'], sql => sql`select * from generate_series(1, 5)`.cursor(2, () => undefined)) + return [JSON.stringify([1, 1]), settled(events)] +}) + +t('Tracing a cursor read with for await settles once, to the end and on break', async() => { + const events = await traced(['query'], async sql => { + for await (const rows of sql`select * from generate_series(1, 5)`.cursor(2)) + rows.length + for await (const rows of sql`select * from generate_series(1, 5)`.cursor(2)) { + rows.length + break + } + await sql`select 1` + }) + return [JSON.stringify([3, 3]), settled(events)] +}) + +t('Tracing forEach settles once', async() => { + const events = await traced(['query'], sql => sql`select * from generate_series(1, 5)`.forEach(() => undefined)) + return [JSON.stringify([1, 1]), settled(events)] +}) + +t('Tracing COPY streams settles each query once, when the copy is over', async() => { + const events = await traced(['query'], async sql => { + await sql`create temp table tracing_copy (x int)` + const writable = await sql`copy tracing_copy from stdin`.writable() + writable.end('1\n2\n') + await new Promise(resolve => writable.on('finish', resolve)) + const readable = await sql`copy (select * from tracing_copy order by x) to stdout`.readable() + readable.resume() + await new Promise(resolve => readable.on('end', resolve)) + await sql`select 1` + }) + const copies = ended(events).filter(x => /^copy/.test(x.query.text)) + return [ + JSON.stringify([4, 4, ['COPY', 'COPY']]), + JSON.stringify([count(events, 'start'), count(events, 'asyncEnd'), copies.map(x => x.result.command)]) + ] +}) + +t('Tracing describe, simple, unsafe and file settle once each', async() => { + const events = await traced(['query'], async sql => { + await sql`select 1 as x`.describe() + await sql`select 2 as x`.simple() + await sql.unsafe('select 3 as x') + await sql.unsafe('select $1::int as x', [4]) + await sql.file(rel('select.sql')) + }) + return [JSON.stringify([5, 5]), settled(events)] +}) + +t('Tracing pipelined queries settle once each with their own context', async() => { + const events = await traced(['query'], sql => Promise.all([sql`select 1 as x`, sql`select 2 as x`, sql`select 3 as x`])) + return [ + JSON.stringify(['select 1 as x', 'select 2 as x', 'select 3 as x']), + JSON.stringify(ended(events).map(x => x.query.text)) + ] +}) + +t('Tracing a query cancelled before it is sent settles with the cancellation and is never built', async() => { + const sql = postgres(options) + const { events, stop } = collect('query') + const first = sql`select 1 as x`.execute() + const waiting = sql`select 2 as x` + const code = waiting.then(() => 'resolved', e => e.code) + await waiting.cancel() + await first + const result = await code + stop() + await sql.end() + const never = of(events, 'query').find(x => x.stage === 'asyncEnd' && x.context.query.text === undefined) + const own = events.filter(x => x.id === never.id) + return [ + JSON.stringify(['57014', failed]), + JSON.stringify([result, own.map(x => x.stage).join(' ')]) + ] +}) + +t('Tracing a reserved connection settles each query once', async() => { + const sql = postgres(options) + const { events, stop } = collect('query') + const reserved = await sql.reserve() + await reserved`select 1 as x` + reserved.release() + stop() + await sql.end() + return [JSON.stringify([1, 1]), settled(events)] +}) + +t('Tracing a transaction publishes begin, its queries and a savepoint', async() => { + const events = await traced(['transaction', 'query'], sql => sql.begin('read write', async sql => { + await sql`select 1 as x` + await sql.savepoint('inner', sql => sql`select 2 as x`) + })) + const [savepoint, transaction] = ended(events, 'transaction') + return [ + JSON.stringify([ + 'start end start end asyncStart asyncEnd asyncStart asyncEnd', 'read write', 's0_inner', { committed: true }, null, true, + ['begin read write', 'select 1 as x', 'savepoint "s0_inner"', 'select 2 as x', 'commit'] + ]), + JSON.stringify([ + sequence(events, 'transaction'), transaction.options, savepoint.savepoint, transaction.result, savepoint.result || null, + savepoint.client.database === transaction.client.database && transaction.client.database !== undefined, + ended(events).map(x => x.query.text) + ]) + ] +}) + +t('Tracing a rolled back transaction publishes the error', async() => { + const events = await traced(['transaction'], sql => sql.begin(() => { + throw new Error('stop') + }).catch(() => undefined)) + const [done] = ended(events, 'transaction') + return [failed + '|stop', sequence(events, 'transaction') + '|' + done.error.message] +}) + +t('Tracing a connection publishes its attempt and the removal', async() => { + const sql = postgres(options) + const { events, stop } = collect('connect', 'postgres:pool:remove') + await sql`select 1` + await sql.end() + stop() + const [done] = ended(events, 'connect') + const [remove] = of(events, 'postgres:pool:remove') + const { host, port } = server(sql.options) + return [ + JSON.stringify([plain, [sql.options.database, host, port, sql.options.user, false], true, null]), + JSON.stringify([ + sequence(events, 'connect'), + [done.connection.database, done.connection.host, done.connection.port, done.connection.user, done.connection.ssl], + typeof remove.context.client.processID === 'number', remove.context.error || null + ]) + ] +}) + +t('Tracing a connection that fails to authenticate or to connect publishes the error', async() => { + const { events, stop } = collect('connect') + const codes = [] + const wrong = postgres({ ...options, user: 'postgres_js_test_md5', pass: 'wrong' }) + codes.push(await wrong`select 1`.catch(e => e.code)) + const refused = postgres({ ...options, host: '127.0.0.1', port: 33333 }) + codes.push(await refused`select 1`.catch(e => e.code)) + stop() + return [ + JSON.stringify([['28P01', 'ECONNREFUSED'], failed + ' ' + failed, ['28P01', 'ECONNREFUSED']]), + JSON.stringify([codes, sequence(events, 'connect'), ended(events, 'connect').map(x => x.error.code)]) + ] +}) + +t('Tracing start runs in the AsyncLocalStorage context of the caller', async() => { + const storage = new AsyncLocalStorage() + const seen = [] + const transforms = [] + const sql = postgres({ ...options, debug: () => seen.push(storage.getStore()) }) + const channel = dc.tracingChannel('postgres:query') + const handlers = { start: () => seen.push('start:' + storage.getStore()) } + channel.start.bindStore(storage, () => (transforms.push(storage.getStore()), 'span')) + channel.subscribe(handlers) + try { + await sql`select 1` + seen.length = 0 + transforms.length = 0 + await storage.run('caller', async() => { + await sql`select 2` + }) + } finally { + channel.unsubscribe(handlers) + channel.start.unbindStore(storage) + await sql.end() + } + return [JSON.stringify([['caller'], ['start:span', 'span']]), JSON.stringify([transforms, seen])] +}) + +t('Tracing a transaction runs its function inside the transaction context', async() => { + const storage = new AsyncLocalStorage() + const sql = postgres(options) + const channel = dc.tracingChannel('postgres:transaction') + const handlers = { start: () => undefined } + channel.start.bindStore(storage, () => 'transaction') + channel.subscribe(handlers) + let seen + try { + await sql.begin(async() => { + seen = storage.getStore() + }) + } finally { + channel.unsubscribe(handlers) + channel.start.unbindStore(storage) + await sql.end() + } + return ['transaction', seen] +}) + +t('Nothing is published when nothing subscribes', async() => { + const published = [] + const restore = [] + const names = ['query', 'connect', 'transaction', 'pool:connect'].flatMap(name => stages.map(stage => 'tracing:postgres:' + name + ':' + stage)) + .concat('postgres:pool:release', 'postgres:pool:remove') + for (const name of names) { + const channel = dc.channel(name) + for (const method of ['publish', 'runStores']) { + const original = channel[method] + channel[method] = function() { + published.push(name + '.' + method) + return original.apply(this, arguments) + } + restore.push(() => delete channel[method]) + } + } + + const sql = postgres(options) + try { + await sql`select 1 as x` + await sql.begin(async sql => { + await sql`select 2 as x` + await sql.savepoint(sql => sql`select 3 as x`) + }) + const reserved = await sql.reserve() + await reserved`select 4 as x` + reserved.release() + } finally { + await sql.end() + restore.forEach(x => x()) + } + + return [JSON.stringify([]), JSON.stringify(published)] +}) + +t('Tracing contexts have no result or error key until one is set', async() => { + const events = await traced(['query', 'connect', 'transaction', 'pool:connect'], sql => sql.begin(async sql => { + await sql.savepoint(sql => sql`select 1 as x`) + })) + const early = events.filter(x => x.stage === 'start' || x.stage === 'end') + return [ + JSON.stringify([['connect', 'pool:connect', 'query', 'transaction'], 0]), + JSON.stringify([[...new Set(early.map(x => x.name))].sort(), early.filter(x => 'result' in x.context || 'error' in x.context).length]) + ] +}) + +const cancelledBeforeAwait = async(extra, warm) => { + const sql = postgres({ ...options, ...extra }) + warm && await sql`select 1` + const { events, stop } = collect('query') + const query = sql`select 2 as x` + query.cancel() + const code = await query.catch(e => e.code) + await sql`select 3 as x` + stop() + await sql.end() + return JSON.stringify([code, count(events, 'start'), count(events, 'asyncEnd')]) +} + +t('Tracing a query cancelled before it is awaited opens no span, with several connections', async() => + [JSON.stringify(['57014', 1, 1]), await cancelledBeforeAwait({ max: 2 }, true)] +) + +t('Tracing a query cancelled before it is awaited opens no span, with one connection', async() => + [JSON.stringify(['57014', 1, 1]), await cancelledBeforeAwait({ max: 1 }, true)] +) + +t('Tracing a query cancelled before it is awaited opens no span, on a pool that has to connect', async() => + [JSON.stringify(['57014', 1, 1]), await cancelledBeforeAwait({ max: 2 }, false)] +) + +t('Tracing a retried query settles once', async() => { + const sql = postgres(options) + const { events, stop } = collect('query') + await sql`drop table if exists tracing_retry` + await sql`create table tracing_retry (name text)` + await sql`insert into tracing_retry values ('1')` + await sql`select name from tracing_retry` + await sql`alter table tracing_retry alter column name type int using name::integer` + const [row] = await sql`select name from tracing_retry` + await sql`drop table tracing_retry` + stop() + await sql.end() + return [JSON.stringify([1, 7, 7]), JSON.stringify([row.name, count(events, 'start'), count(events, 'asyncEnd')])] +}) + +t('Tracing a server error in the middle of a cursor settles once with the error', async() => { + const events = await traced(['query'], async sql => { + await sql`select 1 / (x - 3) from generate_series(1, 5) x`.cursor(2, () => undefined).catch(() => undefined) + await sql`select 1` + }) + const [first] = ended(events) + return [JSON.stringify([2, 2, '22012']), JSON.stringify([count(events, 'start'), count(events, 'asyncEnd'), first.error && first.error.code])] +}) + +t('Tracing a cursor callback that throws settles once with the error', async() => { + const events = await traced(['query'], async sql => { + await sql`select * from generate_series(1, 5)`.cursor(2, () => { + throw new Error('boom') + }).catch(() => undefined) + await sql`select 1` + }) + const [first] = ended(events) + return [JSON.stringify([2, 2, 'boom']), JSON.stringify([count(events, 'start'), count(events, 'asyncEnd'), first.error && first.error.message])] +}) + +t('Tracing a query cancelled in the queue of a reserved connection settles once', async() => { + const sql = postgres({ ...options, max_pipeline: 1 }) + const { events, stop } = collect('query') + const reserved = await sql.reserve() + const first = reserved`select pg_sleep(0.1)`.execute() + const second = reserved`select 2 as x`.execute() + const third = reserved`select 3 as x`.execute() + await settle() + const code = await third.cancel().then(() => third.catch(e => e.code)) + await Promise.allSettled([first, second]) + reserved.release() + stop() + await sql.end() + return [JSON.stringify(['57014', 3, 3]), JSON.stringify([code, count(events, 'start'), count(events, 'asyncEnd')])] +}) + +t('Tracing a query cancelled in the queue of a transaction settles once', async() => { + const sql = postgres({ ...options, max_pipeline: 1 }) + const { events, stop } = collect('query') + await sql.begin(async sql => { + const queries = [sql`select pg_sleep(0.1)`.execute(), sql`select 2 as x`.execute(), sql`select 3 as x`.execute()] + await settle() + await queries[2].cancel() + await Promise.allSettled(queries) + }).catch(() => undefined) + stop() + await sql.end() + return [ + JSON.stringify([true, 1]), + JSON.stringify([count(events, 'start') === count(events, 'asyncEnd'), ended(events).filter(x => x.error && x.error.code === '57014').length]) + ] +}) + +t('Tracing queries rejected because the pool is ending settle once', async() => { + const sql = postgres({ ...options, max: 1 }) + const { events, stop } = collect('query') + const running = sql`select pg_sleep(0.1)`.execute() + const queued = sql`select 2 as x`.execute() + await Promise.allSettled([running, queued, sql.end()]) + stop() + return [JSON.stringify([2, 2]), settled(events)] +}) + +t('Tracing a pool checkout reports the pool at start and whether the connection was reused', async() => { + const sql = postgres(options) + const { events, stop } = collect('pool:connect') + const first = await sql.reserve() + first.release() + const second = await sql.reserve() + second.release() + stop() + await sql.end() + const starts = of(events, 'pool:connect').filter(x => x.stage === 'start').map(x => x.context.pool) + const [one, two] = ended(events, 'pool:connect') + return [ + JSON.stringify([ + plain + ' ' + plain, + [{ totalCount: 0, idleCount: 0, waitingCount: 0, maxSize: 1 }, { totalCount: 1, idleCount: 1, waitingCount: 0, maxSize: 1 }], + [false, true], true + ]), + JSON.stringify([ + sequence(events, 'pool:connect'), starts, [one.client.reused, two.client.reused], + typeof one.client.processID === 'number' && one.client.processID === two.client.processID + ]) + ] +}) + +t('Tracing a pool checkout that fails publishes the error and no client', async() => { + const { events, stop } = collect('pool:connect') + const refused = postgres({ ...options, host: '127.0.0.1', port: 33333 }) + const codes = [await refused.reserve().catch(e => e.code)] + const ended_ = postgres(options) + await ended_.end() + codes.push(await ended_.reserve().catch(e => e.code)) + stop() + const done = ended(events, 'pool:connect') + return [ + JSON.stringify([['ECONNREFUSED', 'CONNECTION_ENDED'], failed + ' ' + failed, [false, false], ['ECONNREFUSED', 'CONNECTION_ENDED']]), + JSON.stringify([codes, sequence(events, 'pool:connect'), done.map(x => 'client' in x), done.map(x => x.error.code)]) + ] +}) + +t('Tracing a release publishes once, with the connection of the checkout', async() => { + const sql = postgres(options) + const { events, stop } = collect('pool:connect', 'postgres:pool:release') + const reserved = await sql.reserve() + reserved.release() + reserved.release() + stop() + await sql.end() + const releases = of(events, 'postgres:pool:release') + const [checkout] = ended(events, 'pool:connect') + return [ + JSON.stringify([1, true, null]), + JSON.stringify([releases.length, releases[0].context.client.processID === checkout.client.processID, releases[0].context.error || null]) + ] +}) + +t('Tracing a transaction publishes its release without an error after a clean rollback', async() => { + const sql = postgres(options) + const { events, stop } = collect('pool:connect', 'postgres:pool:release', 'transaction') + await sql.begin(async sql => { + await sql`select 1` + }) + await sql.begin(() => { + throw new Error('stop') + }).catch(() => undefined) + stop() + await sql.end() + const releases = of(events, 'postgres:pool:release').map(x => x.context) + const checkouts = ended(events, 'pool:connect') + return [ + JSON.stringify([2, [null, null], [true, true], 2]), + JSON.stringify([ + releases.length, releases.map(x => x.error ? x.error.message : null), + releases.map((x, i) => x.client.processID === checkouts[i].client.processID), checkouts.length + ]) + ] +}) + +t('Tracing the release of a lost connection carries the error and the process of the lease', async() => { + const sql = postgres(options) + const killer = postgres({ ...options, max: 1 }) + const reserved = await sql.reserve() + const [{ pid }] = await reserved`select pg_backend_pid() as pid` + const { events, stop } = collect('postgres:pool:release') + await killer`select pg_terminate_backend(${ pid })` + await reserved`select 1`.catch(() => undefined) + reserved.release() + stop() + await Promise.all([sql.end(), killer.end()]) + const [release] = of(events, 'postgres:pool:release') + return [ + JSON.stringify([1, pid, 'CONNECTION_CLOSED']), + JSON.stringify([ + of(events, 'postgres:pool:release').length, release.context.client.processID, release.context.error && release.context.error.code + ]) + ] +}) + +const spans = (events, name = 'pool:connect') => ended(events, name) +const at = (events, name, stage, nth = 0) => events.indexOf(of(events, name).filter(x => x.stage === stage)[nth]) +const asyncEndOf = (events, text) => events.indexOf(of(events, 'query').find(x => x.stage === 'asyncEnd' && x.context.query.text === text)) + +t('Tracing a query on an idle connection has a pool span that starts and ends at once', async() => { + const sql = postgres(options) + await sql`select 1` + const { events, stop } = collect('query', 'pool:connect') + await sql`select 2 as x` + stop() + await sql.end() + const [span] = spans(events) + const start = of(events, 'pool:connect').find(x => x.stage === 'start') + return [ + JSON.stringify([plain, 0, true, true, true, true]), + JSON.stringify([ + sequence(events, 'pool:connect'), span.queuedBehind, span.handoverTime >= start.time, span.client.reused, + typeof span.client.processID === 'number', at(events, 'query', 'start') < at(events, 'pool:connect', 'start') + ]) + ] +}) + +t('Tracing a query that opens its connection nests the connect span inside the pool span', async() => { + const storage = new AsyncLocalStorage() + const sql = postgres(options) + const pool = dc.tracingChannel('postgres:pool:connect') + const connect = dc.tracingChannel('postgres:connect') + const seen = [] + const probe = { start: () => seen.push(storage.getStore()) } + pool.start.bindStore(storage, () => 'pool') + connect.subscribe(probe) + const { events, stop } = collect('query', 'pool:connect', 'connect') + try { + await sql`select 1` + } finally { + stop() + connect.unsubscribe(probe) + pool.start.unbindStore(storage) + await sql.end() + } + const [span] = spans(events) + return [ + JSON.stringify([['pool'], false, plain, true, true]), + JSON.stringify([ + seen, span.client.reused, sequence(events, 'pool:connect'), + at(events, 'pool:connect', 'start') < at(events, 'connect', 'start'), + at(events, 'connect', 'asyncEnd') < at(events, 'pool:connect', 'asyncEnd') + ]) + ] +}) + +t('Tracing a query sent ahead to a busy connection ends its pool span when the earlier query is done', async() => { + const sql = postgres(options) + await sql`select 1` + const { events, stop } = collect('query', 'pool:connect') + const slow = sleeper(sql) + await active(slow) + const waiting = sql`select 2 as x`.execute() + await settle() + await slow.cancel() + await Promise.allSettled([slow, waiting]) + stop() + await sql.end() + const [first, second] = spans(events) + return [ + JSON.stringify([0, true, true, true]), + JSON.stringify([ + first.queuedBehind, second.queuedBehind >= 1, second.client.reused, + asyncEndOf(events, 'select pg_sleep(60)') < at(events, 'pool:connect', 'asyncEnd', 1) + ]) + ] +}) + +t('Tracing queries drained from the pool queue when the connection opens wait behind the first', async() => { + const sql = postgres(options) + const { events, stop } = collect('query', 'pool:connect') + await Promise.all([sql`select 1 as x`, sql`select 2 as x`, sql`select 3 as x`]) + stop() + await sql.end() + const found = spans(events) + const pairs = [0, 1, 2].map(i => at(events, 'pool:connect', 'asyncEnd', i) < at(events, 'query', 'asyncEnd', i)) + return [ + JSON.stringify([3, 3, [false, true, true], true, [true, true, true]]), + JSON.stringify([ + count(events, 'asyncEnd', 'pool:connect'), count(events, 'start', 'pool:connect'), found.map(x => x.client.reused), + found[1].queuedBehind >= 1, pairs + ]) + ] +}) + +t('Tracing fails the pool span before the query when the pool is ending', async() => { + const sql = postgres(options) + await sql`select 1` + const { events, stop } = collect('query', 'pool:connect') + const ending = sql.end() + const code = await sql`select 2 as x`.catch(e => e.code) + await ending + stop() + const [span] = spans(events) + return [ + JSON.stringify(['CONNECTION_ENDED', failed, 'CONNECTION_ENDED', true]), + JSON.stringify([ + code, sequence(events, 'pool:connect'), span.error.code, + at(events, 'pool:connect', 'asyncEnd') < at(events, 'query', 'asyncEnd') + ]) + ] +}) + +t('Tracing fails the pool span of a query refused during a COPY', async() => { + const sql = postgres(options) + await sql`create temp table tracing_pool_copy (x int)` + const writable = await sql`copy tracing_pool_copy from stdin`.writable() + const { events, stop } = collect('query', 'pool:connect') + const code = await sql`select 1`.catch(e => e.code) + stop() + writable.end('1\n') + await new Promise(resolve => writable.on('finish', resolve)) + await sql.end() + const [span] = spans(events) + return [ + JSON.stringify(['COPY_IN_PROGRESS', failed, 'COPY_IN_PROGRESS']), + JSON.stringify([code, sequence(events, 'pool:connect'), span.error.code]) + ] +}) + +t('Tracing fails the pool span of a query cancelled in the pool queue', async() => { + const sql = postgres(options) + await sql`select 1` + const { events, stop } = collect('query', 'pool:connect') + const first = sql`select pg_sleep(${ 60 })`.execute() + await active(first) + const waiting = sql`select 2 as x` + const code = waiting.then(() => 'resolved', e => e.code) + await settle() + await waiting.cancel() + await first.cancel() + await Promise.allSettled([first]) + const result = await code + stop() + await sql.end() + const found = spans(events) + return [ + JSON.stringify(['57014', ['57014', 'ok'], 2, 2]), + JSON.stringify([ + result, found.map(x => x.error ? x.error.code : 'ok').sort(), count(events, 'asyncEnd', 'pool:connect'), count(events, 'start', 'pool:connect') + ]) + ] +}) + +t('Tracing fails the pool span of a query whose connection attempt fails', async() => { + const { events, stop } = collect('query', 'pool:connect', 'connect') + const refused = postgres({ ...options, host: '127.0.0.1', port: 33333 }) + const code = await refused`select 1`.catch(e => e.code) + stop() + return [ + JSON.stringify(['ECONNREFUSED', failed, failed, true]), + JSON.stringify([ + code, sequence(events, 'pool:connect'), sequence(events, 'connect'), + at(events, 'pool:connect', 'asyncEnd') < at(events, 'query', 'asyncEnd') + ]) + ] +}) + +t('Tracing resolves the pool span of a query that waited behind others on a connection that is lost', async() => { + const sql = postgres(options) + const killer = postgres({ ...options, max: 1 }) + const [{ pid }] = await sql`select pg_backend_pid() as pid` + const { events, stop } = collect('query', 'pool:connect') + const running = sleeper(sql) + await active(running) + const waiting = sql`select 2 as x`.execute() + await killer`select pg_terminate_backend(${ pid })` + const outcomes = await Promise.allSettled([running, waiting]) + stop() + await Promise.all([sql.end(), killer.end()]) + const failures = of(events, 'pool:connect').filter(x => x.stage === 'error') + const failed_ = events.find(x => x.name === 'pool:connect' && x.stage === 'asyncEnd' && x.context.error) + return [ + JSON.stringify(['rejected', 'rejected', 0, true, true]), + JSON.stringify([ + outcomes[0].status, outcomes[1].status, failures.length, + count(events, 'start', 'pool:connect') === count(events, 'asyncEnd', 'pool:connect'), + events.indexOf(failed_) < asyncEndOf(events, 'select 2 as x') + ]) + ] +}) + +t('Tracing opens no pool span when only one of the query and pool channels has a subscriber', async() => { + const sql = postgres(options) + const poolOnly = collect('pool:connect') + await sql`select 1` + poolOnly.stop() + const published = [] + const channel = dc.channel('tracing:postgres:pool:connect:start') + const original = channel.runStores + channel.runStores = function() { + published.push('runStores') + return original.apply(this, arguments) + } + const queryOnly = collect('query') + try { + await sql`select 2` + } finally { + queryOnly.stop() + delete channel.runStores + await sql.end() + } + return [JSON.stringify([0, []]), JSON.stringify([poolOnly.events.length, published])] +}) + +t('Tracing a query that fails to build resolves its pool span once handed over, on an idle and on a busy connection', async() => { + const sql = postgres(options) + await sql`select 1` + const idle = collect('query', 'pool:connect') + await sql`select ${ undefined }`.catch(() => undefined) + idle.stop() + const slow = sleeper(sql) + await active(slow) + const crowded = collect('query', 'pool:connect') + await sql`select ${ undefined }`.catch(() => undefined) + crowded.stop() + await slow.cancel() + await Promise.allSettled([slow]) + await sql.end() + const summary = events => [ + sequence(events, 'pool:connect'), sequence(events, 'query'), count(events, 'asyncEnd', 'pool:connect'), count(events, 'asyncEnd'), + at(events, 'pool:connect', 'asyncEnd') < at(events, 'query', 'asyncEnd') + ] + return [ + JSON.stringify([[plain, failed, 1, 1, true], [plain, failed, 1, 1, true]]), + JSON.stringify([summary(idle.events), summary(crowded.events)]) + ] +}) + +t('Tracing statements inside begin and reserve publish no plain pool span', async() => { + const sql = postgres(options) + const { events, stop } = collect('query', 'pool:connect') + await sql.begin(async sql => { + await sql`select 1` + }) + const reserved = await sql.reserve() + await reserved`select 2` + reserved.release() + stop() + await sql.end() + return [ + JSON.stringify([2, 2, 4]), + JSON.stringify([count(events, 'start', 'pool:connect'), count(events, 'asyncEnd', 'pool:connect'), count(events, 'start')]) + ] +}) + +t('Tracing a lease taken on a busy connection reports the queries ahead of it', async() => { + const sql = postgres(options) + await sql`select 1` + const slow = sleeper(sql) + await active(slow) + const { events, stop } = collect('pool:connect') + const transaction = sql.begin(async sql => { + await sql`select 1` + }) + await settle() + await slow.cancel() + await transaction + stop() + await Promise.allSettled([slow]) + await sql.end() + const [span] = spans(events) + return [JSON.stringify([1, true]), JSON.stringify([span.queuedBehind, span.client.reused])] +}) + +const reconnected = async(queued) => { + const sql = postgres(options) + const killer = postgres({ ...options, max: 1 }) + const [{ pid }] = await sql`select pg_backend_pid() as pid` + await killer`select 1` + const { events, stop } = collect('query', 'pool:connect') + const running = sql`select pg_sleep(${ 5 })`.execute() + await active(running) + const waiting = queued === 'lease' ? sql.reserve() : sql`select 2 as x`.execute() + await killer`select pg_terminate_backend(${ pid })` + const [, outcome] = await Promise.allSettled([running, waiting]) + stop() + outcome.status === 'fulfilled' && queued === 'lease' && outcome.value.release() + await Promise.all([sql.end(), killer.end()]) + return JSON.stringify([outcome.status, spans(events).filter(x => x.client && x.client.reused === false).length]) +} + +t('Tracing a query served by the reconnect of a closed connection reports that it opened the connection', async() => + [JSON.stringify(['fulfilled', 1]), await reconnected('query')] +) + +t('Tracing a lease served by the reconnect of a closed connection reports that it opened the connection', async() => + [JSON.stringify(['fulfilled', 1]), await reconnected('lease')] +) + +t('Tracing a lease served after the initial query of a connection counts that query as ahead of it', async() => { + const sql = postgres(options) + const { events, stop } = collect('pool:connect') + const first = sql`select 1 as x`.execute() + await 1 + const reserved = await sql.reserve() + reserved.release() + stop() + await first + await sql.end() + const [span] = spans(events) + return [JSON.stringify([1, true]), JSON.stringify([span.queuedBehind, span.client.reused])] +}) diff --git a/transpile.deno.js b/transpile.deno.js index 25ea9dac..2eea9e45 100644 --- a/transpile.deno.js +++ b/transpile.deno.js @@ -25,7 +25,7 @@ fs.readdirSync('src').forEach(name => ) ) -fs.readdirSync('tests').forEach(name => +fs.readdirSync('tests').filter(name => name !== 'tracing.js').forEach(name => fs.writeFileSync( path.join(tests, name), name.endsWith('.js') @@ -44,8 +44,10 @@ function transpile(x, name, folder) { .replace(/\nexec\(/g, '\nawait exec(') .replace('{ spawnSync }', '{ spawn }') } - if (name === 'index.js') + if (name === 'index.js') { + x = x.replace('import \'./tracing.js\'\n', '') x += '\n;globalThis.addEventListener("unload", () => Deno.exit(process.exitCode))' + } } const buffer = x.includes('Buffer') @@ -74,6 +76,7 @@ function transpile(x, name, folder) { '(query.writable.push({ chunk }), callback())' ) .replace('socket.setKeepAlive(true, 1000 * keep_alive)', 'socket.setKeepAlive(true)') + .replace('from \'diagnostics_channel\'', 'from \'node:diagnostics_channel\'') .replace('node:stream', std + 'node/stream.ts') .replace('import net from \'net\'', 'import { net } from \'../polyfills.js\'') .replace('import tls from \'tls\'', 'import { tls } from \'../polyfills.js\'') diff --git a/types/index.d.ts b/types/index.d.ts index 7574d4b0..80530752 100644 --- a/types/index.d.ts +++ b/types/index.d.ts @@ -798,6 +798,88 @@ declare namespace postgres { prepare(name: string): Promise>; } + /** The connection a traced call runs on. Host, port and ssl are those of the connection once it is known. */ + interface TraceClient { + database: string; + host: string | undefined; + port: number | undefined; + user: string; + ssl: boolean; + /** Backend process id; set once the call is written to a connection */ + processID: number | undefined; + } + + /** Context of the `postgres:query` tracing channel. `query` and the connection fields of `client` are set when the query is written to a connection, after `start`. */ + interface QueryTraceContext { + query: { + /** SQL text with `$n` placeholders as sent to the server */ + text: string | undefined; + /** Prepared statement name; undefined for an unnamed statement */ + name: string | undefined; + }; + client: TraceClient; + /** Set before `asyncStart` when the query succeeded: the `Result`, one for each statement of a multi-statement simple query, the statement for `describe()`, or for a `COPY` the `Result` of the finished copy */ + result?: ResultMeta | ResultMeta[] | Statement; + /** Set before `error` when the query failed: the query's own rejection, which can be any thrown value */ + error?: unknown; + } + + /** Context of the `postgres:connect` tracing channel, one span for each connection acquisition. */ + interface ConnectTraceContext { + connection: Omit; + error?: Error; + } + + /** Context of the `postgres:pool:connect` tracing channel: every wait for a connection, for `sql.reserve()`, `sql.begin()` and plain pooled queries. */ + interface PoolConnectTraceContext { + pool: { + totalCount: number; + idleCount: number; + waitingCount: number; + maxSize: number; + }; + /** Epoch milliseconds at which the connection took the call over; set before `asyncStart` once a connection took the call over. `handoverTime` minus the `start` time is the wait for a connection. */ + handoverTime?: number; + /** Queries the connection already had running or waiting when it took this one over. For a plain query, the time from `handoverTime` to `asyncStart` is spent behind them; a lease span ends at the hand-over, so that time falls inside its first statement. */ + queuedBehind?: number; + /** Set with `handoverTime` */ + client?: { + processID: number | undefined; + /** False when the acquisition had to open the connection */ + reused: boolean; + }; + /** Set before `error`: why the wait failed, or the error of a request that failed before a connection took it over */ + error?: unknown; + } + + /** Context of the `postgres:transaction` tracing channel, for `sql.begin()` and `sql.savepoint()`. */ + interface TransactionTraceContext { + client: TraceClient; + /** The mode string passed to `sql.begin()`; undefined for a savepoint */ + options: string | undefined; + /** The savepoint name as sent to the server; undefined for `sql.begin()` */ + savepoint: string | undefined; + /** The name given to `sql.prepare()` */ + prepared: string | undefined; + /** Set by `sql.begin()` on success: `committed` is false when the transaction was prepared */ + result?: { committed: boolean }; + error?: unknown; + } + + /** Message of the `postgres:pool:release` channel. */ + interface PoolReleaseMessage { + client: { processID: number | undefined }; + /** Why the connection was terminated instead of returned healthy, such as a failed commit or a lost connection; undefined otherwise, including after a transaction that rolled back cleanly */ + error: Error | undefined; + } + + /** Message of the `postgres:pool:remove` channel. */ + interface PoolRemoveMessage { + client: { processID: number | undefined }; + /** The error that closed the connection; undefined for a normal close */ + error: Error | undefined; + } + interface ReservedSql = {}> extends Sql { release(): void;