Transaction mode: a backend goes back to the pool with a transaction still open on it, and the reply is never relayed

One more measurement, added because it is evidence about the fault rather than a fix for it, and because it answers something from the client side that the report above left open.

We bounded the client's begin from outside its callback, at 35 seconds. postgres.js awaits begin before it runs the transaction callback, so where the reply to begin read only never arrives the callback is never entered and the promise pends for the life of the process. That is why the probes above return nothing at all rather than returning slowly: nothing on the client side was ever going to end the wait.

Same reproduction as above (400 aborted renders, six in flight, paced 40ms), three probes each time, with a healthy baseline taken immediately before each run at 200 in 1.17s, 731ms and 776ms.

Two things follow that may be useful to whoever picks this up.

The client is never answered, rather than answered late. A 120-second bound is not enough and a 35-second one produces an error rather than a reply, so the reply is not in flight anywhere. This is the same conclusion as the instrumented run in the report, arrived at from the other direction.

Nothing on the client side frees the connection. After the bound fires the pool stays exhausted and every subsequent request fails at the bound too. The connection remains reserved inside the client because, as far as it knows, a transaction is still open on it. So the client cannot recover from this without closing connections, and closing them causes a second problem: the SQLSTATE 26000 in the report's "A second fault" section is roughly twenty times more frequent when we terminate the unanswered connection than when we leave it alone.

We are not proposing the bound as a fix and have not changed anything else. It is in place only so that the failure is bounded and visible rather than silent. Still happy to reproduce on demand, add any instrumentation you suggest, or hand over the project ref and session IDs privately.

One more measurement, added because it is evidence about the fault rather than a fix for it, and because it answers something from the client side that the report above left open.

We bounded the client's begin from outside its callback, at 35 seconds. postgres.js awaits begin before it runs the transaction callback, so where the reply to begin read only never arrives the callback is never entered and the promise pends for the life of the process. That is why the probes above return nothing at all rather than returning slowly: nothing on the client side was ever going to end the wait.

Same reproduction as above (400 aborted renders, six in flight, paced 40ms), three probes each time, with a healthy baseline taken immediately before each run at 200 in 1.17s, 731ms and 776ms.

Two things follow that may be useful to whoever picks this up.

The client is never answered, rather than answered late. A 120-second bound is not enough and a 35-second one produces an error rather than a reply, so the reply is not in flight anywhere. This is the same conclusion as the instrumented run in the report, arrived at from the other direction.

Nothing on the client side frees the connection. After the bound fires the pool stays exhausted and every subsequent request fails at the bound too. The connection remains reserved inside the client because, as far as it knows, a transaction is still open on it. So the client cannot recover from this without closing connections, and closing them causes a second problem: the SQLSTATE 26000 in the report's "A second fault" section is roughly twenty times more frequent when we terminate the unanswered connection than when we leave it alone.

We are not proposing the bound as a fix and have not changed anything else. It is in place only so that the failure is bounded and visible rather than silent. Still happy to reproduce on demand, add any instrumentation you suggest, or hand over the project ref and session IDs privately.

Client-side evidence from a Next.js server using postgres.js against the transaction pooler on port 6543, eu-west-2.

On a red run the client's socket to the pooler closed cleanly (no error, hadError: false), with the last whole message received being an ErrorResponse and seven pipelined statements still unanswered. writableLength was 0 at the last write and at close, so nothing was truncated on the client side.

In the same window the pooler logged DbHandler: Session terminated by server while checked out by a client: invalid frontend message type 109 (08P01), 16.6s after the ErrorResponse was delivered to the client (5.4s on another occurrence).

So the malformed frontend message reaches Postgres on the pooler-to-backend link, not from this client, and the backend it kills is one checked out by a different client at the time. Happy to share the socket-level trace and timestamps.

Client-side evidence from a Next.js server using postgres.js against the transaction pooler on port 6543, eu-west-2.

