search

brettwooldridge / HikariCP

光 HikariCP・A solid, high-performance, JDBC connection pool at last.
Apache License 2.0
19.91k stars 2.93k forks source link

Randomly HikariPool pool becomes zero and HikariCP is not renewing/creating new connections #1474

Open bytor99999 opened 4 years ago

bytor99999 commented 4 years ago

A couple times this year our production servers crashed because of a bug in Hikari that it runs out of connections. It never creates new connections to move from min size to max size. Our setting is 20 min and 100 max. We have not changed any OS related timeouts. We do not have firewall issues, or TLS issues.

Environment

HikariCP version: which ever comes with Spring Boot 2.0.3.RELEASE (spring-boot-starter-data-jpa)
JDK version     : 1.8.0_111
Database        : MySQL
Driver version  : 5.1.46

First time it was a process running that we had a few users start around the same time. This last time this week was a longer running process by one user. The use cases have the correct transactionality and thread settings on them. We do not have any special logs turned on, and luckily these are rare as we only had it happen twice this year so far. So trying to even replicate it will be difficult.

Gongziyu666 commented 4 years ago

I hava same

Ryaryu commented 4 years ago

I have the same issue. In my case, a PostgreSQL database. For some reasons, not related to TLS or OS, HikariCP cannot get connections in some random moments. Instead of throwing away such bad connections, it does not renew the pool, and gets stuck until the application is restarted. After that, we can work some weeks without issues, but eventually Hikari will get stuck, unable to get connections until the application is restarted.

bytor99999 commented 4 years ago

I apologize, and think this ticket should stay open, but I have moved on. We have switched back to Tomcat's CP implementation.

haresh1288 commented 4 years ago

We are also facing the same issues, and it's random. We are using Azure MySQL Database. our Mysql Wait_Timeout is 30min.

and below is Hikari Configuration

connectionTimeout=30000 idleTimeout=600000 maximumPoolSize=100 maxLifetime=1795000 minimumIdle=25

below is snippet of error.

2020-04-23 13:57:08.315 DEBUG [HikariPool-1 housekeeper][HikariPool:389] HikariPool-1 - Before cleanup stats (total=26, active=1, idle=25, waiting=0)
2020-04-23 13:57:08.316 DEBUG [HikariPool-1 housekeeper][HikariPool:389] HikariPool-1 - After cleanup  stats (total=26, active=1, idle=25, waiting=0)
2020-04-23 13:57:09.947 DEBUG [HikariPool-2 housekeeper][HikariPool:389] HikariPool-2 - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2020-04-23 13:57:09.947 DEBUG [HikariPool-2 housekeeper][HikariPool:389] HikariPool-2 - After cleanup  stats (total=0, active=0, idle=0, waiting=0)

Can you please provide some input, how and what are the possible reasons of this and how we can reproduce. Once we restart the application it's work normally.

brettwooldridge commented 4 years ago

@haresh1288 What I see in the log above is two pools: HikariPool-1 and HikariPool-2. What I need to see is a longer log segment that includes two or more housekeeping cycles for HikariPool-2. For example:

2020-04-23 13:56:09.947 DEBUG ... HikariPool-2 - Before cleanup stats ???
2020-04-23 13:56:09.947 DEBUG ... HikariPool-2 - After cleanup stats ???
2020-04-23 13:56:39.947 DEBUG ... HikariPool-2 - Before cleanup stats ???
2020-04-23 13:56:39.947 DEBUG ... HikariPool-2 - After cleanup stats ???
2020-04-23 13:57:09.947 DEBUG ... HikariPool-2 - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2020-04-23 13:57:09.947 DEBUG ... HikariPool-2 - After cleanup  stats (total=0, active=0, idle=0, waiting=0)

Finally, that version of HikariCP are you using, and what version of the MySQL driver?

brettwooldridge commented 4 years ago

To @bytor99999 and others experiencing any of these kinds of connection issues, one of the first things to check is for changes in the JDBC driver. Every pool and every driver interact differently especially in terms of connection acquisition and termination.

Taking the MySQL Connector/J driver 5.1.46 as an example, the following fix in subsequent version is potentially determinative of connection issues and the ability to establish connection on an ongoing basis:

v5.1.48 bug fix

For an SSL connection, after a client disconnected from a server by calling Connection.close(), the TCP connection remained in the TIME_WAIT state on the server side. With this fix, the connection remains in the TIME_WAIT state on the client side instead, in most cases. (Bug #29054329, Bug #93590)

If you are using MySQL Server 5.6 or later, you should be using the Connector/J 8.x.

Having said that, I am continuing to investigate this issue. Any data, especially logs (both HikariCP and database server) immediately preceding and up to the zeroing of the pool would be extremely helpful.

haresh-patel-eic commented 4 years ago

@brettwooldridge , Thanks for quick replay. I had two datasource connected using Hikari. HikariCP : 2.6.3 MySQL Connector: 5.1.23 MySQL : 5.6 Java:1.8.0_221 Please find the attached logs connections.log

nitinparetha commented 4 years ago

I have the same issue. In my case, a PostgreSQL database. For some reasons, not related to TLS or OS, HikariCP cannot get connections in some random moments. Instead of throwing away such bad connections, it does not renew the pool, and gets stuck until the application is restarted. After that, we can work some weeks without issues, but eventually Hikari will get stuck, unable to get connections until the application is restarted.

Hi @Ryaryu , Did you found any solution to this ?? we are stuck badly with this issue, i tried many things but no success yet for this..

brettwooldridge commented 4 years ago

@Hpatel-eic You need to be running the latest version of HikariCP available for the version of Java that you are using. On Java 8, that would be HikariCP v3.4.3. I cannot support back-level versions, too many changes and fixes have been made.

Also, upgrade your Connector/J driver to v5.1.48.

bytor99999 commented 4 years ago

I thought Java 8 has the highest percentage of users. Are you saying all of us still using it are SOL in getting this major issue fixed?

On May 2, 2020, at 11:09 PM, Brett Wooldridge notifications@github.com wrote:

 @Hpatel-eic You need to be running the latest version of HikariCP available for the version of Java that you are using. On Java 8, that would be HikariCP v3.4.3. I cannot support back-level versions, too many changes and fixes have been made.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

huangyayu commented 3 years ago

I have the same issue, please help. My version: HikariCP : 3.4.5 MySQL Connector: 8.0.24 Java:1.8.0_232

My Hikari Config:

2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1066] HikariPool-3 - configuration:
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] allowPoolSuspension.............false
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] autoCommit......................true
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] catalog.........................none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] connectionInitSql...............none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] connectionTestQuery............."SELECT 1"
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] connectionTimeout...............60000
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] dataSource......................none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] dataSourceClassName.............none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] dataSourceJNDI..................none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] dataSourceProperties............{password=<masked>}
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] driverClassName................."com.mysql.cj.jdbc.Driver"
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] exceptionOverrideClassName......none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] healthCheckProperties...........{}
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] healthCheckRegistry.............none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] idleTimeout.....................500000
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] initializationFailTimeout.......1
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] isolateInternalQueries..........false
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] jdbcUrl.........................jdbc:mysql://xxxx:3306/xxx?serverTimezone=UTC&allowPublicKeyRetrieval=true&characterEncoding=utf-8&socketTimeout=60000&connectTimeout=30000
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] leakDetectionThreshold..........60000
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] maxLifetime.....................540000
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] maximumPoolSize.................50
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] metricRegistry..................none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] metricsTrackerFactory...........none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] minimumIdle.....................20
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] password........................<masked>
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] poolName........................"HikariPool-3"
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] readOnly........................false
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] registerMbeans..................false
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] scheduledExecutor...............none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] schema..........................none
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] threadFactory...................internal
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] transactionIsolation............default
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] username........................"xxx"
2021-05-07 15:10:03 DEBUG [com.zaxxer.hikari.HikariConfig:1098] validationTimeout...............5000

