HikariCP icon indicating copy to clipboard operation
HikariCP copied to clipboard

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

Open igv-git opened this issue 6 months ago • 9 comments

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([email protected]/Native Method)
    at sun.nio.ch.SocketDispatcher.read([email protected]/SocketDispatcher.java:39)
    at sun.nio.ch.IOUtil.readIntoNativeBuffer([email protected]/IOUtil.java:276)
    at sun.nio.ch.IOUtil.read([email protected]/IOUtil.java:245)
    at sun.nio.ch.IOUtil.read([email protected]/IOUtil.java:223)
    at sun.nio.ch.SocketChannelImpl.read([email protected]/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?

igv-git avatar Jan 04 '24 18:01 igv-git

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)
  1. 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([email protected]/Native Method)
        at sun.nio.ch.NioSocketImpl.park([email protected]/NioSocketImpl.java:191)
        at sun.nio.ch.NioSocketImpl.park([email protected]/NioSocketImpl.java:201)
        at sun.nio.ch.NioSocketImpl.implRead([email protected]/NioSocketImpl.java:309)
        at sun.nio.ch.NioSocketImpl.read([email protected]/NioSocketImpl.java:346)
        at sun.nio.ch.NioSocketImpl$1.read([email protected]/NioSocketImpl.java:796)
        at java.net.Socket$SocketInputStream.read([email protected]/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.

MrPowerGamerBR avatar Jan 21 '24 05:01 MrPowerGamerBR

@igv-git:

  1. Share your pool config
  2. Try to reproduce the issue with the newest HikariCP release and a recent oracle jdbc driver

patric-r avatar Jan 22 '24 15:01 patric-r

@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.

  1. 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.

igv-git avatar Jan 23 '24 15:01 igv-git

  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?

patric-r avatar Jan 23 '24 17:01 patric-r

  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
  1. Linux (RHEL, version 7.9)

igv-git avatar Jan 24 '24 09:01 igv-git

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

rajaasthana avatar Feb 29 '24 09:02 rajaasthana

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.

MrPowerGamerBR avatar Feb 29 '24 17:02 MrPowerGamerBR

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

  • start as usual
  • physically disconnect database via network
  • see idle connections decrease
  • see in logs PoolEntryCreator trying to fill pool
  • restart database machine without network to clean any tcp context
  • once restarted reattach db network


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

KazzmanK avatar Mar 08 '24 14:03 KazzmanK

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)

roee-gavriel avatar May 17 '24 01:05 roee-gavriel