On a red run the client's socket to the pooler closed cleanly (no error, hadError: false), with the last whole message received being an ErrorResponse and seven pipelined statements still unanswered. writableLength was 0 at the last write and at close, so nothing was truncated on the client side.

In the same window the pooler logged DbHandler: Session terminated by server while checked out by a client: invalid frontend message type 109 (08P01), 16.6s after the ErrorResponse was delivered to the client (5.4s on another occurrence).

So the malformed frontend message reaches Postgres on the pooler-to-backend link, not from this client, and the backend it kills is one checked out by a different client at the time. Happy to share the socket-level trace and timestamps.

Client-side evidence from a Next.js server using postgres.js against the transaction pooler on port 6543, eu-west-2.

On a red run the client's socket to the pooler closed cleanly (no error, hadError: false), with the last whole message received being an ErrorResponse and seven pipelined statements still unanswered. writableLength was 0 at the last write and at close, so nothing was truncated on the client side.

In the same window the pooler logged DbHandler: Session terminated by server while checked out by a client: invalid frontend message type 109 (08P01), 16.6s after the ErrorResponse was delivered to the client (5.4s on another occurrence).

So the malformed frontend message reaches Postgres on the pooler-to-backend link, not from this client, and the backend it kills is one checked out by a different client at the time. Happy to share the socket-level trace and timestamps.

A third reproduction, and this one shows the fault from the Postgres side rather than from the client's.

Same driver as before: 400 client-aborted renders through the transaction pooler, six in flight, 40ms apart, against a page whose render pipelines eight statements per transaction. Healthy baseline first (one render, 762ms), no app_user backends open beforehand.

Inside 250ms of the burst, Postgres's own log (by session id, which I can supply privately):

• one backend logged WARNING 25001 there is already a transaction in progress three times in 6ms, and a second backend once more 200ms later. The client sends exactly one BEGIN per transaction, so these are BEGINs arriving at a backend that was already inside another client's transaction;
• the backend the baseline render had used, last statement COMMIT, logged ERROR 08P01 bind message supplies 3 parameters, but prepared statement "" requires 0. The client writes Parse, Bind, Execute, Sync for that statement in one flush. A Bind arriving at a backend whose unnamed statement is still COMMIT is a Bind delivered without the Parse that preceded it on the same client socket.

That second one was not fatal, so it came back to the client as an ordinary ErrorResponse, which is the first time this has reached the application as anything but a closed connection. Every earlier sighting was the fatal invalid frontend message type 109 form. Both read as the same thing: bytes from one client's flush reaching a backend assigned to another, once cut between messages and once cut inside one.

Sixty seconds later idle_in_transaction_session_timeout reaped two backends that Supavisor logged as Session terminated by server while checked out by a client, and the client's socket saw the FATAL as an ErrorResponse before the close, so the relay of a backend's FATAL to its client does work.

And one backend was held for five minutes: active, waiting on ClientRead, inside a transaction from the burst, logging nothing. It was still there 4m48s later after the client process had been killed and every client socket closed. active on ClientRead is a backend between an Execute and its Sync, so this one received a Parse, Bind and Execute whose Sync went elsewhere. The idle-in-transaction timeout does not apply to that state. Supavisor closed it at exactly 5m00s after the burst, 65s after the last client socket had gone (Postgres: unexpected EOF on client connection with an open transaction), and the tenant pool shut down for want of subscribers a minute later. So each occurrence costs the pool one backend for five minutes.

Client side is unchanged from the earlier runs: every socket eight statements out and unanswered, nothing buffered in either direction, and on seven of ten sockets the last reply before the silence was COMMIT plus ReadyForQuery idle.

A third reproduction, and this one shows the fault from the Postgres side rather than from the client's.

Same driver as before: 400 client-aborted renders through the transaction pooler, six in flight, 40ms apart, against a page whose render pipelines eight statements per transaction. Healthy baseline first (one render, 762ms), no app_user backends open beforehand.

Inside 250ms of the burst, Postgres's own log (by session id, which I can supply privately):

