search

brettwooldridge / HikariCP

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

Available connections in HikariPool occassionaly drop to zero and not being renewed #2161

Open igv-git opened 10 months ago

igv-git commented 10 months ago

Hello, We've encountered an issue with HikariPool when it runs out of connections and becomes compeletly unavailable as all requests would fail with an error:

SQLTransientConnection Exception: HikariPool-1 - Connection is not available, request timed out after 30000ms.

I've captured some additional logs from HikariPool when that happens:

[l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=0, active=0, idle=0, waiting=0)
[l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Fill pool skipped, pool is at sufficient level.
[nio-7096-exec-1] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Add connection elided, waiting 1, queue 10

Our environment

HikariCP version: 3.4.5
Java version     : 11
Database        : Oracle 12c
Driver version  : 18.3.0.0

After some researching I found out that the issue is caused by Hikari connection-adder thread being stuck on socket read operation. Once that happens, the connection pool becomes completely blocked as it's unable to add any new connections. Relevenant thread dump for a reference:

"HikariPool-1 connection adder" 274 daemon prio=5 os_prio=0 cpu=3.32ms elapsed=14365.84s tid=0x00007f9028004800 nid=0x11abd runnable  [0x00007f90166ea000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.FileDispatcherImpl.read0(java.base@11.0.20/Native Method)
    at sun.nio.ch.SocketDispatcher.read(java.base@11.0.20/SocketDispatcher.java:39)
    at sun.nio.ch.IOUtil.readIntoNativeBuffer(java.base@11.0.20/IOUtil.java:276)
    at sun.nio.ch.IOUtil.read(java.base@11.0.20/IOUtil.java:245)
    at sun.nio.ch.IOUtil.read(java.base@11.0.20/IOUtil.java:223)
    at sun.nio.ch.SocketChannelImpl.read(java.base@11.0.20/SocketChannelImpl.java:353)
    at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:178)
    at oracle.net.ns.NSProtocolNIO.doSocketRead(NSProtocolNIO.java:544)
    at oracle.net.ns.NIOPacket.readHeader(NIOPacket.java:234)
    at oracle.net.ns.NIOPacket.readPacketFromSocketChannel(NIOPacket.java:174)
    at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:122)
    at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:100)
    at oracle.net.ns.NIONSDataChannel.readDataFromSocketChannel(NIONSDataChannel.java:86)
    at oracle.jdbc.driver.T4CMAREngineNIO.prepareForUnmarshall(T4CMAREngineNIO.java:762)
    at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalUB1(T4CMAREngineNIO.java:427)
    at oracle.jdbc.driver.T4C8TTIdty.receive(T4C8TTIdty.java:732)
    at oracle.jdbc.driver.T4C8TTIdty.doRPC(T4C8TTIdty.java:643)
    at oracle.jdbc.driver.T4CConnection.connect(T4CConnection.java:1587)
    at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:540)
    at oracle.jdbc.driver.PhysicalConnection.connect(PhysicalConnection.java:782)
    at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:39)
    at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:704)
    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:138)
    at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:358)
    at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:206)
    at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:477)
    at com.zaxxer.hikari.pool.HikariPool.access$100(HikariPool.java:71)
    at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:725)
    at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:711)

I've tried to resolve it on DB driver level by adding timeout parameter oracle.jdbc.ReadTimeout but it didn't help as the thread still would get stuck at some point. Is there anything else we can try?

MrPowerGamerBR commented 9 months ago

Can confirm the same issue, the connection adder thread gets stuck and no connections are added to the pool.

