Runaway connection attempts with `pgxpool`

[mbrancato]

Describe the bug
I have an application using a pgxpool.Pool (pgx/v4 v4.18.1) to manage connections to a PgBouncer instance, and ultimately to a PostgreSQL 15 server.

To Reproduce
I am currently trying to reproduce this in a simple manner. The connection setup looks like this:

	poolConfig, err := pgxpool.ParseConfig("postgres://postgres:postgres@localhost:5432/postgres")
	if err != nil {
		sugar.Fatalf("error parsing DB URL: %v", err)
	}
	poolConfig.MaxConns = 4
	poolConfig.MinConns = 4
	poolConfig.ConnConfig.Logger = zapadapter.NewLogger(logger)
	poolConfig.ConnConfig.LogLevel = pgx.LogLevelDebug

	dbPool, err := pgxpool.ConnectConfig(ctx, poolConfig)
	if err != nil {
		sugar.Fatalf("error connecting to DB: %v", err)
	}

We're using the QueryRow() etc directly on the pool and not using Acquire(). The resulting Row is passed to Scan() eventually.

Expected behavior
The pool should fill and keep 4 connections.

Actual behavior
The pool fills up, then for some unknown reason, it is attempting to create more connections constantly. The data from pool.Stat() indicates there are already 4 total connections, but continues to attempt to create more.

At the debug log level, pgxpool is not clearly indicating why it is creating multiple connections, but it is easy to see the attempts:

Note: the connection failures here are all PgBouncer running out of client connections, which has way more than pool size * number of copies of app.

 server error (FATAL: no more connections allowed (max_client_conn) (SQLSTATE 08P01))

Stat info for the above logs:
before connection runaway (2023-10-26 05:34:14.968):

{
    "max_lifetime_destroy_count": 0,
    "constructing_connections": 0,
    "acquired_connections": 0,
    "empty_acquire_count": 0,
    "new_connections_count": 4,
    "acquire_count": 1,
    "acquire_duration": 2.6e-7,
    "max_idle_destroy_count": 0,
    "total_connections": 4,
    "canceled_acquire_count": 0,
    "message": "Database pool stats",
    "idle_connections": 4,
    "timestamp": "2023-10-26T09:34:14.968Z",
    "max_connections": 4
}

shortly after connection runaway (2023-10-26 05:34:29.969):
Note: I thought this is probably when it received its first query attempt, but no query is logged (which eventually happens with the logger attached)

{
    "idle_connections": 0,
    "canceled_acquire_count": 0,
    "constructing_connections": 0,
    "max_connections": 4,
    "message": "Database pool stats",
    "total_connections": 4,
    "max_lifetime_destroy_count": 0,
    "empty_acquire_count": 5,
    "timestamp": "2023-10-26T09:34:29.969Z",
    "max_idle_destroy_count": 0,
    "acquire_duration": 34.920843834,
    "acquire_count": 10,
    "acquired_connections": 4,
    "new_connections_count": 4
}

1 minute after connection runaway (2023-10-26 05:35:24.975):

{
    "max_lifetime_destroy_count": 0,
    "idle_connections": 0,
    "new_connections_count": 15,
    "max_idle_destroy_count": 0,
    "empty_acquire_count": 299,
    "acquired_connections": 3,
    "acquire_count": 304,
    "message": "Database pool stats",
    "constructing_connections": 0,
    "canceled_acquire_count": 4,
    "timestamp": "2023-10-26T09:35:24.975Z",
    "acquire_duration": 2790.153294167,
    "max_connections": 4,
    "total_connections": 3
}

Version

• Go: 1.20
• PostgreSQL: 15 (CloudSQL), with PgBouncer 1.20.1
• pgx: v4.18.1

Additional context
I started setting MaxConns and MinConns to mitigate this, with no luck.

[jackc]

I haven't seen anything like that before.

A few things to try:

• Connect directly to the PG server to eliminate PgBouncer as a factor
• When you have the simpler reproduction case, also try it with v5.

---

Actually, it doesn't appear that the pool is overfilling. That would indicate that existing connections are dying. Are you canceling contexts? That terminates the underlying connection. Based on your stats only 15 total connections were made. It's quite possible that canceled queries are triggering the new connections.

[mbrancato]