• one backend logged WARNING 25001 there is already a transaction in progress three times in 6ms, and a second backend once more 200ms later. The client sends exactly one BEGIN per transaction, so these are BEGINs arriving at a backend that was already inside another client's transaction;
• the backend the baseline render had used, last statement COMMIT, logged ERROR 08P01 bind message supplies 3 parameters, but prepared statement "" requires 0. The client writes Parse, Bind, Execute, Sync for that statement in one flush. A Bind arriving at a backend whose unnamed statement is still COMMIT is a Bind delivered without the Parse that preceded it on the same client socket.

That second one was not fatal, so it came back to the client as an ordinary ErrorResponse, which is the first time this has reached the application as anything but a closed connection. Every earlier sighting was the fatal invalid frontend message type 109 form. Both read as the same thing: bytes from one client's flush reaching a backend assigned to another, once cut between messages and once cut inside one.

Sixty seconds later idle_in_transaction_session_timeout reaped two backends that Supavisor logged as Session terminated by server while checked out by a client, and the client's socket saw the FATAL as an ErrorResponse before the close, so the relay of a backend's FATAL to its client does work.

And one backend was held for five minutes: active, waiting on ClientRead, inside a transaction from the burst, logging nothing. It was still there 4m48s later after the client process had been killed and every client socket closed. active on ClientRead is a backend between an Execute and its Sync, so this one received a Parse, Bind and Execute whose Sync went elsewhere. The idle-in-transaction timeout does not apply to that state. Supavisor closed it at exactly 5m00s after the burst, 65s after the last client socket had gone (Postgres: unexpected EOF on client connection with an open transaction), and the tenant pool shut down for want of subscribers a minute later. So each occurrence costs the pool one backend for five minutes.

Client side is unchanged from the earlier runs: every socket eight statements out and unanswered, nothing buffered in either direction, and on seven of ten sockets the last reply before the silence was COMMIT plus ReadyForQuery idle.

A third reproduction, and this one shows the fault from the Postgres side rather than from the client's.

Same driver as before: 400 client-aborted renders through the transaction pooler, six in flight, 40ms apart, against a page whose render pipelines eight statements per transaction. Healthy baseline first (one render, 762ms), no app_user backends open beforehand.

Inside 250ms of the burst, Postgres's own log (by session id, which I can supply privately):

• one backend logged WARNING 25001 there is already a transaction in progress three times in 6ms, and a second backend once more 200ms later. The client sends exactly one BEGIN per transaction, so these are BEGINs arriving at a backend that was already inside another client's transaction;
• the backend the baseline render had used, last statement COMMIT, logged ERROR 08P01 bind message supplies 3 parameters, but prepared statement "" requires 0. The client writes Parse, Bind, Execute, Sync for that statement in one flush. A Bind arriving at a backend whose unnamed statement is still COMMIT is a Bind delivered without the Parse that preceded it on the same client socket.

That second one was not fatal, so it came back to the client as an ordinary ErrorResponse, which is the first time this has reached the application as anything but a closed connection. Every earlier sighting was the fatal invalid frontend message type 109 form. Both read as the same thing: bytes from one client's flush reaching a backend assigned to another, once cut between messages and once cut inside one.

Sixty seconds later idle_in_transaction_session_timeout reaped two backends that Supavisor logged as Session terminated by server while checked out by a client, and the client's socket saw the FATAL as an ErrorResponse before the close, so the relay of a backend's FATAL to its client does work.

And one backend was held for five minutes: active, waiting on ClientRead, inside a transaction from the burst, logging nothing. It was still there 4m48s later after the client process had been killed and every client socket closed. active on ClientRead is a backend between an Execute and its Sync, so this one received a Parse, Bind and Execute whose Sync went elsewhere. The idle-in-transaction timeout does not apply to that state. Supavisor closed it at exactly 5m00s after the burst, 65s after the last client socket had gone (Postgres: unexpected EOF on client connection with an open transaction), and the tenant pool shut down for want of subscribers a minute later. So each occurrence costs the pool one backend for five minutes.