What I have noticed is that what happens is the following:

  1. Application runs fine and well
  2. After a while (not sure when) the current active connections gets stuck, maybe due to network issues (?), this causes new connections to be waiting 
    2024-01-17 17:47:26,496 [PuddingPool connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - PuddingPool - Connection not added, stats (total=30, active=30, idle=0, waiting=2)
2024-01-17 17:47:26,496 [PuddingPool connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - PuddingPool - Connection not added, stats (total=30, active=30, idle=0, waiting=2)
2024-01-17 17:47:26,496 [PuddingPool connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - PuddingPool - Connection not added, stats (total=30, active=30, idle=0, waiting=3)
2024-01-17 17:47:26,497 [PuddingPool connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - PuddingPool - Connection not added, stats (total=30, active=30, idle=0, waiting=4)
2024-01-17 17:47:26,655 [PuddingPool connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - PuddingPool - Connection not added, stats (total=30, active=30, idle=0, waiting=5)
  3. The current active connections, after a while, are removed from the pool, but HikariCP fails to reconnect to the database due to...
2024-01-17 19:54:24,587 [pool-2-thread-5368 @coroutine#52534701] DEBUG com.zaxxer.hikari.pool.HikariPool - PuddingPool - Timeout failure stats (total=0, active=0, idle=0, waiting=128)
05:01:56.004 [DefaultDispatcher-worker-4 @coroutine#96539287] WARN  n.p.e.s.SuspendableNestedTransaction - Exception while trying to execute query. Tries: 1
org.jetbrains.exposed.exceptions.ExposedSQLException: java.sql.SQLTransientConnectionException: PuddingPool - Connection is not available, request timed out after 30000ms (total=0, active=0, idle=0, waiting=127)
        at org.jetbrains.exposed.sql.statements.Statement.executeIn$exposed_core(Statement.kt:49)
        at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:141)
        at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:127)
        at org.jetbrains.exposed.sql.AbstractQuery.iterator(AbstractQuery.kt:61)
        at org.jetbrains.exposed.sql.IterableExKt$mapLazy$1.iterator(IterableEx.kt:136)
        at kotlin.collections.CollectionsKt___CollectionsKt.firstOrNull(_Collections.kt:269)
        at org.jetbrains.exposed.dao.EntityClass.findById(EntityClass.kt:56)
        at org.jetbrains.exposed.dao.EntityClass.findById(EntityClass.kt:47)
        at net.perfectdreams.loritta.morenitta.LorittaBot._getOrCreateServerConfig(LorittaBot.kt:967)
        at net.perfectdreams.loritta.morenitta.LorittaBot.access$_getOrCreateServerConfig(LorittaBot.kt:163)
        at net.perfectdreams.loritta.morenitta.LorittaBot$getOrCreateServerConfig$3.invokeSuspend(LorittaBot.kt:949)
        at net.perfectdreams.loritta.morenitta.LorittaBot$getOrCreateServerConfig$3.invoke(LorittaBot.kt)
        at net.perfectdreams.loritta.morenitta.LorittaBot$getOrCreateServerConfig$3.invoke(LorittaBot.kt)
        at net.perfectdreams.exposedpowerutils.sql.SuspendableNestedTransactionKt$transaction$3$1$1.invokeSuspend(SuspendableNestedTransaction.kt:61)
        at net.perfectdreams.exposedpowerutils.sql.SuspendableNestedTransactionKt$transaction$3$1$1.invoke(SuspendableNestedTransaction.kt)
        at net.perfectdreams.exposedpowerutils.sql.SuspendableNestedTransactionKt$transaction$3$1$1.invoke(SuspendableNestedTransaction.kt)
        at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturn(Undispatched.kt:78)
        at kotlinx.coroutines.BuildersKt__Builders_commonKt.withContext(Builders.common.kt:167)
        at kotlinx.coroutines.BuildersKt.withContext(Unknown Source)
        at net.perfectdreams.exposedpowerutils.sql.SuspendableNestedTransactionKt$transaction$3$1.invokeSuspend(SuspendableNestedTransaction.kt:60)
        at net.perfectdreams.exposedpowerutils.sql.SuspendableNestedTransactionKt$transaction$3$1.invoke(SuspendableNestedTransaction.kt)
        at net.perfectdreams.exposedpowerutils.sql.SuspendableNestedTransactionKt$transaction$3$1.invoke(SuspendableNestedTransaction.kt)
        at org.jetbrains.exposed.sql.transactions.experimental.SuspendedKt$suspendedTransactionAsyncInternal$1.invokeSuspend(Suspended.kt:129)
        at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
        at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
        at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: java.sql.SQLTransientConnectionException: PuddingPool - Connection is not available, request timed out after 30000ms (total=0, active=0, idle=0, waiting=127)
        at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:686)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:179)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:144)
        at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:99)
        at org.jetbrains.exposed.sql.Database$Companion$connect$3.invoke(Database.kt:141)
        at org.jetbrains.exposed.sql.Database$Companion$connect$3.invoke(Database.kt:138)
        at org.jetbrains.exposed.sql.Database$Companion$doConnect$3.invoke(Database.kt:126)
        at org.jetbrains.exposed.sql.Database$Companion$doConnect$3.invoke(Database.kt:127)
        at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManager$ThreadLocalTransaction$connectionLazy$1.invoke(ThreadLocalTransactionManager.kt:76)
        at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManager$ThreadLocalTransaction$connectionLazy$1.invoke(ThreadLocalTransactionManager.kt:75)
        at kotlin.UnsafeLazyImpl.getValue(Lazy.kt:81)
        at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManager$ThreadLocalTransaction.getConnection(ThreadLocalTransactionManager.kt:89)
        at org.jetbrains.exposed.sql.Transaction.getConnection(Transaction.kt)
        at org.jetbrains.exposed.sql.statements.Statement.prepared(Statement.kt:24)
        at org.jetbrains.exposed.sql.statements.Statement.executeIn$exposed_core(Statement.kt:47)
        ... 27 common frames omitted
Caused by: org.postgresql.util.PSQLException: This connection has been closed.
        at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:993)
        at org.postgresql.jdbc.PgConnection.setNetworkTimeout(PgConnection.java:1694)
        at com.zaxxer.hikari.pool.PoolBase.setNetworkTimeout(PoolBase.java:562)
        at com.zaxxer.hikari.pool.PoolBase.isConnectionDead(PoolBase.java:169)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:168)
        ... 40 common frames omitted