Thanks for the suggestion @jackc
There was a timeout on the context for pgxpool.ConnectConfig(ctx, poolConfig). I moved it to simply context.Background() but it didn't seem to fix the issue. If a query gets a context timeout (context passed to QueryRow), then immediately after that the pool appears to attempt to create new connections.

The surprising thing is that the connection is orphaned or something when a query times out.

{"severity":"ERROR","timestamp":"2023-10-27T13:30:09.268Z","message":"Query","pid":3727644839,"err":"timeout: context deadline exceeded","sql":"....","time":10.0033073,"args":["..."]}
{"severity":"ERROR","timestamp":"2023-10-27T13:30:09.270Z","message":"Query","err":"timeout: context deadline exceeded","sql":"...","time":10.000524572,"args":["..."],"pid":3765987911}
{"severity":"DEBUG","timestamp":"2023-10-27T13:30:09.271Z","message":"Connecting to database"}
{"severity":"INFO","timestamp":"2023-10-27T13:30:09.271Z","message":"Dialing PostgreSQL server","host":"..."}
{"severity":"DEBUG","timestamp":"2023-10-27T13:30:09.272Z","message":"Connecting to database"}
{"severity":"INFO","timestamp":"2023-10-27T13:30:09.273Z","message":"Dialing PostgreSQL server","host":"..."}
{"severity":"DEBUG","timestamp":"2023-10-27T13:30:09.275Z","message":"Connected to database"}

[mbrancato]

Looking at this, would a context cancelled or timeout cause a connection to be disconnected? And does it notify the server to disconnect. I ask the latter because if there is a graceful disconnect, I wouldn't expect to get max connection errors.

#506 (comment)

[mbrancato]

I did notice I'm not seeing the connection Close() being called in the logs emitted, just constant new connection creation.

pgx/conn.go

Line 257 in 13468eb

c.log(ctx, LogLevelInfo, "closed connection", nil)

We've never had an issue with v4 to date, but I might have to switch this over to v5 to see if that helps.

[jackc]

Looking at this, would a context cancelled or timeout cause a connection to be disconnected?

Yes.

And does it notify the server to disconnect. I ask the latter because if there is a graceful disconnect, I wouldn't expect to get max connection errors.

It tries to cancel the running query and it sends the terminate message to the server. But it also closes the local end of the connection immediately.

[mbrancato]

hey @jackc

I've been able to make some simple examples that show pgxpool attempting to create too many connections. As I worked on this, I started using multiple pgbouncer containers. I thought that may have been the cause due to a lack of peering in the pgbouncer replicas. Ultimately, I was able to see it happening directly against the database server.

I've created two branches to demo this, one for v4 and one for v5. Both seem to trigger the same behavior.

v4: https://github.com/mbrancato/pool-party/tree/pgx/v4/pgxpool
v5: https://github.com/mbrancato/pool-party/tree/pgx/v5/pgxpool

[jackc]

I don't have docker setup on my development machine (I'm on MacOS), but I ran the example against my local database both over TCP and local socket. I wasn't able to duplicate the error.

But it doesn't actually surprise me too much that it could occur when the application pool size is exactly the same as the server max connections. pgxpool considers the slot available for a new connection when the termination message has been sent and the local side of the network connection has been closed. But it may take the server side process a little while to terminate.

[mbrancato]

I'm using Rancher Desktop as my "Docker" implementation on MacOS as well. Mainly as it provides a quick way to setup multiple things including a TCP loadbalancer and many pgbouncer copies.

I understand the example is using a small connection max count. At scale, I'm seeing these connections runaway at several times the size of the max pool size. I can also duplicate this behavior using pgbouncer in the mix, and it may be that pgbouncer does not try to discard the connection to the client until the client disconnects the socket.

The setup looks like this:

  graph LR;
      pgxpool-->pgbouncer;
      pgbouncer-->pgsql;

Loading

Where the pool / max conn values are:
pgxpool: 4
pgbouncer: 40 (max pooled client connections)
pgbouncer: 4 (actual database connections)
pgsql: 40 (max actual client connections)

I do see some of these errors, not many. This indicates the cancel request was sent to the wrong copy of pgbouncer.