there are no logs at 17:36:03 to 17:47:00 , and then timeout occurred.

2021-05-07 17:35:33 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Before cleanup stats (total=20, active=0, idle=20, waiting=0)
2021-05-07 17:35:33 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - After cleanup  stats (total=20, active=0, idle=20, waiting=0)
2021-05-07 17:35:33 DEBUG [com.zaxxer.hikari.pool.HikariPool:517] HikariPool-3 - Fill pool skipped, pool is at sufficient level.
2021-05-07 17:36:03 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Before cleanup stats (total=19, active=0, idle=19, waiting=0)
2021-05-07 17:36:03 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - After cleanup  stats (total=19, active=0, idle=19, waiting=0)
2021-05-07 17:47:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:50:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:50:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:342] HikariPool-3 - Add connection elided, waiting 1, queue 2
2021-05-07 17:51:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:51:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:342] HikariPool-3 - Add connection elided, waiting 1, queue 2
2021-05-07 17:52:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:52:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:342] HikariPool-3 - Add connection elided, waiting 1, queue 2
TomasTokaMrazek commented 3 years ago

Same issue, tried everything I've found here. Sadly it heavily impacts production environment.

Java: jdk1.8.0_192 DB: Azure hosted - PostgreSQL 10.11, compiled by Visual C++ build 1800, 64-bit Driver: postgresql-42.2.14 Pool: HikariCP-3.4.5

Our appliaction has actually two pools pointing to the exact same database, the only difference is sizing. Both pools have leakDetectionTreshold configured and socketTimeout as dataSource parameter. There is no leak warning in logs, yet few days ago one pool just stopped working, unable to create new connection due to timeout, while the second pool is OK. Again, both pools point to the exact same database with same username and timeout configuration.

[2021-05-25 13:20:58,568] [DEBUG] [wso2 connection closer] com.zaxxer.hikari.pool.PoolBase - wso2 - Closing connection org.postgresql.jdbc.PgConnection@3fdbc150: (connection has passed maxLifetime)
[2021-05-25 13:20:58,744] [DEBUG] [wso2 connection adder] com.zaxxer.hikari.pool.HikariPool - wso2 - Added connection org.postgresql.jdbc.PgConnection@288501e4
[2021-05-25 13:21:00,001] [DEBUG] [DefaultQuartzScheduler_Worker-5] com.zaxxer.hikari.pool.HikariPool - monitoring - Add connection elided, waiting 4, queue 5
[2021-05-25 13:21:00,002] [DEBUG] [DefaultQuartzScheduler_Worker-8] com.zaxxer.hikari.pool.HikariPool - monitoring - Timeout failure stats (total=0, active=0, idle=0, waiting=3)

Also I noticed really weird behaviour. How can completely empty pool be at "sufficient level"?