I've also had other stacktraces related to read timeout

org.jetbrains.exposed.exceptions.ExposedSQLException: java.sql.SQLTransientConnectionException: PuddingPool - Connection is not available, request timed out after 30000ms (total=0, active=0, idle=0, waiting=128)
    at org.jetbrains.exposed.sql.statements.Statement.executeIn$exposed_core(Statement.kt:49)
    at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:141)
    at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:127)
    at org.jetbrains.exposed.sql.AbstractQuery.iterator(AbstractQuery.kt:61)
    at org.jetbrains.exposed.sql.IterableExKt$mapLazy$1.iterator(IterableEx.kt:136)
    at kotlin.collections.CollectionsKt___CollectionsKt.firstOrNull(_Collections.kt:269)
    at org.jetbrains.exposed.dao.EntityClass.findById(EntityClass.kt:56)
    at org.jetbrains.exposed.dao.EntityClass.findById(EntityClass.kt:47)
    at net.perfectdreams.loritta.morenitta.LorittaBot._getOrCreateServerConfig(LorittaBot.kt:967)
    at net.perfectdreams.loritta.morenitta.LorittaBot.access$_getOrCreateServerConfig(LorittaBot.kt:163)
    at net.perfectdreams.loritta.morenitta.LorittaBot$getOrCreateServerConfig$3.invokeSuspend(LorittaBot.kt:949)
    at net.perfectdreams.loritta.morenitta.LorittaBot$getOrCreateServerConfig$3.invoke(LorittaBot.kt)
    at net.perfectdreams.loritta.morenitta.LorittaBot$getOrCreateServerConfig$3.invoke(LorittaBot.kt)
    at net.perfectdreams.exposedpowerutils.sql.SuspendableNestedTransactionKt$transaction$3$1$1.invokeSuspend(SuspendableNestedTransaction.kt:61)
    at net.perfectdreams.exposedpowerutils.sql.SuspendableNestedTransactionKt$transaction$3$1$1.invoke(SuspendableNestedTransaction.kt)
    at net.perfectdreams.exposedpowerutils.sql.SuspendableNestedTransactionKt$transaction$3$1$1.invoke(SuspendableNestedTransaction.kt)
    at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturn(Undispatched.kt:78)
    at kotlinx.coroutines.BuildersKt__Builders_commonKt.withContext(Builders.common.kt:167)
    at kotlinx.coroutines.BuildersKt.withContext(Unknown Source)
    at net.perfectdreams.exposedpowerutils.sql.SuspendableNestedTransactionKt$transaction$3$1.invokeSuspend(SuspendableNestedTransaction.kt:60)
    at net.perfectdreams.exposedpowerutils.sql.SuspendableNestedTransactionKt$transaction$3$1.invoke(SuspendableNestedTransaction.kt)
    at net.perfectdreams.exposedpowerutils.sql.SuspendableNestedTransactionKt$transaction$3$1.invoke(SuspendableNestedTransaction.kt)
    at org.jetbrains.exposed.sql.transactions.experimental.SuspendedKt$suspendedTransactionAsyncInternal$1.invokeSuspend(Suspended.kt:129)
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
    at java.base/java.lang.Thread.run(Thread.java:1583)