Client side is unchanged from the earlier runs: every socket eight statements out and unanswered, nothing buffered in either direction, and on seven of ten sockets the last reply before the silence was COMMIT plus ReadyForQuery idle.

A fourth run this morning, read from pg_stat_activity inside the wedge (0.6s, 8s and 25s after the driver started, so before the 60-second idle-in-transaction reaper). The client sends eight statements per transaction in one flush: BEGIN READ ONLY, a set_config, five reads, and a final SELECT EXISTS.

• At 0.6s: ten backends, seven active on the page's reads, one idle in transaction on BEGIN READ ONLY, three idle after COMMIT.
• At 8s: every backend quiet since the same instant. Nine idle with no transaction, five of them having last executed the flush's LAST statement, four COMMIT; one idle in transaction on that last statement. Unchanged at 25s.
• Postgres logged 25001 there is already a transaction in progress four times in 31ms on one backend, which 74ms earlier was 3.6ms into a transaction on a different client's read. Four BEGINs from four clients reached a backend already inside a fifth's transaction.
• Client side at the same instant: ten sockets, each eight statements out and none answered, last reply the previous transaction's COMMIT + ReadyForQuery(I), last statement written the flush's last one. Seven sockets had 451 bytes back after that reply and three had 110 to 118, none containing a ReadyForQuery.
• Supavisor logged nothing at the instant.

So one flush, sent as one TCP write, was delivered statement by statement to different backends: its BEGIN to a backend already in somebody else's transaction, its last statement to a backend that ran it outside any transaction and answered, and that answer never reached the client that sent it.

The same split shows from inside a completed request: the one render of 400 that was not aborted was refused by our own invariant check, because current_setting('request.jwt.claim.sub') was empty on the transaction serving a signed-in user. That is the read landing on a backend that never received the set_config pipelined ahead of it. Without the check, the page would have told the user they belong to no organisation, which is what two earlier end-to-end runs saw.

Also: postgres.js's idle_timeout: 20 closed none of these sockets in 85 seconds, so they are not idle to the client; it is waiting for replies that will not come.

A fourth run this morning, read from pg_stat_activity inside the wedge (0.6s, 8s and 25s after the driver started, so before the 60-second idle-in-transaction reaper). The client sends eight statements per transaction in one flush: BEGIN READ ONLY, a set_config, five reads, and a final SELECT EXISTS.

• At 0.6s: ten backends, seven active on the page's reads, one idle in transaction on BEGIN READ ONLY, three idle after COMMIT.
• At 8s: every backend quiet since the same instant. Nine idle with no transaction, five of them having last executed the flush's LAST statement, four COMMIT; one idle in transaction on that last statement. Unchanged at 25s.
• Postgres logged 25001 there is already a transaction in progress four times in 31ms on one backend, which 74ms earlier was 3.6ms into a transaction on a different client's read. Four BEGINs from four clients reached a backend already inside a fifth's transaction.
• Client side at the same instant: ten sockets, each eight statements out and none answered, last reply the previous transaction's COMMIT + ReadyForQuery(I), last statement written the flush's last one. Seven sockets had 451 bytes back after that reply and three had 110 to 118, none containing a ReadyForQuery.
• Supavisor logged nothing at the instant.

So one flush, sent as one TCP write, was delivered statement by statement to different backends: its BEGIN to a backend already in somebody else's transaction, its last statement to a backend that ran it outside any transaction and answered, and that answer never reached the client that sent it.

The same split shows from inside a completed request: the one render of 400 that was not aborted was refused by our own invariant check, because current_setting('request.jwt.claim.sub') was empty on the transaction serving a signed-in user. That is the read landing on a backend that never received the set_config pipelined ahead of it. Without the check, the page would have told the user they belong to no organisation, which is what two earlier end-to-end runs saw.