[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - Before cleanup stats (total=0, active=0, idle=0, waiting=3)
[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - After cleanup  stats (total=0, active=0, idle=0, waiting=3)
[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - Fill pool skipped, pool is at sufficient level.

Cannot provide configuration from logs, so here is at least JMX.

image

image

image

image

bytor99999 commented 3 years ago

Same issue, tried everything I've found here. Sadly it heavily impacts production environment.

Java: jdk1.8.0_192 DB: Azure hosted - PostgreSQL 10.11, compiled by Visual C++ build 1800, 64-bit Driver: postgresql-42.2.14 Pool: HikariCP-3.4.5

Our appliaction has actually two pools pointing to the exact same database, the only difference is sizing. Both pools have leakDetectionTreshold configured and socketTimeout as dataSource parameter. There is no leak warning in logs, yet few days ago one pool just stopped working, unable to create new connection due to timeout, while the second pool is OK. Again, both pools point to the exact same database with same username and timeout configuration.

[2021-05-25 13:20:58,568] [DEBUG] [wso2 connection closer] com.zaxxer.hikari.pool.PoolBase - wso2 - Closing connection org.postgresql.jdbc.PgConnection@3fdbc150: (connection has passed maxLifetime)
[2021-05-25 13:20:58,744] [DEBUG] [wso2 connection adder] com.zaxxer.hikari.pool.HikariPool - wso2 - Added connection org.postgresql.jdbc.PgConnection@288501e4
[2021-05-25 13:21:00,001] [DEBUG] [DefaultQuartzScheduler_Worker-5] com.zaxxer.hikari.pool.HikariPool - monitoring - Add connection elided, waiting 4, queue 5
[2021-05-25 13:21:00,002] [DEBUG] [DefaultQuartzScheduler_Worker-8] com.zaxxer.hikari.pool.HikariPool - monitoring - Timeout failure stats (total=0, active=0, idle=0, waiting=3)

Also I noticed really weird behaviour. How can completely empty pool be at "sufficient level"?

[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - Before cleanup stats (total=0, active=0, idle=0, waiting=3)
[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - After cleanup  stats (total=0, active=0, idle=0, waiting=3)
[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - Fill pool skipped, pool is at sufficient level.

Cannot provide configuration from logs, so here is at least JMX.

image

image

image

image

brettwooldridge commented 3 years ago

@bytor99999 Thanks for the sarcasm. No good deed goes unpunished, I guess. I asked several times for more logs, but none were provided. Reproducing a bug that happens "couple times [per] year" is difficult when all you have is an anecdotal account. So far as the issue having never been assigned, it's just little old me, so I don't bother using the assignment feature.

Enjoy your retirement.

brettwooldridge commented 3 years ago

@bytor99999 I believe you can unsubscribe from notifications.

bytor99999 commented 3 years ago

Yeah, I finally figured it all out, right after I posted that I couldn't figure it out. Go figure. But good luck with this one.

Funny, too is it looks like if you unsubscribe, but then are mentioned in the issue, you get re-subscribed. ;)

Ryaryu commented 3 years ago

@TomasTokaMrazek Although it is contradictory to docs, I'm setting minimumIdle to 0 so HikariCP is always forced to create new connections. So far (~2 weeks of testing in production) I haven't got this connection issue. Or at least at a noticeable rate. Since it still seems to be random, I cannot say that it is the better approach for now (and since it forces the pool to constantly create connections, it certainly's not the better approach).

brettwooldridge commented 3 years ago

@TomasTokaMrazek Thank you for the logs. This log is particularly useful:

[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - After cleanup  stats (total=0, active=0, idle=0, waiting=3)
[2021-05-25 13:38:03,215] [DEBUG] [monitoring housekeeper] com.zaxxer.hikari.pool.HikariPool - monitoring - Fill pool skipped, pool is at sufficient level.

Can you try PostgeSQL driver v4.2.20? They have fixed a number of key issues in the past few releases, including these since v4.2.14 that you are using:

Fixed

  • isValid() timeout should not be blocked #1943 Cherry-picked #2076 The usage of setQueryTimeout(); with the same value as the setNetworkTimeout(); is blocking the current transaction timeout. The timeouts are blocking each other with this approach.

  • Fix: properly set cancel socket timeout (#2044)

  • Fix Connnection.isValid() to not wait longer than existing network timeout PR #2040

  • Make sure socketTimeout is enforced PR 1831 210b27a6

If the issue is semi-reproducible or occurring frequently enough, and you are running on Linux, the output of lsof from the application server where HikariCP and PostgreSQL is deployed would be useful -- captured when the pool is dead.

Any logs from PostgreSQL from just before until just after the pool stats go to zero could also prove useful. Documentation on enabling debug logging levels as well as log format strings can be found here.

TomasTokaMrazek commented 3 years ago

@brettwooldridge I've read the changelogs for pgjdbc, obviously not carefully enough as I missed the timeout fixes. I will update the driver as soon as possible.

I've enabled Hikari debug logs before server restart, so I should be able to provide as much info as possible when the next draining occurs. I'll keep in mind to lsof, for now I can only tell you the OS version centos-release-7-9.2009.1.el7.centos.x86_64. I don't know, if it is the factor, but ulimit is set to unlimited for basically everything.

As for PostgreSQL logs and lsof, I'm afraid I will not be able to provide them. We have PostgreSQL as PaaS in Azure, and while that might not be a blocker, I don't have direct access to that service either. I could escalate the request, if the issue persists after driver update.

I have to ask tho, I still find it weird, that the hikari logs report empty pool while reporting that it is at sufficient level. While the root cause might be in jdbc driver itself, I think that the report should indicate, that there actually are connections, be it still in active state or for example blocked state.

brettwooldridge commented 3 years ago

@TomasTokaMrazek Re: your last statement, I agree, and that is why I said those particular log messages are particularly useful. None of the other reports in this issue included that message when the pool was in fact empty. I am hoping that through careful dissection of the code, I can figure out how that can occur. I strongly suspect a race condition that leaves internal state inconsistent.

EDIT: One commonality that I notice is that all of the reported configurations have a minimumIdle that is lower than the maximumPoolSize. That is a certainly a clue. My company always runs with a fixed size pool (the default), which may be why in the +5 years we have been running it we have never encountered this issue. I'll let you know if I can come up with a reproduction scenario.

TomasTokaMrazek commented 3 years ago

@brettwooldridge One pool got depleted just moments ago. Here's pool configuration from logs after a restart.

[2021-05-31 13:18:23,571] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - Driver class org.postgresql.Driver found in Thread context class loader org.eclipse.core.runtime.internal.adaptor.ContextFinder@7a2d3f94
[2021-05-31 13:18:23,578] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - wso2 - configuration:
[2021-05-31 13:18:23,581] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - allowPoolSuspension.............false
[2021-05-31 13:18:23,582] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - autoCommit......................true
[2021-05-31 13:18:23,582] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - catalog.........................none
[2021-05-31 13:18:23,586] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - connectionInitSql...............none
[2021-05-31 13:18:23,586] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - connectionTestQuery.............none
[2021-05-31 13:18:23,586] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - connectionTimeout...............10000
[2021-05-31 13:18:23,586] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSource......................none
[2021-05-31 13:18:23,586] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSourceClassName.............none
[2021-05-31 13:18:23,587] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................none
[2021-05-31 13:18:23,587] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSourceProperties............{password=<masked>, socketTimeout=30}
[2021-05-31 13:18:23,587] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - driverClassName................."org.postgresql.Driver"
[2021-05-31 13:18:23,590] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - exceptionOverrideClassName......none
[2021-05-31 13:18:23,590] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
[2021-05-31 13:18:23,590] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............none
[2021-05-31 13:18:23,590] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000
[2021-05-31 13:18:23,590] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - initializationFailTimeout.......1
[2021-05-31 13:18:23,590] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - jdbcUrl.........................jdbc:postgresql://<masked>
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - leakDetectionThreshold..........30000
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - maxLifetime.....................1800000
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - maximumPoolSize.................100
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - metricRegistry..................none
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........none
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - minimumIdle.....................100
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - password........................<masked>
[2021-05-31 13:18:23,591] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - poolName........................"wso2"
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - readOnly........................false
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - registerMbeans..................true
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - schema..........................none
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - threadFactory...................internal
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - transactionIsolation............default
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - username........................"<masked>"
[2021-05-31 13:18:23,592] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
[2021-05-31 13:18:23,597] [INFO ] [sodexo-init-jdbc] com.zaxxer.hikari.HikariDataSource - wso2 - Starting...
[2021-05-31 13:18:23,804] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.pool.HikariPool - wso2 - Added connection org.postgresql.jdbc.PgConnection@1da0e3dd
[2021-05-31 13:18:23,808] [INFO ] [sodexo-init-jdbc] com.zaxxer.hikari.HikariDataSource - wso2 - Start completed.
[2021-05-31 13:18:23,908] [DEBUG] [wso2 housekeeper] com.zaxxer.hikari.pool.HikariPool - wso2 - Pool stats (total=1, active=0, idle=1, waiting=0)
[2021-05-31 13:18:23,955] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - Driver class org.postgresql.Driver found in Thread context class loader org.eclipse.core.runtime.internal.adaptor.ContextFinder@7a2d3f94
[2021-05-31 13:18:23,955] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - monitoring - configuration:
[2021-05-31 13:18:23,956] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - allowPoolSuspension.............false
[2021-05-31 13:18:23,956] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - autoCommit......................true
[2021-05-31 13:18:23,956] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - catalog.........................none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - connectionInitSql...............none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - connectionTestQuery.............none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - connectionTimeout...............10000
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSource......................none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSourceClassName.............none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - dataSourceProperties............{password=<masked>, socketTimeout=30}
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - driverClassName................."org.postgresql.Driver"
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - exceptionOverrideClassName......none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............none
[2021-05-31 13:18:23,957] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - initializationFailTimeout.......1
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - jdbcUrl.........................jdbc:postgresql://<masked>
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - leakDetectionThreshold..........30000
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - maxLifetime.....................1800000
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - maximumPoolSize.................5
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - metricRegistry..................none
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........none
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - minimumIdle.....................1
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - password........................<masked>
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - poolName........................"monitoring"
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - readOnly........................false
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - registerMbeans..................true
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - schema..........................none
[2021-05-31 13:18:23,958] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - threadFactory...................internal
[2021-05-31 13:18:23,959] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - transactionIsolation............default
[2021-05-31 13:18:23,959] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - username........................"<masked>"
[2021-05-31 13:18:23,959] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
[2021-05-31 13:18:23,959] [INFO ] [sodexo-init-jdbc] com.zaxxer.hikari.HikariDataSource - monitoring - Starting...
[2021-05-31 13:18:24,085] [DEBUG] [wso2 connection adder] com.zaxxer.hikari.pool.HikariPool - wso2 - Added connection org.postgresql.jdbc.PgConnection@4a8a57b0
[2021-05-31 13:18:24,134] [DEBUG] [sodexo-init-jdbc] com.zaxxer.hikari.pool.HikariPool - monitoring - Added connection org.postgresql.jdbc.PgConnection@12b1d73c
[2021-05-31 13:18:24,135] [INFO ] [sodexo-init-jdbc] com.zaxxer.hikari.HikariDataSource - monitoring - Start completed.

And here are Hikari logs during pool exhaustion and lsof from application server. hikari.log lsof.txt

We also switched to newest PG driver 42.2.20

EDIT: We didn't change pool configuration and this time "wso2" pool got depleted. Pool with the same minimumIdle and maximumPoolSize.

brettwooldridge commented 3 years ago

@huangyayu What is happening with these logs? Did you remove some?

2021-05-07 17:35:33 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Before cleanup stats (total=20, active=0, idle=20, waiting=0)
2021-05-07 17:35:33 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - After cleanup  stats (total=20, active=0, idle=20, waiting=0)
2021-05-07 17:35:33 DEBUG [com.zaxxer.hikari.pool.HikariPool:517] HikariPool-3 - Fill pool skipped, pool is at sufficient level.
2021-05-07 17:36:03 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Before cleanup stats (total=19, active=0, idle=19, waiting=0)
2021-05-07 17:36:03 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - After cleanup  stats (total=19, active=0, idle=19, waiting=0)
2021-05-07 17:47:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:50:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:50:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:342] HikariPool-3 - Add connection elided, waiting 1, queue 2
2021-05-07 17:51:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:51:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:342] HikariPool-3 - Add connection elided, waiting 1, queue 2
2021-05-07 17:52:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:421] HikariPool-3 - Timeout failure stats (total=0, active=0, idle=0, waiting=0)
2021-05-07 17:52:00 DEBUG [com.zaxxer.hikari.pool.HikariPool:342] HikariPool-3 - Add connection elided, waiting 1, queue 2

I see the housekeeper run at 17:35:33, and then 30 seconds later at 17:36:03, which is correct (every 30s). But then there is a 4-minute skip to 17:47:00. And then a 3-minute skip to 17:50:00. This should not be possible.

brettwooldridge commented 3 years ago

@TomasTokaMrazek Are you really running a pool with 100 connections? Did you read About pool sizing?

TomasTokaMrazek commented 3 years ago

@brettwooldridge I do run a pool with 100 connections, I did read about pool sizing, several times actually. I am planning to lover it slowly, but we've encountered a lot of pool exhaustion issues (not related to HikariCP per se, there's Tomcat Pool for appliation server internals). Higher connection pool helped a lot, even at the price of slightly worse performance. Now we have about 5 minutes to act, when pool does not create new connections. Besides our Postgres subscription in Azure allows currently 7500 simultaneous connections and CPU barely hits 20%. Active connections are in 95% cases under 5, sometimes it jumps to 10, and there is one time (in our metrics) in the last two days, when it was above 40. It's more of a buffer of connections, we do not actrively use all of them.

TomasTokaMrazek commented 3 years ago

@brettwooldridge FYI so far so good, no pool exhaustion with newest PG jdbc.

ncorreard commented 3 years ago

Hello there, I have the same, although, as far as I can tell, it's only happened once, on 1 server out of 6, and in over a year.

Spring 2.2.7.RELEASE, HikariCP 3.4.3, Postgres driver 42.2.18.

We'll upgrade to the latest driver, and hope that we never see this again, but hoping info here can help troubleshoot the issue.

spring.datasource.hikari.minimum-idle=10
spring.datasource.hikari.maximum-pool-size=20

There was absolutely no traffic on this server at the time; a few anomalies pointing to possibly a network issue, which might explain why database connections could not be established (although no trace of errors there).

The pool remained at 0 for several hours (until the server was restarted) A couple of hours after the pool depleted, traffic picked up, and requests were then timing out after the default 30 seconds: java.sql.SQLTransientConnectionException: HikariCP-Pool - Connection is not available, request timed out after 30001ms.; as expected with an empty pool...

The logs:

2021-06-29T01:00:09.49957714Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:00:09.499628265Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:00:09.499645469Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:00:39.500073285Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:00:39.50014193Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:00:39.500153115Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:01:09.500430648Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:01:09.500476543Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:01:09.500506514Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:01:39.500917543Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:01:39.500969329Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:01:39.500976971Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:02:09.501257526Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:02:09.501347133Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:02:09.501358873Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:02:39.501673118Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:02:39.501746493Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:02:39.501757056Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:03:09.502149824Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:03:09.502239242Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:03:09.50225113Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:03:39.502513634Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:03:39.502577477Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:03:39.502586818Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:03:51.301645809Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@77ee65c3: (connection has passed maxLifetime)
2021-06-29T01:03:51.378162954Z  --- [onnection adder] class=HikariPool   method=call   HikariCP-Pool - Added connection org.postgresql.jdbc.PgConnection@6b03c51
2021-06-29T01:04:09.502926235Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:04:09.502976534Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:04:09.502984864Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:04:39.503374865Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:04:39.503439295Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:04:39.50345082Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:05:09.503792364Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:05:09.503898772Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:05:09.503910288Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:05:39.50431245Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:05:39.504381693Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:05:39.50447626Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:06:09.504914021Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:06:09.504990971Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:06:09.505003689Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:06:39.505361102Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:06:39.505425864Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:06:39.505454275Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:06:48.468215048Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@2c57dec8: (connection has passed maxLifetime)
2021-06-29T01:06:48.511801881Z  --- [onnection adder] class=HikariPool   method=call   HikariCP-Pool - Added connection org.postgresql.jdbc.PgConnection@54c76d75
2021-06-29T01:07:06.569838289Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@2c2f9b47: (connection has passed maxLifetime)
2021-06-29T01:07:06.58737191Z  --- [onnection adder] class=HikariPool   method=call   HikariCP-Pool - Added connection org.postgresql.jdbc.PgConnection@709a149c
2021-06-29T01:07:09.505913315Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:07:09.506067032Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:07:09.506087933Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:07:39.506576515Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:07:39.506624414Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:07:39.506632485Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:07:46.740513308Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@26d6d5ba: (connection has passed maxLifetime)
2021-06-29T01:07:46.794847705Z  --- [onnection adder] class=HikariPool   method=call   HikariCP-Pool - Added connection org.postgresql.jdbc.PgConnection@235f7b70
2021-06-29T01:08:09.506940981Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:08:09.506991341Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=10, active=0, idle=10, waiting=0)
2021-06-29T01:08:09.507000331Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:08:18.28318327Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@2129067d: (connection has passed maxLifetime)
2021-06-29T01:08:18.363369171Z  --- [onnection adder] class=HikariPool   method=call   HikariCP-Pool - Added connection org.postgresql.jdbc.PgConnection@6f156098
2021-06-29T01:08:20.151587209Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@4c4cc607: (connection has passed maxLifetime)
2021-06-29T01:08:39.507316652Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=9, active=0, idle=9, waiting=0)
2021-06-29T01:08:39.507365809Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=9, active=0, idle=9, waiting=0)
2021-06-29T01:08:39.507374499Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:08:56.927597178Z  --- [ool housekeeper] class=HikariPool   method=addBagItem  HikariCP-Pool - Add connection elided, waiting 0, queue 1
2021-06-29T01:08:56.928889001Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@28c635c5: (connection has passed maxLifetime)
2021-06-29T01:09:05.942431229Z  --- [ool housekeeper] class=HikariPool   method=addBagItem  HikariCP-Pool - Add connection elided, waiting 0, queue 2
2021-06-29T01:09:05.942510543Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@788b0207: (connection has passed maxLifetime)
2021-06-29T01:09:08.319300363Z  --- [ool housekeeper] class=HikariPool   method=addBagItem  HikariCP-Pool - Add connection elided, waiting 0, queue 3
2021-06-29T01:09:08.319524591Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@7cb48949: (connection has passed maxLifetime)
2021-06-29T01:09:09.507762761Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=6, active=0, idle=6, waiting=0)
2021-06-29T01:09:09.50786155Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=6, active=0, idle=6, waiting=0)
2021-06-29T01:09:09.508270457Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:09:39.508292778Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=6, active=0, idle=6, waiting=0)
2021-06-29T01:09:39.508351035Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=6, active=0, idle=6, waiting=0)
2021-06-29T01:09:39.508411535Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:10:09.508863811Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=6, active=0, idle=6, waiting=0)
2021-06-29T01:10:09.508936933Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=6, active=0, idle=6, waiting=0)
2021-06-29T01:10:09.508949202Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:10:24.003927023Z  --- [ool housekeeper] class=HikariPool   method=addBagItem  HikariCP-Pool - Add connection elided, waiting 0, queue 4
2021-06-29T01:10:24.004640073Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@6d01ce23: (connection has passed maxLifetime)
2021-06-29T01:10:39.509278991Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:10:39.509328959Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:10:39.509350526Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:11:09.509761952Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:11:09.50983824Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:11:09.509851454Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:11:39.510290608Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:11:39.51034942Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:11:39.51035739Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:12:09.510650825Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:12:09.510707035Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:12:09.510718653Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:12:39.511157062Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:12:39.511205324Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:12:39.511213435Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:13:09.511609779Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:13:09.511666268Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:13:09.511746067Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:13:39.512067169Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:13:39.51215596Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:13:39.512205084Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:14:09.512559362Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:14:09.512609493Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:14:09.512618157Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:14:39.513180797Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:14:39.513241737Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:14:39.513250501Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:15:09.513515045Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:15:09.513577992Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:15:09.513597052Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:15:39.513841408Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:15:39.513889186Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:15:39.513964944Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:16:09.514291971Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:16:09.514348694Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:16:09.514360069Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:16:39.514774739Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:16:39.514850311Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:16:39.514954256Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:17:09.515316585Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:17:09.515373943Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:17:09.515382199Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:17:39.515865467Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:17:39.515956812Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:17:39.515969071Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:18:09.516253452Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:18:09.516308871Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:18:09.51631763Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:18:39.516509215Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:18:39.516575373Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:18:39.516588366Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:19:09.517159524Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:19:09.517235574Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:19:09.517247644Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:19:39.517455051Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:19:39.518628897Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:19:39.519209522Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:20:09.517881635Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:20:09.517936623Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:20:09.517946308Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:20:39.518350225Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:20:39.518405452Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:20:39.518414191Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:21:09.518837812Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:21:09.518894729Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:21:09.518903179Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:21:39.519335494Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:21:39.519426571Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:21:39.519473398Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:22:09.519796614Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:22:09.519885103Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:22:09.519894573Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:22:39.520244203Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:22:39.520368613Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:22:39.520386302Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:23:09.520596045Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:23:09.520645563Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:23:09.520656771Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:23:39.521190075Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:23:39.521270343Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:23:39.521284373Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:24:09.521499449Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:24:09.521558434Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:24:09.52156739Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:24:39.52188109Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:24:39.52201449Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:24:39.522075882Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:25:09.522444725Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:25:09.522542199Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:25:09.522556085Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:25:39.52273193Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:25:39.522782444Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:25:39.522790339Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:26:09.523218806Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:26:09.523277074Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:26:09.523285777Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:26:39.523546817Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:26:39.523659005Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:26:39.523700401Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:27:09.524115564Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:27:09.524171598Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:27:09.524180265Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:27:39.524503071Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:27:39.524567885Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:27:39.52458053Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:28:09.524999005Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:28:09.52509318Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:28:09.525129636Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:28:39.525410395Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:28:39.525471877Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:28:39.525480293Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:29:09.525889203Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:29:09.525947083Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:29:09.525955797Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:29:39.526215978Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:29:39.526299654Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:29:39.526315465Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:30:09.526582797Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:30:09.526628154Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:30:09.526660111Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:30:39.527122193Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:30:39.527192555Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:30:39.527214937Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:31:09.527553499Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:31:09.52760292Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:31:09.527610362Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:31:39.528067675Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:31:39.528118977Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:31:39.528127087Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:32:09.528483697Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:32:09.528540421Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:32:09.528549088Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:32:39.528743219Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:32:39.528796679Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=5, active=0, idle=5, waiting=0)
2021-06-29T01:32:39.528813139Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:33:07.453472655Z  --- [ool housekeeper] class=HikariPool   method=addBagItem  HikariCP-Pool - Add connection elided, waiting 0, queue 5
2021-06-29T01:33:07.453567154Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@6b03c51: (connection has passed maxLifetime)
2021-06-29T01:33:09.529342826Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:33:09.529404025Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:33:09.529430415Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:33:39.529638727Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:33:39.529691038Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:33:39.529700583Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:34:09.530121403Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:34:09.530197531Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:34:09.530206232Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:34:39.530431809Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:34:39.530505529Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:34:39.5305207Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:35:09.530791571Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:35:09.530879886Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:35:09.530890606Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:35:39.531218851Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:35:39.531297708Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:35:39.531312217Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:36:09.531769424Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:36:09.531872485Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=4, active=0, idle=4, waiting=0)
2021-06-29T01:36:09.531886214Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:36:21.819081062Z  --- [ool housekeeper] class=HikariPool   method=addBagItem  HikariCP-Pool - Add connection elided, waiting 0, queue 6
2021-06-29T01:36:21.819233355Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@54c76d75: (connection has passed maxLifetime)
2021-06-29T01:36:26.981083206Z  --- [ool housekeeper] class=HikariPool   method=addBagItem  HikariCP-Pool - Add connection elided, waiting 0, queue 7
2021-06-29T01:36:26.981164912Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@709a149c: (connection has passed maxLifetime)
2021-06-29T01:36:39.532479584Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=2, active=0, idle=2, waiting=0)
2021-06-29T01:36:39.532536753Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=2, active=0, idle=2, waiting=0)
2021-06-29T01:36:39.532544952Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:37:08.892000145Z  --- [ool housekeeper] class=HikariPool   method=addBagItem  HikariCP-Pool - Add connection elided, waiting 0, queue 8
2021-06-29T01:37:08.892060929Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@235f7b70: (connection has passed maxLifetime)
2021-06-29T01:37:09.532683903Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=1, active=0, idle=1, waiting=0)
2021-06-29T01:37:09.532737619Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=1, active=0, idle=1, waiting=0)
2021-06-29T01:37:09.532744965Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:37:33.710740649Z  --- [ool housekeeper] class=HikariPool   method=addBagItem  HikariCP-Pool - Add connection elided, waiting 0, queue 9
2021-06-29T01:37:33.710927581Z  --- [nnection closer] class=PoolBase     method=quietlyCloseConnection                   : HikariCP-Pool - Closing connection org.postgresql.jdbc.PgConnection@6f156098: (connection has passed maxLifetime)
2021-06-29T01:37:39.533289121Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:37:39.533361054Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:37:39.533373058Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:38:09.533570366Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:38:09.533627264Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:38:09.533636121Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:38:39.534016165Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:38:39.534148709Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:38:39.534187612Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:39:09.534634757Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:39:09.534716188Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:39:09.534731419Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
2021-06-29T01:39:39.53497712Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - Before cleanup stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:39:39.535031822Z  --- [ool housekeeper] class=HikariPool   method=logPoolState  HikariCP-Pool - After cleanup  stats (total=0, active=0, idle=0, waiting=0)
2021-06-29T01:39:39.535040161Z  --- [ool housekeeper] class=HikariPool   method=fillPool  HikariCP-Pool - Fill pool skipped, pool is at sufficient level.
ashviswam commented 2 years ago