Caused by: java.sql.SQLTransientConnectionException: PuddingPool - Connection is not available, request timed out after 30000ms (total=0, active=0, idle=0, waiting=128)
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:686)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:179)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:144)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:99)
    at org.jetbrains.exposed.sql.Database$Companion$connect$3.invoke(Database.kt:141)
    at org.jetbrains.exposed.sql.Database$Companion$connect$3.invoke(Database.kt:138)
    at org.jetbrains.exposed.sql.Database$Companion$doConnect$3.invoke(Database.kt:126)
    at org.jetbrains.exposed.sql.Database$Companion$doConnect$3.invoke(Database.kt:127)
    at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManager$ThreadLocalTransaction$connectionLazy$1.invoke(ThreadLocalTransactionManager.kt:76)
    at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManager$ThreadLocalTransaction$connectionLazy$1.invoke(ThreadLocalTransactionManager.kt:75)
    at kotlin.UnsafeLazyImpl.getValue(Lazy.kt:81)
    at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManager$ThreadLocalTransaction.getConnection(ThreadLocalTransactionManager.kt:89)
    at org.jetbrains.exposed.sql.Transaction.getConnection(Transaction.kt)
    at org.jetbrains.exposed.sql.statements.Statement.prepared(Statement.kt:24)
    at org.jetbrains.exposed.sql.statements.Statement.executeIn$exposed_core(Statement.kt:47)
    ... 27 common frames omitted
Caused by: org.postgresql.util.PSQLException: The connection attempt failed.
    at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:354)
    at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:54)
    at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:263)
    at org.postgresql.Driver.makeConnection(Driver.java:444)
    at org.postgresql.Driver.connect(Driver.java:297)
    at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:137)
    at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:360)
    at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:202)
    at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:461)
    at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:724)
    at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:703)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
    ... 3 common frames omitted
Caused by: java.net.SocketTimeoutException: Read timed out
    at java.base/sun.nio.ch.NioSocketImpl.timedRead(NioSocketImpl.java:278)
    at java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:304)
    at java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:346)
    at java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:796)
    at java.base/java.net.Socket$SocketInputStream.read(Socket.java:1099)
    at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:161)
    at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:128)
    at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:113)
    at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
    at org.postgresql.core.PGStream.receiveChar(PGStream.java:465)
    at org.postgresql.core.v3.ConnectionFactoryImpl.enableSSL(ConnectionFactoryImpl.java:589)
    at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:191)
    at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:258)
    ... 14 common frames omitted

Thread dump of the connection adder thread

