CODEWITHSUNDEEP
kotlinspring-data-jpaspring-datahikaricppgjdbc-ng
tomson
tomson

Reputation: 171

How do I configure HikariCP correctly to work with connections that have to stay active?

I am using Spring Boot 2.4.0 with Spring Boot Data JPA to connect to PostgreSQL and perform typical read and write operations with JPA based repositories. Since the database is also used by other services, I use the LISTEN/NOTIFY functionality (https://www.postgresql.org/docs/9.1/sql-listen.html) to be notified about changes from PostgeSQL. For this I use the driver com.impossibl.postgres.jdbc.PGDriver instead of the default driver and the following code to make Spring listen for changes to the database:

@Service
class PostgresChangeListener(
    val dataSource: HikariDataSource,
    @Qualifier("dbToPGReceiverQueue") val postgresQueue: RBlockingQueue<String>
) {
    init {
        listenToNotifyMessage()
    }

    final fun listenToNotifyMessage() {
        val notificationListener = object:PGNotificationListener {
            override fun notification(processId: Int, channelName: String, payload: String) {
                log.info("Received change from PostgresQL: $processId, $channelName, $payload")
                postgresQueue.add(payload)
            }
            override fun closed() {
                log.debug("Connection to Postgres lost! Try to reconnect...")
                listenToNotifyMessage()
            }
        }

        try {
            val connection = DataSourceUtils.getConnection(dataSource).unwrap(PGConnection::class.java)
            connection.addNotificationListener(notificationListener)
            connection.createStatement().use { statement -> statement.execute("LISTEN change_notifier;") }
        } catch (e: SQLException) {
            throw RuntimeException(e)
        }
    }
}

This is the Kotlin-like implementation of the listener discribed here: https://impossibl.github.io/pgjdbc-ng/docs/current/user-guide/#extensions-notifications

The listener works, however after one or more days I get the following error:

2021-03-03 06:33:00.185  WARN 1 --- [nio-8080-exec-8] o.s.b.a.jdbc.DataSourceHealthIndicator   : DataSource health check failed

org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30001ms.
...

To find the problem, i enabled logging from Hikari as recommended on https://github.com/brettwooldridge/HikariCP/issues/1111#issuecomment-569552070. Here is the output of an excerpt of the logs:

2021-03-02 21:31:59.055 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
...
2021-03-02 21:31:59.055 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
2021-03-02 22:00:53.139 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.impossibl.postgres.jdbc.PGDirectConnection@201ab69f: (connection has passed maxLifetime)
2021-03-02 22:00:53.162 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection com.impossibl.postgres.jdbc.PGDirectConnection@f2ffd1ea
2021-03-02 22:00:54.709 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.impossibl.postgres.jdbc.PGDirectConnection@3bb847ef: (connection has passed maxLifetime)
2021-03-02 22:00:54.730 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection com.impossibl.postgres.jdbc.PGDirectConnection@fd5932d7
2021-03-02 22:00:59.110 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
2021-03-02 22:00:59.111 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Fill pool skipped, pool is at sufficient level.
2021-03-02 22:01:04.782 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.impossibl.postgres.jdbc.PGDirectConnection@1d081266: (connection has passed maxLifetime)
2021-03-02 22:01:04.803 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection com.impossibl.postgres.jdbc.PGDirectConnection@e0b396bc
2021-03-02 22:01:09.295 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.impossibl.postgres.jdbc.PGDirectConnection@a2b0bd29: (connection has passed maxLifetime)
2021-03-02 22:01:09.313 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection com.impossibl.postgres.jdbc.PGDirectConnection@ca9c8226
2021-03-02 22:01:10.075 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.impossibl.postgres.jdbc.PGDirectConnection@ec8746aa: (connection has passed maxLifetime)
2021-03-02 22:01:10.093 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection com.impossibl.postgres.jdbc.PGDirectConnection@aff2bfd8
2021-03-02 22:01:12.820 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.impossibl.postgres.jdbc.PGDirectConnection@a7e0fc39: (connection has passed maxLifetime)
2021-03-02 22:01:12.840 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection com.impossibl.postgres.jdbc.PGDirectConnection@d637554
2021-03-02 22:01:15.099 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.impossibl.postgres.jdbc.PGDirectConnection@dadcba66: (connection has passed maxLifetime)
2021-03-02 22:01:15.119 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection com.impossibl.postgres.jdbc.PGDirectConnection@e29805ef
2021-03-02 22:01:21.558 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.impossibl.postgres.jdbc.PGDirectConnection@762f0753: (connection has passed maxLifetime)
2021-03-02 22:01:21.576 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection com.impossibl.postgres.jdbc.PGDirectConnection@d5b8d008
2021-03-02 22:01:23.351 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.impossibl.postgres.jdbc.PGDirectConnection@5e4721b0: (connection has passed maxLifetime)
2021-03-02 22:01:23.370 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection com.impossibl.postgres.jdbc.PGDirectConnection@a8606b56
2021-03-02 22:01:29.111 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
2021-03-02 22:01:29.111 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Fill pool skipped, pool is at sufficient level.
2021-03-02 22:01:59.112 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=1, idle=9, waiting=0)
...

For me the log looks correct but after a while the active connections increase more and more...

...
2021-03-03 06:31:29.664 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=9, idle=1, waiting=0)
2021-03-03 06:31:48.687 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase          : HikariPool-1 - Closing connection com.impossibl.postgres.jdbc.PGDirectConnection@4fa5ec41: (connection is dead)
2021-03-03 06:31:48.707 DEBUG 1 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Added connection com.impossibl.postgres.jdbc.PGDirectConnection@693052fe
2021-03-03 06:31:48.709 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Fill pool skipped, pool is at sufficient level.
2021-03-03 06:31:59.665 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=10, idle=0, waiting=1)
2021-03-03 06:31:59.665 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Fill pool skipped, pool is at sufficient level.
2021-03-03 06:32:20.199 DEBUG 1 --- [io-8080-exec-10] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=2)
2021-03-03 06:32:20.208  WARN 1 --- [io-8080-exec-10] o.s.b.a.jdbc.DataSourceHealthIndicator   : DataSource health check failed

org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
...

... until it comes to the described error message.

I wonder how I need to configure Hikari correctly or change my code to avoid the errors described? I hope you can help.

Upvotes: 2

Views: 3353

Answers (1)

spartalos
spartalos

Reputation: 108

Not the same issue, but I had a similar problem. When my database was restarted, Hikari couldn't close the active listener connection, and the whole notification stopped working.

I found a possible solution for this. The reason why Hikari can't close the connection when it's dead because you are unwrapping the connection from the proxied Connection here:

DataSourceUtils.getConnection(dataSource).unwrap(PGConnection::class.java)

After this you are attaching a notificationListener to the PGConnection, so it remains alive.

First thing first to avoid hikaripool leaking you should seperate the 2 connection, and after initializing the listener you should close the hikariConnection.

private hikariConnection: Connection;

...

hikariConnection = DataSourceUtils.getConnection(dataSource)
val pgConnection: PGConnection = hikariConnection.unwrap(PGConnection::class.java)

... init the listener
hikariConnection.close()

And in the PGNotificationListener.closed() you have to reinitalize the listener, get a new Connection from the datasource. But beware, getting new connection while the Hikaripool filling it's pool(because the database outage was only a few seconds), can block each other. We solved it by getting the new connection on a dedicated new thread.

 override fun closed() {
            ... get a new PGConnection, and start listening for the notifications
    }

Sorry if it's not correctly answering your question, but it may help to some.

Upvotes: 6

Related Questions