@brettwooldridge The issue occurs with a fixed sized pool too. This error occurs randomly in any of the pods.

HikariCP:3.4.5 Spring Boot: 2.3.4-RELEASE JDBC Driver: Microsoft SQL Server

The logs are very similar to the previous one posted here.

I see that you've added a fix for the issue in the latest version 5.0.0.

krandhir commented 2 years ago

@brettwooldridge

Used the version 5.0.0 but still pool size becomes zero and no new connections are added. Only solution we see for now is to keep monitoring and restart the POD as soon as the POOL drains out. 

HikariCP:5.0.0
Spring Boot: 2.3.4-RELEASE
JDBC Driver: Microsoft SQL Server
spring.datasource.hikari.maximum-pool-size=20
spring.datasource.hikari.leak-detection-threshold=20000
spring.datasource.hikari.max-lifetime=30000

Looks like your recent fix also didn't solve the issue.

logs:

2021-10-16 20:31:45.669 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=13 2021-10-16 20:31:45.669 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68700 ClientConnectionId: 1a185b9a-6fec-4fe4-b269-332f277b1fe0: (connection has passed maxLifetime) 2021-10-16 20:31:45.698 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=14 2021-10-16 20:31:45.698 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68701 ClientConnectionId: 5469f543-f26b-4f13-85b0-d92202658cc6: (connection has passed maxLifetime) 2021-10-16 20:31:46.545 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=15 2021-10-16 20:31:46.545 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68702 ClientConnectionId: fb7b6930-1b40-4fc0-9314-30706727b766: (connection has passed maxLifetime) 2021-10-16 20:31:46.760 INFO 1 --- [nio-8080-exec-8] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:31:47.087 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=5, active=0, idle=5, waiting=0) 2021-10-16 20:31:47.199 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68703 ClientConnectionId: cbfcdbe4-b47e-433a-bc91-c02e77a33960: (connection has passed maxLifetime) 2021-10-16 20:31:47.199 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=17 2021-10-16 20:31:47.488 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68704 ClientConnectionId: 4eef9b94-8e1c-4d92-8d2f-a351bbdc6185: (connection has passed maxLifetime) 2021-10-16 20:31:47.488 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=17 2021-10-16 20:31:47.648 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=17 2021-10-16 20:31:47.648 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68705 ClientConnectionId: 9649835b-2d1c-49b2-a5eb-f99459b99fcb: (connection has passed maxLifetime) 2021-10-16 20:31:48.898 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=17 2021-10-16 20:31:48.898 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68707 ClientConnectionId: 78dc2f69-d4bc-4a99-912f-5f9ef17d2e2d: (connection has passed maxLifetime) 2021-10-16 20:31:48.960 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Add connection elided, waiting=0, adders pending/running=17 2021-10-16 20:31:48.960 DEBUG 1 --- [nnection closer] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Closing connection ConnectionID:68706 ClientConnectionId: eb60394a-9e49-4321-b551-efe6a1a9557b: (connection has passed maxLifetime) 2021-10-16 20:31:51.760 INFO 1 --- [nio-8080-exec-9] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:31:56.760 INFO 1 --- [io-8080-exec-10] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:01.760 INFO 1 --- [nio-8080-exec-1] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:06.760 INFO 1 --- [nio-8080-exec-2] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:11.760 INFO 1 --- [nio-8080-exec-3] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:16.760 INFO 1 --- [nio-8080-exec-4] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:17.087 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=0, active=0, idle=0, waiting=0) 2021-10-16 20:32:21.760 INFO 1 --- [nio-8080-exec-5] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:26.760 INFO 1 --- [nio-8080-exec-6] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:31.760 INFO 1 --- [nio-8080-exec-7] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:36.760 INFO 1 --- [nio-8080-exec-8] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:41.760 INFO 1 --- [nio-8080-exec-9] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:46.760 INFO 1 --- [io-8080-exec-10] c.a.p.d.c.HealthCheckController : Health status: 200 OK 2021-10-16 20:32:47.087 DEBUG 1 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=0, active=0, idle=0, waiting=0)