"PuddingPool connection adder" #99448 [100703] daemon prio=5 os_prio=0 cpu=7.68ms elapsed=4420.23s tid=0x00007f308019b090 nid=100703 runnable  [0x00007f2fbdcfd000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.Net.poll(java.base@21.0.1/Native Method)
        at sun.nio.ch.NioSocketImpl.park(java.base@21.0.1/NioSocketImpl.java:191)
        at sun.nio.ch.NioSocketImpl.park(java.base@21.0.1/NioSocketImpl.java:201)
        at sun.nio.ch.NioSocketImpl.implRead(java.base@21.0.1/NioSocketImpl.java:309)
        at sun.nio.ch.NioSocketImpl.read(java.base@21.0.1/NioSocketImpl.java:346)
        at sun.nio.ch.NioSocketImpl$1.read(java.base@21.0.1/NioSocketImpl.java:796)
        at java.net.Socket$SocketInputStream.read(java.base@21.0.1/Socket.java:1099)
        at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:161)
        at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:128)
        at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:113)
        at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
        at org.postgresql.core.PGStream.receiveChar(PGStream.java:465)
        at org.postgresql.core.v3.ConnectionFactoryImpl.doAuthentication(ConnectionFactoryImpl.java:678)
        at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:203)
        at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:258)
        at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:54)
        at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:263)
        at org.postgresql.Driver.makeConnection(Driver.java:444)
        at org.postgresql.Driver.connect(Driver.java:297)
        at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:137)
        at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:360)
        at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:202)
        at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:461)
        at com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call(HikariPool.java:724)

I know that it isn't a "well you just don't have any connectivity to the database" issue because if I connect to the application container and connect to the PostgreSQL server with psql, it works fine, also restarting the application fixes the issue.

Sadly I'm not sure if this is a regression in the PostgreSQL driver or in HikariCP, the last time I updated them was ~one month ago. I was using pgjdbc 42.5.0 and HikariCP 5.0.1 and back then I didn't recall any issues like that, currently I'm using pgjdbc 42.7.1 and HikariCP 5.1.0. I will try downgrading the versions later to see if the issue persists or not.

Update: To be honest, I'm not 100% sure if this is the exactly the same issue because your HikariCP version is way way way older than mine (3.4.5 vs 5.1.0) and you are using a driver than I am.

patric-r commented 9 months ago

@igv-git:

  1. Share your pool config
  2. Try to reproduce the issue with the newest HikariCP release and a recent oracle jdbc driver
igv-git commented 9 months ago

@patric-r

  1. Currently we're using default values for hikari, so there is no specific config for the pool. Only exception is an environment where we're seeing that issue, I've added parameter there:

    spring:
datasource:
hikari:
  maxLifetime: 0

    to prevent connections from being removed from the pool as a temporary workaround.

  2. That will take some time, the issue is intermittent and we don't have any means to force it, it may take more then a week to appear. But I can confirm the same behaviour with HikariCP version 5.1.0. I've tried this version before and the same error appeared after some time, though we didn't try any other versions for oracle driver yet.

patric-r commented 9 months ago

  1. As I don't know what spring is doing behind the curtain - can you enable DEBUG Logging and paste the effective configuration HikariCP is using here?

  2. On which OS do you see this issue?

igv-git commented 9 months ago
  1. Sure, here're log entries for our default config: 
    10:03:01.979 [main] DEBUG c.z.h.HikariConfig - HikariPool-1 - configuration:
10:03:01.981 [main] DEBUG c.z.h.HikariConfig - allowPoolSuspension.............false
10:03:01.981 [main] DEBUG c.z.h.HikariConfig - autoCommit......................true
10:03:01.982 [main] DEBUG c.z.h.HikariConfig - catalog.........................none
10:03:01.982 [main] DEBUG c.z.h.HikariConfig - connectionInitSql...............none
10:03:01.982 [main] DEBUG c.z.h.HikariConfig - connectionTestQuery.............none
10:03:01.982 [main] DEBUG c.z.h.HikariConfig - connectionTimeout...............30000
10:03:01.982 [main] DEBUG c.z.h.HikariConfig - dataSource......................none
10:03:01.982 [main] DEBUG c.z.h.HikariConfig - dataSourceClassName.............none
10:03:01.982 [main] DEBUG c.z.h.HikariConfig - dataSourceJNDI..................none
10:03:01.982 [main] DEBUG c.z.h.HikariConfig - dataSourceProperties............{password=<masked>}
10:03:01.982 [main] DEBUG c.z.h.HikariConfig - driverClassName................."oracle.jdbc.OracleDriver"
10:03:01.982 [main] DEBUG c.z.h.HikariConfig - exceptionOverrideClassName......none
10:03:01.982 [main] DEBUG c.z.h.HikariConfig - healthCheckProperties...........{}
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - healthCheckRegistry.............none
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - idleTimeout.....................600000
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - initializationFailTimeout.......1
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - isolateInternalQueries..........false
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - jdbcUrl.........................<masked>
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - leakDetectionThreshold..........0
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - maxLifetime.....................1800000
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - maximumPoolSize.................10
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - metricRegistry..................none
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - metricsTrackerFactory...........none
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - minimumIdle.....................10
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - password........................<masked>
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - poolName........................"HikariPool-1"
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - readOnly........................false
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - registerMbeans..................false
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - scheduledExecutor...............none
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - schema..........................none
10:03:01.983 [main] DEBUG c.z.h.HikariConfig - threadFactory...................internal
10:03:01.984 [main] DEBUG c.z.h.HikariConfig - transactionIsolation............default
10:03:01.984 [main] DEBUG c.z.h.HikariConfig - username........................<masked>
10:03:01.984 [main] DEBUG c.z.h.HikariConfig - validationTimeout...............5000
  2. Linux (RHEL, version 7.9)
rajaasthana commented 8 months ago

Hi, did you solve this issue? We are experiencing same issue now.

MrPowerGamerBR commented 8 months ago

Hi, did you solve this issue? We are experiencing same issue now.

In my case, the issue was that the dedicated server was losing network connectivity, so the PostgreSQL JDBC driver was getting stuck on random network calls.

KazzmanK commented 8 months ago

Pretty much issues are connected with com.zaxxer.hikari.pool.PoolBase.isConnectionDead , this morning, after DB VM failure, we have same "Connection closed" exception in isConnectionDead routine, the outcome - no connection from pool available, timeout. https://github.com/brettwooldridge/HikariCP/issues/1705#issuecomment-1985365270 https://github.com/brettwooldridge/HikariCP/issues/1403#issuecomment-1985393205 Here is how it was looked inprocess image It was trying to fill pool with connections, but failed to do so. Once I have resources, reproduction should be like

Just to let you know, all my attempts to simulate and reproduce issue failed.

roee-gavriel commented 6 months ago

Having the same issue here. We encountering the following message

HikariPool-1 - Connection is not available, request timed out after 5000ms (total=0, active=0, idle=0, waiting=0)
rigotre7 commented 5 months ago

Similar issue with Hikari 4.0.3.

Logs:

2024-05-29 17:02:53.780   DEBUG 19 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : ****-db-pool - Pool stats (total=0, active=0, idle=0, waiting=0)
2024-05-29 17:02:53.780   DEBUG 19 --- [ool housekeeper] com.zaxxer.hikari.pool.HikariPool        : ****-db-pool - Fill pool skipped, pool is at sufficient level.
2024-05-29 17:02:57.660 /****-microservice-api/6308 XXXXXX1000 DEBUG 19 --- [nio-8080-exec-1] com.zaxxer.hikari.pool.HikariPool        : ****-db-pool - Add connection elided, waiting 1, queue 10
2024-05-29 17:03:07.667 /****-microservice-api/6308 XXXXXX1000 DEBUG 19 --- [nio-8080-exec-1] com.zaxxer.hikari.pool.HikariPool        : ****-db-pool - Timeout failure stats (total=0, active=0, idle=0, waiting=0)

As you can see, my pool has 0 connections and 10 queued up to be opened. However, each time a user hits our API it results in a timeout with an "Unable to acquire JDBC connection" error and the following SQL error indicating the connections have been closed:

SQL Error: 0, SQLState: 08003

    ... 127 more
Caused by: java.sql.SQLTransientConnectionException: miluma-db-pool - Connection is not available, request timed out after 30000ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:100)
    at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
    at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:108)
    ... 131 more
Caused by: org.postgresql.util.PSQLException: This connection has been closed.
    at org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:885)
    at org.postgresql.jdbc.PgConnection.setNetworkTimeout(PgConnection.java:1610)
    at com.zaxxer.hikari.pool.PoolBase.setNetworkTimeout(PoolBase.java:566)
    at com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:173)
    at com.zaxxer.hikari.pool.HikariPool$KeepaliveTask.run(HikariPool.java:847)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
    at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    ... 1 more

I've connected to the docker container which is running this API and can successfully telnet to my database so I know it's accessible. Furthermore, we have about 6 other services on the same network connecting to the same database. It happens mostly with this specific container.

Hikari Config: maxLifetime: 45000 maxPoolSize: 15 minimumIdle: 5 connectionTimeout: 10000 keepAliveTime: 30000

samety22 commented 5 months ago

Hi,

i have the same issue.

In my scenario, I have the same problem. On the client side, I need to call the same REST API seven times in a row (with different parameters) within a function and then merge the results on client side. I have the following configuration:

spring.datasource.hikari.minimumIdle=8
spring.datasource.hikari.maximumPoolSize=12
spring.datasource.hikari.connectionTimeout=20000

If I set minimumIdle to 15 and maximumPoolSize to 20, then it works again. In the background, I am using JdbcTemplate with Spring Boot 3.2.2. What am I doing wrong here? JdbcTemplate should manage the connections and close operations by itself, right? Or am I misunderstanding something?

What i think: The Timeout of 50000ms is still waiting - without doing anything! - The "Hakari Pool Manager" didnt try to get a "reopened" connection from the Pool. And After 50000ms he throw an Exception! -> I test it in my Test-Enviroment - I start 20 Requests on same Time and no any Requests after them. But Hakari are not get the next "reopened" connection.

My error message:

org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection
SQLTransientConnectionException: HikariPool-6 - Connection is not available, request timed out after 50003ms.

My Question: is it a worth practices when i set minimumIdle=8 and set maximumPoolSize=100? because when i get to much requests - the HikariPool can open more connections if he need - and are not limited to 12 Connections? Did the maximumPoolSize=100 cause any performance issues when it is not used?

andreaniccolini commented 4 months ago

@samety22 pay attention using Spring JdbcTemplate, in this particular issue using queryForStream method because you have to close the stream, otherwise Hikari pool cannot release the active connection. Receiving further requests new connections will be created until reached the max pool size value and throwing the exception.

Docs: "the result Stream, containing mapped objects, needing to be closed once fully processed (e.g. through a try-with-resources clause)"

I had a similar issue, in my log i could see connection actives not released after sending response to the client request.

I don't know if this can be your scenario.

edwinquaihoi commented 3 months ago

Any update, I've experienced the same issue using version 5.0.1 against a PostgresSQL DB which results in having to restart the application server.

rigotre7 commented 3 months ago

@edwinquaihoi No update from my side. We are still experiencing random drops in DB pool connections with no network issues. We have to restart our application container to recover. The pool stats even indicate that the pool is empty but no attempt will be made at creating connections:

Screenshot 2024-07-24 at 8 58 17 AM

We've decided to move towards a server-side database pool (PgBouncer). If I find anything before we make that lift I will share it here.

edwinquaihoi commented 3 months ago

@rigotre7 Thanks for your status update. We recently added the socketTimeout setting to our configuration and so far it seems to have worked. Referencing this source article as it gave us some insight on a solution https://www.theguardian.com/info/2019/dec/02/faster-postgresql-connection-recovery

rigotre7 commented 3 months ago

@edwinquaihoi Thank you, that's a great article! I will set this config in our testing environment and see how it behaves.

aeiliev commented 3 months ago

This might help you.