pool-party-pgbouncer-2   | 2023-10-31 02:48:13.600 UTC [1] LOG C-0x5588de338460: (nodb)/(nouser)@192.168.224.13:57658 closing because: failed cancel request (age=0s)

And that is likely the case because the cancel request was sent to the wrong copy. I imagine this is because the connection is not re-using an existing socket connection to the DB.

[jackc]

Hmm... I'm not sure. The cancel request has to temporarily make a new connection to issue the cancel request. Not sure if those are counted in PgBouncer or PostgreSQLs max connection counts.

I hope to release v5.5.0 today. It includes a tweak to CancelRequest for PgBouncer (5d0f904). Perhaps that will improve things.

[rkofman]

We seem to be running into a similar issue. Recently had a production issue where a single process was able to saturate DB connections (direct to DB, no pgBouncer in between), which is 20x our MaxConns setting.

[edit: seems completely unrelated. mb.]

[jlisthood]

Hi @mbrancato, thanks for raising this issue publicly and also providing a repro, we are seeing a very similar issue between pgx v4.16.1 and Pgbouncer. We have symptoms of client-side connections far exceeding expected values during periods of context cancellation.

For example, on the client-side we have a client-side connection pool limit of 100 and on the server-side we have a limit of 1024, but we are seeing this get exhausted when the only client is a sole pgxpool that is maxed out on connections.

I was reading through the old pgconn code and I noticed that query cancels are sent asynchronously:
https://github.com/jackc/pgconn/blob/831fc211bc3b06eb7b461992c231fea7496dbf29/pgconn.go#L618-L641

A question for @jackc, assuming that query cancels are generally asynchronous and are triggered when contexts passed into the various pgx interfaces are canceled - it wouldn't be too surprising that the number of client-connections from pgx to the target could exceed the max size of the connection pool? Presumably if there is some delay in processing cancellation requests, then the outbound client-connection count could be SUM(current_pool_size, pending_cancel_requests)

[jackc]

it wouldn't be too surprising that the number of client-connections from pgx to the target could exceed the max size of the connection pool? Presumably if there is some delay in processing cancellation requests, then the outbound client-connection count could be SUM(current_pool_size, pending_cancel_requests)

I'm not sure how pgbouncer or PostgreSQL itself count cancellation requests, but yes, there would be that many outbound connections.

In pgx v5, you can use pgconn.Config.BuildContextWatcherHandler to control exactly how cancellations are performed. Tuning this might solve the problem./

[james-johnston-thumbtack]

We also have been experiencing runaway client connections on PGBouncer 1.22.0 where show pools reports orders of magnitude more connections in cl_waiting status than the database/sql client connection pool size (note we are using pgx stdlib package). Eventually this can lead to errors like no more connections allowed (max_client_conn). We did some further investigation and experimentation since we could reproduce the problem with a load test.

TL;DR of conclusions in our case:

• pgx is not leaking or otherwise holding open excessive numbers of TCP sockets to PgBouncer. That is not the problem.
• However, the database/sql connection pool (or probably pgxpool for that matter?) will allow the app to aggressively reconnect to PgBouncer, without any sort of backoff / delay mechanism. It would be beneficial if there was an easy way to configure some sort of exponential backoff when reconnecting to PostgreSQL from pgxpool. For example, if queries are failing due to transient reasons (e.g. canceled contexts) and the connection is being discarded, then creation of new connections should start to be throttled. We think this might be a way that would allow overwhelmed PGBouncer instances to recover.

Example PGBouncer output in our case (note that cancel requests are tracked separately):

pgbouncer=# show pools;
 database  |        user        | cl_active | cl_waiting | cl_active_cancel_req | cl_waiting_cancel_req | sv_active | sv_active_cancel | sv_being_canceled | sv_idle | sv_used | sv_tested | sv_login | maxwait | maxwait_us |  pool_mode
-----------+--------------------+-----------+------------+----------------------+-----------------------+-----------+------------------+-------------------+---------+---------+-----------+----------+---------+------------+-------------
 pgbouncer | pgbouncer          |         1 |          0 |                    0 |                     0 |         0 |                0 |                 0 |       0 |       0 |         0 |        0 |       0 |          0 | statement
 users     | users_latency_read |         0 |       2027 |                    0 |                     0 |         0 |                0 |                 0 |       0 |       0 |         0 |        1 |      10 |      52536 | transaction