tioxo commented 2 years ago

HikariCP: 3.4.5 PostgreSQL JDBC: 42.2.18

We're now also upgrading to the latest HikariCP version (5.0.x) and PostgreSQL JDBC version hoping this will be the cure. But because @krandhir has mentioned that this issue may not be entirely resolved with the new version, I've decided to also share our story. Will keep you posted when it occurs again with 5.0.x.

We've had multiple outages due to this issue which required a manual restart of the app to recover - yesterday it even happened twice. Once just at the end of business hours and once during the night after which it stayed in this broken state for many hours as we only page operators during business hours.

Edit 2: It turned out, that this was actually a problem with RHEL. A system admin restarted the firewalld service which cut our java application running within a podman container entirely off from the network. Using a heap dump we've figured out HikariCP correctly continued trying to connect, so that part kept working.

davidvuletas commented 2 years ago 
HikariCP:5.6.5.Final
Postgresql driver: 42.4.0

Hello @brettwooldridge , I think that I have a similar error. A few times per day one of our pods is facing issue that has a lot of connections in a WAITING state, this problem mostly disappears after 1 minute, but it is blocking customers to use API over that period of time. Here are Hikari logs from that period of time hikarilogs.csv

brettwooldridge commented 2 years ago

@davidvuletas It seems clear to me that the issue is on the PostgreSQL-side. This has been a most elusive issue to nail down. It is clear from the logs that HikariCP is trying its best to establish new connections, but ultimately PostgreSQL refuses. If this is happening frequently, you are in the best position of anyone I've spoken with to help resolve this once and for all. What would be really useful would be PostgreSQL logging.