Also: postgres.js's idle_timeout: 20 closed none of these sockets in 85 seconds, so they are not idle to the client; it is waiting for replies that will not come.

A fourth run this morning, read from pg_stat_activity inside the wedge (0.6s, 8s and 25s after the driver started, so before the 60-second idle-in-transaction reaper). The client sends eight statements per transaction in one flush: BEGIN READ ONLY, a set_config, five reads, and a final SELECT EXISTS.

• At 0.6s: ten backends, seven active on the page's reads, one idle in transaction on BEGIN READ ONLY, three idle after COMMIT.
• At 8s: every backend quiet since the same instant. Nine idle with no transaction, five of them having last executed the flush's LAST statement, four COMMIT; one idle in transaction on that last statement. Unchanged at 25s.
• Postgres logged 25001 there is already a transaction in progress four times in 31ms on one backend, which 74ms earlier was 3.6ms into a transaction on a different client's read. Four BEGINs from four clients reached a backend already inside a fifth's transaction.
• Client side at the same instant: ten sockets, each eight statements out and none answered, last reply the previous transaction's COMMIT + ReadyForQuery(I), last statement written the flush's last one. Seven sockets had 451 bytes back after that reply and three had 110 to 118, none containing a ReadyForQuery.
• Supavisor logged nothing at the instant.

So one flush, sent as one TCP write, was delivered statement by statement to different backends: its BEGIN to a backend already in somebody else's transaction, its last statement to a backend that ran it outside any transaction and answered, and that answer never reached the client that sent it.

The same split shows from inside a completed request: the one render of 400 that was not aborted was refused by our own invariant check, because current_setting('request.jwt.claim.sub') was empty on the transaction serving a signed-in user. That is the read landing on a backend that never received the set_config pipelined ahead of it. Without the check, the page would have told the user they belong to no organisation, which is what two earlier end-to-end runs saw.

Also: postgres.js's idle_timeout: 20 closed none of these sockets in 85 seconds, so they are not idle to the client; it is waiting for replies that will not come.

Correction to my previous comment, from reading our client's code rather than the dump. Two details were wrong; the measurements stand.

1. The client does not pipeline BEGIN with anything. It awaits BEGIN READ ONLY, then awaits the set_config, and only then sends the page's nine reads in one flush, with COMMIT written behind them as soon as the render resolves or is abandoned. postgres.js reserves a connection on the BEGIN it writes and sends no second BEGIN on it. So the four BEGINs that reached one backend in 31ms came from four client sockets, not one flush.

2. The COMMIT + ReadyForQuery(I) that each wedged socket had last read was the reply to its OWN COMMIT, the statement written behind the reads, not the previous transaction's. So on each socket the pooler answered the last statement of the transaction and none of the nine reads before it. The five backends idle with no transaction had executed that read flush outside any transaction (as nobody), and their answers did not reach the socket that sent them.

So the shape is a client-to-backend pin lost inside a transaction: BEGIN answered by one backend, the reads that followed run on another with no transaction open, COMMIT answered, and four clients' BEGINs landing on a backend that was already pinned to a fifth. Same conclusion as before, more precisely stated.

Correction to my previous comment, from reading our client's code rather than the dump. Two details were wrong; the measurements stand.

1. The client does not pipeline BEGIN with anything. It awaits BEGIN READ ONLY, then awaits the set_config, and only then sends the page's nine reads in one flush, with COMMIT written behind them as soon as the render resolves or is abandoned. postgres.js reserves a connection on the BEGIN it writes and sends no second BEGIN on it. So the four BEGINs that reached one backend in 31ms came from four client sockets, not one flush.

2. The COMMIT + ReadyForQuery(I) that each wedged socket had last read was the reply to its OWN COMMIT, the statement written behind the reads, not the previous transaction's. So on each socket the pooler answered the last statement of the transaction and none of the nine reads before it. The five backends idle with no transaction had executed that read flush outside any transaction (as nobody), and their answers did not reach the socket that sent them.