In this case, 10 load test programs were running, each with a connection pool size of 30, so we should never see more than 10 * 30 = 300 connections across cl_active + cl_waiting. But here, cl_waiting is 2027. Note that the PGBouncer instance has exhausted all server connections: we find it's in a loop of logging in and then immediately discarding the connection, over and over (in our case it's because the client is timing out and cancels the Go context passed to QueryContext). Thus PGBouncer is in a bad state, and it won't recover unless you make it shed the load.

Given the discussion in this issue around asyncClose which has a fire-and-forget Goroutine in it, which could hold TCP connections open that are no longer considered part of the connection pool (and thus subject to pool limits), we questioned whether this could be the excess of connections shown here. We temporarily changed go func() { to just func() { in asyncClose. Also we temporarily added a global counter to track how many concurrent asyncClose functions were running, and it was never very high. Our load test could still cause the above condition. Therefore, in our case, we conclude that the goroutine in the asyncClose function in pgx is not the cause of the "runaway connection counts" on PgBouncer.

This was further proved by examining netstat output. What we found is that pgx is dutifully closing the sockets such that the number of open sockets in ESTABLISHED state is never more than the connection pool size times two (doubled for the cancel requests). However, when PGBouncer shows runaway state above, we find a large number of additional netstat connections on the client in FIN_WAIT2 state. (On the PGBouncer server, they show as CLOSE_WAIT state). This means that the client (pgx) has closed the TCP socket, but the server application (PGBouncer) has yet to finish working with the socket on its end and close it as well - PGBouncer still has the PGBouncer server socket held open for lengthy periods of time, long after pgx has closed pgx's socket.

What we are currently concluding is that the single-threaded nature of PGBouncer may be a limitation. The hypothesis is that there is this timeline:

1. Client app (pgx) connects to PGBouncer. PGBouncer immediately answers.
2. Client app asks to connect to app database and sends the PG credentials.
3. Client app asks to run a query.
4. PGBouncer puts the connection into waiting state, because there is not a PG database connection available.
5. A few seconds pass or whatever because PGBouncer has 2000 other connections in front of it that are waiting.
6. The client gives up and the context is canceled on the client.
7. Go code decides to throw out the connection since we canceled context and the state of the connection is poisoned. The connection is promptly closed and the pgx socket is closed and the connection moves to FIN_WAIT2 state on the client and CLOSE_WAIT on the server.
8. Yet another few seconds later - finally PGBouncer is ready to serve the connection! (Remember it is only making one connection attempt to a PG server at a time, so it took awhile to get to us). It logs into PG and associates the new PG connection with the client connection. (Note this is proved by polling pg_stat_activity on the reader PG instance: the list is empty apart from an occasional fleeting connection if you poll it at the right time. You can see sv_login appears stuck as 1.)
9. Uh oh - PGBouncer finally realizes that the client has disconnected! (In reality the client did that a long time ago in step 7). PGBouncer immediately disconnects from PostgreSQL since the connection is poisoned. So all that hard work it went to, waiting to establish a new PG connection? It all gets thrown away now.
10. Now PGBouncer will close the client connection socket, and finally the operating system closes out the connection completely. In the mean time, the client application had failed, and more connections stack up in PGBouncer, enqueued/waiting connections from all the client's retry attempts.

Some things that we think may help (we are still investigating/experimenting):

• Reducing query_wait_timeout in PGBouncer to the client application's timeout. When the client application has a canceled context and pgx closes the socket, it's useless for PGBouncer to leave the connection in the cl_waiting queue. Our application has 2 second timeout, after which the context will end up canceled. So we set query_wait_timeout to 2, and we find the number of connections in cl_waiting state will decrease significantly (but alone it is not enough to get PgBouncer out of the bad state).
• Horizontally scaling PgBouncer. PgBouncer is single threaded and can only initiate one new server connection at a time, so more PgBouncer instances means more threads available to start new server connections.
• Exponential backoff / throttling in pgx client connection pools when connections are failing. This is an area where pgx could help. Is there a good way to delay creating new connections in pgxpool if queries are failing due to transient reasons? We think this could help temporarily reduce load to PgBouncer and allow it to recover.