Logging is documented here. In particular, if you can enable log_connections, log_disconnections, log_error_verbosity=VERBOSE, and configure log_line_prefix using your best judgement.

brettwooldridge commented 2 years ago

@davidvuletas If you encounter the pool going to zero, can you run this query in psql against your server?

select pid as process_id, 
       usename as username, 
       datname as database_name, 
       client_addr as client_address, 
       application_name,
       backend_start,
       state,
       state_change
from pg_stat_activity;
davidvuletas commented 2 years ago

@davidvuletas If you encounter the pool going to zero, can you run this query in psql against your server?

It's hard to execute this query at the time of losing connection because it happens at a random period of the day and it takes 1 minute. I executed the query right now. And this is the result. pg_stat_activity.csv

alromos commented 1 year ago

@brettwooldridge Our team faced the same issue and we don't use PostgreSQL.

HicariCP version: 5.0.1
DB Provider: Microsoft SQL Azure (RTM) - 12.0.2000.8 Oct 18 2022 13:24:45 Copyright (C) 2022 Microsoft Corporation 
JDBC Driver: mssql-jdbc-11.2.1.jre17

Hikari Properties (Spring Boot):

spring.datasource.hikari.maximum-pool-size=50
spring.datasource.hikari.minimum-idle=10
spring.datasource.hikari.idle-timeout=300000
spring.datasource.hikari.connection-timeout=10000

