search

vapor / postgres-nio

🐘 Non-blocking, event-driven Swift client for PostgreSQL.
https://api.vapor.codes/postgresnio/documentation/postgresnio/
MIT License
305 stars 70 forks source link

Connection Pool Crash: Precondition failure when ping and close happen at the same time #443

Closed lovetodream closed 7 months ago

lovetodream commented 7 months ago

Describe the bug

When running a connection pool using PostgresClient, the pool crashes with a precondition failure ("All connections that have been created should say goodbye exactly once!") on certain cases.

This seems to happen if the keep alive is triggered at the same time as the close on a connection.

To Reproduce

  1. In the PostgresClient.Configuration, set the connectionIdleTimeout to a multiple of keepAliveBehavior?.frequency.
  2. Repeat running a query shortly after connectionIdleTimeout until it crashes. (The crash doesn't happen every time)

I've created a minimal reproduction sample: https://github.com/lovetodream/connection-pool-crash Note: the crash might not occur on every run, but for me it did (mostly around the ~5th connection)

Here is a log dump, note the second ping pong on the crashing connection:

2023-12-11T13:55:20+0100 debug connection-pool-crash : psql_connection_id=0 [PostgresNIO] Creating new connection
2023-12-11T13:55:30+0100 debug connection-pool-crash : psql_connection_id=0 [PostgresNIO] run ping pong
2023-12-11T13:55:41+0100 debug connection-pool-crash : psql_connection_id=0 [PostgresNIO] Close connection
2023-12-11T13:55:41+0100 debug connection-pool-crash : psql_connection_id=0 psql_error=PSQLError – Generic description to prevent accidental leakage of sensitive data. For debugging details, use `String(reflecting: error)`. [PostgresNIO] Cleaning up and closing connection.
2023-12-11T13:55:41+0100 debug connection-pool-crash : psql_connection_id=0 psql_error=ioOnClosedChannel [PostgresNIO] Channel error caught.
2023-12-11T13:55:41+0100 debug connection-pool-crash : psql_connection_id=0 [PostgresNIO] Connection closed
2023-12-11T13:55:43+0100 debug connection-pool-crash : psql_connection_id=1 [PostgresNIO] Creating new connection
2023-12-11T13:55:54+0100 debug connection-pool-crash : psql_connection_id=1 [PostgresNIO] run ping pong
2023-12-11T13:56:04+0100 debug connection-pool-crash : psql_connection_id=1 [PostgresNIO] Close connection
2023-12-11T13:56:04+0100 debug connection-pool-crash : psql_connection_id=1 psql_error=PSQLError – Generic description to prevent accidental leakage of sensitive data. For debugging details, use `String(reflecting: error)`. [PostgresNIO] Cleaning up and closing connection.
2023-12-11T13:56:04+0100 debug connection-pool-crash : psql_connection_id=1 psql_error=ioOnClosedChannel [PostgresNIO] Channel error caught.
2023-12-11T13:56:04+0100 debug connection-pool-crash : psql_connection_id=1 [PostgresNIO] Connection closed
2023-12-11T13:56:07+0100 debug connection-pool-crash : psql_connection_id=2 [PostgresNIO] Creating new connection
2023-12-11T13:56:17+0100 debug connection-pool-crash : psql_connection_id=2 [PostgresNIO] run ping pong
2023-12-11T13:56:27+0100 debug connection-pool-crash : psql_connection_id=2 [PostgresNIO] Close connection
2023-12-11T13:56:27+0100 debug connection-pool-crash : psql_connection_id=2 psql_error=PSQLError – Generic description to prevent accidental leakage of sensitive data. For debugging details, use `String(reflecting: error)`. [PostgresNIO] Cleaning up and closing connection.
2023-12-11T13:56:27+0100 debug connection-pool-crash : psql_connection_id=2 psql_error=ioOnClosedChannel [PostgresNIO] Channel error caught.
2023-12-11T13:56:27+0100 debug connection-pool-crash : psql_connection_id=2 [PostgresNIO] Connection closed
2023-12-11T13:56:30+0100 debug connection-pool-crash : psql_connection_id=3 [PostgresNIO] Creating new connection
2023-12-11T13:56:41+0100 debug connection-pool-crash : psql_connection_id=3 [PostgresNIO] run ping pong
2023-12-11T13:56:50+0100 debug connection-pool-crash : psql_connection_id=3 [PostgresNIO] Close connection
2023-12-11T13:56:50+0100 debug connection-pool-crash : psql_connection_id=3 psql_error=PSQLError – Generic description to prevent accidental leakage of sensitive data. For debugging details, use `String(reflecting: error)`. [PostgresNIO] Cleaning up and closing connection.
2023-12-11T13:56:50+0100 debug connection-pool-crash : psql_connection_id=3 psql_error=ioOnClosedChannel [PostgresNIO] Channel error caught.
2023-12-11T13:56:50+0100 debug connection-pool-crash : psql_connection_id=3 [PostgresNIO] Connection closed
2023-12-11T13:56:53+0100 debug connection-pool-crash : psql_connection_id=4 [PostgresNIO] Creating new connection
2023-12-11T13:57:03+0100 debug connection-pool-crash : psql_connection_id=4 [PostgresNIO] run ping pong
2023-12-11T13:57:14+0100 debug connection-pool-crash : psql_connection_id=4 [PostgresNIO] run ping pong
2023-12-11T13:57:14+0100 debug connection-pool-crash : psql_connection_id=4 [PostgresNIO] Close connection
2023-12-11T13:57:14+0100 debug connection-pool-crash : psql_connection_id=4 psql_error=PSQLError – Generic description to prevent accidental leakage of sensitive data. For debugging details, use `String(reflecting: error)`. [PostgresNIO] Cleaning up and closing connection.
2023-12-11T13:57:14+0100 debug connection-pool-crash : psql_connection_id=4 psql_error=ioOnClosedChannel [PostgresNIO] Channel error caught.
2023-12-11T13:57:14+0100 debug connection-pool-crash : psql_connection_id=4 [PostgresNIO] Connection closed
_ConnectionPoolModule/PoolStateMachine+ConnectionGroup.swift:498: Fatal error: All connections that have been created should say goodbye exactly once!

Expected behavior

The crash shouldn't happen, because the connection is only closed once.

Environment

Additional context

I've noticed this crash on my own implementation of ConnectionPool, but it is also reproducible with PostgresClient. So I guess it's a problem within the ConnectionPool module itself.