So the shape is a client-to-backend pin lost inside a transaction: BEGIN answered by one backend, the reads that followed run on another with no transaction open, COMMIT answered, and four clients' BEGINs landing on a backend that was already pinned to a fifth. Same conclusion as before, more precisely stated.

Correction to my previous comment, from reading our client's code rather than the dump. Two details were wrong; the measurements stand.

1. The client does not pipeline BEGIN with anything. It awaits BEGIN READ ONLY, then awaits the set_config, and only then sends the page's nine reads in one flush, with COMMIT written behind them as soon as the render resolves or is abandoned. postgres.js reserves a connection on the BEGIN it writes and sends no second BEGIN on it. So the four BEGINs that reached one backend in 31ms came from four client sockets, not one flush.

2. The COMMIT + ReadyForQuery(I) that each wedged socket had last read was the reply to its OWN COMMIT, the statement written behind the reads, not the previous transaction's. So on each socket the pooler answered the last statement of the transaction and none of the nine reads before it. The five backends idle with no transaction had executed that read flush outside any transaction (as nobody), and their answers did not reach the socket that sent them.

So the shape is a client-to-backend pin lost inside a transaction: BEGIN answered by one backend, the reads that followed run on another with no transaction open, COMMIT answered, and four clients' BEGINs landing on a backend that was already pinned to a fifth. Same conclusion as before, more precisely stated.

An A/B that isolates the client-side trigger, on one build and one server process.

The one thing every wedged socket had in common was ordering: on an abandoned response our release wrote COMMIT behind nine reads it had not waited for, all inside one transaction, all on one client socket. I changed only that, so the release waits (bounded at 5s) for the transaction's outstanding reads to be answered before COMMIT is written.

• With the wait: three runs of 400 client-aborted renders (1,200 total). No wedge, every backend idle after COMMIT within ten seconds, and the Postgres log for the window contains no 25001, no 08P01, nothing but idle closes.
• Without the wait (same server restarted with the wait set to 0): wedged inside 200ms of the burst. Seven 25001 there is already a transaction in progress across three backends, one there is no transaction in progress, one 08P01 bind message supplies 3 parameters, but prepared statement "" requires 0, and a backend left idle in transaction on BEGIN READ ONLY.

So the reproducer is: in transaction mode, a client inside a transaction sends COMMIT while earlier statements of that same transaction are still unanswered, under concurrent client disconnects. Legal for a client to send. Afterwards the client's pin is lost: its COMMIT is answered, the reads before it are not, other clients' BEGINs land on the backend it was pinned to, and a later Bind reaches a backend that never saw its Parse.

We have stopped sending that sequence, which works around it on our side. Happy to supply timestamps and session ids privately.

An A/B that isolates the client-side trigger, on one build and one server process.

The one thing every wedged socket had in common was ordering: on an abandoned response our release wrote COMMIT behind nine reads it had not waited for, all inside one transaction, all on one client socket. I changed only that, so the release waits (bounded at 5s) for the transaction's outstanding reads to be answered before COMMIT is written.

• With the wait: three runs of 400 client-aborted renders (1,200 total). No wedge, every backend idle after COMMIT within ten seconds, and the Postgres log for the window contains no 25001, no 08P01, nothing but idle closes.
• Without the wait (same server restarted with the wait set to 0): wedged inside 200ms of the burst. Seven 25001 there is already a transaction in progress across three backends, one there is no transaction in progress, one 08P01 bind message supplies 3 parameters, but prepared statement "" requires 0, and a backend left idle in transaction on BEGIN READ ONLY.

So the reproducer is: in transaction mode, a client inside a transaction sends COMMIT while earlier statements of that same transaction are still unanswered, under concurrent client disconnects. Legal for a client to send. Afterwards the client's pin is lost: its COMMIT is answered, the reads before it are not, other clients' BEGINs land on the backend it was pinned to, and a later Bind reaches a backend that never saw its Parse.

We have stopped sending that sequence, which works around it on our side. Happy to supply timestamps and session ids privately.