At some random point of time (it happens about once in 2-3 months) we start to see those exceptions in our logs:

Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 10000ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:181)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:146)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
    at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:159)
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:117)
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:80)
       ...

The pool can be recovered only by application restart. In Production we have 2 application instances and one of them may be affected by the issue while another one continues to work without any connection issues.

Also I found the following issues in your repository describing the same: #1942 (PostgreSQL) #1982 (Azure DB + mssql-jdbc)

chilembomusafili commented 1 year ago

I am also experiencing same issue only this time with Oracle DB and hikariPool on a springboot app, was there a solution found??

dmis-2000 commented 1 year ago

I know this thread is rather old. We are experiencing this issue currently as well.

MSSQL Driver 8.2 HikariCP 5.0.2

Was there any other recommendations or thoughts? We will be upgrading to the latest MSSQL driver - 12.2

Ryaryu commented 1 year ago

I only managed to "solve" this by forcing HikariCP to renew connections using idleTimeouts.

dmis-2000 commented 1 year ago

I only managed to "solve" this by forcing HikariCP to renew connections using idleTimeouts.

Could you give me a bit more information/example of what you did. We are struggling and I'm interested in any options people tried. Thank you.

simymylooran commented 1 year ago

@brettwooldridge / others

Any update on this issue ? It is happening very frequently in our production environment too ..

Issue seems to be in this method. 'shouldAdd' became false even when there 0 idle connection.

synchronized void fillPool(final boolean isAfterAdd) https://github.com/brettwooldridge/HikariCP/blob/HikariCP-5.0.1/src/main/java/com/zaxxer/hikari/pool/HikariPool.java#L508

simymylooran commented 1 year ago

@brettwooldridge / others

Any update on this issue ? It is happening very frequently in our production environment too ..

Issue seems to be in this method. 'shouldAdd' became false even when there 0 idle connection.

synchronized void fillPool(final boolean isAfterAdd) https://github.com/brettwooldridge/HikariCP/blob/HikariCP-5.0.1/src/main/java/com/zaxxer/hikari/pool/HikariPool.java#L508

getting 'Fill pool skipped, pool has sufficient level or currently being filled' in debug log even when idle connection count is zero

simymylooran commented 1 year ago

I only managed to "solve" this by forcing HikariCP to renew connections using idleTimeouts. @Ryaryu , can you please help us with more details ? What value is recommended for idleTimeouts ?

brettwooldridge commented 1 year ago

@simymylooran This is a breakdown if the logic. Let me know if you can spot a "seam" in the logic.

final var queueDepth = addConnectionQueueDepth.get();
final var countToAdd = connectionBag.getWaitingThreadCount() - queueDepth;

For example, if 5 threads are awaiting a connection, and there are 3 tasks already queued to add new connections, then countToAdd will be 2 ... meaning "2 more connection add tasks" need to be created.

Now, let's look at shouldAdd...

final var shouldAdd =
   getTotalConnections() < config.getMaximumPoolSize() &&
   (getIdleConnections() < config.getMinimumIdle() || countToAdd > getIdleConnections());

If we assume the pool has fallen to zero connections, likely indicated in debug logs, then getTotalConnections() < config.getMaximumPoolSize() should be true. At least that portion of the conditional should be true.

Which leaves us with (getIdleConnections() < config.getMinimumIdle() || countToAdd > getIdleConnections()).

Now, if we assume that getIdleConnections() is also zero, because the total pool size is zero, and assuming minimumIdle is configured as non-zero, we can assume that part of the expression is true.

That is enough to result in shouldAdd being true.

However, if we assume that minimumIdle is configured as 0, then shouldAdd will now be false. Only then do we get to the last part of the conditional, || countToAdd > getIdleConnections().

Again, if the pool has fallen to 0 connections, then getIdleConnections() will also be 0, and this should be reflected in the debug log. For example:

21-10-16 20:32:17 DEBUG - [housekeeper] <snip> : HikariPool-1 - Pool stats (total=0, active=0, idle=0, waiting=0)

Therefore, if countToAdd is positive, then shouldAdd will obviously become true.

However, if there are no waiting threads, then countToAdd will be:

And therefore this last part of the expression will be false, resulting in shouldAdd being false.

HOWEVER, if countToAdd is zero or negative, that indicates that there are already add connection tasks queued and running. Therefore, connections will be added as long as those connection attempts succeed.

The "Fill pool skipped, pool has sufficient level or currently being filled" that you cited should include the current count of the number of add connections tasks are in the queue:

logger.debug("{} - Fill pool skipped, pool has sufficient level or currently being filled (queueDepth={}).", poolName, queueDepth);

So, if queueDepth is being logged as 0, then we have an issue. However, if it is non-zero then there is a different issue -- i.e. the add connection tasks are not able, for whatever reason, to successfully establish new connections.

👉 Can you tell me if minimumIdle is configured as 0 in your pool? And can you tell me what queueDepth is logged when your pool goes to zero?

simymylooran commented 1 year ago

3 tasks already queued to add new connections

thanks for the response .. I did further analysis ...

3 tasks already queued to add new connections Noticed that adding to queue is happening .. But, for some reason thread executer is not picking it and adding connection .. We couldn't debug further as this is not happening all the time ..

Now, we have implemented some workaround to monitor IdleConnections, and if it is less for sometime, restart entire connection pool !

npathai commented 1 year ago

@simymylooran We are facing exactly the same issue with Hikari and MSSQL. Can you describe a bit how did you implement the workaround solution to restart?

brettwooldridge commented 1 year ago

@simymylooran Thank you for the feedback. It is disturbing, though informative, that a restart addresses the issue.

It is interesting looking at the .csv output of established connections from the database perspective provided by another user. Their .csv indicates a large number of connections from the database-side, yet zero connections in the pool.

This to me indicates that the close connection path may not be actually retiring connections under some conditions. I am satisifed, for now, that the add-connection path is correct, so I am going to focus my investigation on the close path.

If you run into this condition again, anything you can do to collect connection information from the database-side of the equation would be very informative.

npathai commented 1 year ago

@brettwooldridge What information do we need from the database side? Next time we run into the issue I will try to collect that information. Also, we are working on adding observability and metrics from Hikari to troubleshoot this issue. If you can provide list of the metrics we need for troubleshooting will be really helpful. Thanks.

brettwooldridge commented 1 year ago

@npathai I know that for PostgreSQL you can query connection status like this:

select pid as process_id, 
       usename as username, 
       datname as database_name, 
       client_addr as client_address, 
       application_name,
       backend_start,
       state,
       state_change
from pg_stat_activity;

I do not know what the MSSQL equivalent is, but I am sure that it exists.

simymylooran commented 1 year ago

@simymylooran We are facing exactly the same issue with Hikari and MSSQL. Can you describe a bit how did you implement the workaround solution to restart?

My workaround was completely external (to connection pool).. A scheduled job to monitor idle connection size, and if it continues to be zero for sometime, restart ..

crazyjurich commented 1 year ago

I have also faced this issue on customer environment. com.zaxxer:HikariCP:jar:4.0.3 org.postgresql:postgresql:jar:42.2.12

c.z.h.p.HikariPool - HikariPool-1 - Pool stats (total=0, active=0, idle=0, waiting=0) c.z.h.p.HikariPool - HikariPool-1 - Add connection elided, waiting 1, queue 9

The issue appeared on many services (keycloak as well!!) without any change to the code and config, and disappeared without any change to the code and config. So the issue is likely caused by network or postgres or DB load balancer we use. But still it is handled by Hikari incorrectly - single "connection adder" thread was stuck and nothing happened, no errors in log.

I tried to reproduce the issue. When I just abruptly terminate the connection to DB with firewall, Hikari detects it fast and after connection is back, pool is filled instantly. Errors are also logged about being unable to connect.

Then I tried this:

sudo iptables -A INPUT -p tcp --destination-port 5433 -j DROP && sudo iptables -A OUTPUT -p tcp --source-port 5433 -j DROP sudo service postgresql stop nc -l 5433 sudo iptables -D INPUT -p tcp --destination-port 5433 -j DROP && sudo iptables -D OUTPUT -p tcp --source-port 5433 -j DROP

And it granted similar results to the subject issue - pool has 0 connections, connection queue stuck at ~9, no errors logged. socketTimeout connectstring parameter is a good thing to have in general, but in my case it didn't help. What did help is loginTimeout connectstring parameter, it interrupts the stuck connection thread, logs exception and attempts connecting again.

Also a good thing to diagnose similar issues is this config: org.postgresql: TRACE

ramzes3333 commented 9 months ago

Our team faced similar issue: com.zaxxer:HikariCP:jar:5.0.1 org.postgresql:postgresql:jar:42.6.0

This error occurs only on one pod. HikariCP does not renew the pool and gets stuck until the application is restarted.

Connections from grafana: image