HikariCP broken connections goes unresponsive

660 views

Skip to first unread message

Shubham Mangla

unread,

Oct 22, 2020, 10:49:42 AM10/22/20

to HikariCP

Hi, Greetings !!

On an enterprise network, I am working on a springboot app which comes by default with Hikari connection pooling mechanism. The DB connection is established while starting up the application and below is the Hikari Pool configuration:-

DEBUG com.zaxxer.hikari.HikariConfig - HikariPool-1 - configuration:

DEBUG com.zaxxer.hikari.HikariConfig - allowPoolSuspension.............false

DEBUG com.zaxxer.hikari.HikariConfig - autoCommit......................false

DEBUG com.zaxxer.hikari.HikariConfig - catalog.........................none

DEBUG com.zaxxer.hikari.HikariConfig - connectionInitSql...............none

DEBUG com.zaxxer.hikari.HikariConfig - connectionTestQuery.............none

DEBUG com.zaxxer.hikari.HikariConfig - connectionTimeout...............30000

DEBUG com.zaxxer.hikari.HikariConfig - dataSource......................none

DEBUG com.zaxxer.hikari.HikariConfig - dataSourceClassName.............none

DEBUG com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................none

DEBUG com.zaxxer.hikari.HikariConfig - dataSourceProperties............{password=<masked>}

DEBUG com.zaxxer.hikari.HikariConfig - driverClassName................."com.microsoft.sqlserver.jdbc.SQLServerDriver"

DEBUG com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}

DEBUG com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............none

DEBUG com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000

DEBUG com.zaxxer.hikari.HikariConfig - initializationFailTimeout.......1

DEBUG com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false

DEBUG com.zaxxer.hikari.HikariConfig - jdbcUrl.........................jdbc:sqlserver://{db-name}.database.windows.net:1433;database={db-name};encrypt=true;trustServerCertificate=false;hostNameInCertificate=*.database.windows.net;loginTimeout=30;

DEBUG com.zaxxer.hikari.HikariConfig - leakDetectionThreshold..........0

DEBUG com.zaxxer.hikari.HikariConfig - maxLifetime.....................1800000

DEBUG com.zaxxer.hikari.HikariConfig - maximumPoolSize.................10

DEBUG com.zaxxer.hikari.HikariConfig - metricRegistry..................none

DEBUG com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........none

DEBUG com.zaxxer.hikari.HikariConfig - minimumIdle.....................10

DEBUG com.zaxxer.hikari.HikariConfig - password........................<masked>

DEBUG com.zaxxer.hikari.HikariConfig - poolName........................"HikariPool-1"

DEBUG com.zaxxer.hikari.HikariConfig - readOnly........................false

DEBUG com.zaxxer.hikari.HikariConfig - registerMbeans..................false

DEBUG com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none

DEBUG com.zaxxer.hikari.HikariConfig - schema..........................none

DEBUG com.zaxxer.hikari.HikariConfig - threadFactory...................internal

DEBUG com.zaxxer.hikari.HikariConfig - transactionIsolation............default

DEBUG com.zaxxer.hikari.HikariConfig - username........................<masked>

DEBUG com.zaxxer.hikari.HikariConfig - validationTimeout...............5000

I am encountering an issue where a Spring Boot service, after running for about a day with some load, suddenly the application becomes unresponsive as I am assuming the communication link between the driver and the data source to which the driver was attempting to connect failed while the application was performing some operation resulting to following logs and application not performing any other operation.

Sometimes the error is :-

WARN 98332 --- [ scheduling-1] com.zaxxer.hikari.pool.ProxyConnection : HikariPool-1 - Connection ConnectionID:1 ClientConnectionId: 91a118c1-e9c5-4bda-beae-bb8fba1ca9bf marked as broken because of SQLSTATE(08S01), ErrorCode(0)

com.microsoft.sqlserver.jdbc.SQLServerException: Operation timed out (Read failed) Caused by: java.net.SocketException: Operation timed out (Read failed) at java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.8.0_265] at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[na:1.8.0_265] at java.net.SocketInputStream.read(SocketInputStream.java:171) ~[na:1.8.0_265] at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[na:1.8.0_265] at com.microsoft.sqlserver.jdbc.TDSChannel$ProxyInputStream.readInternal(IOBuffer.java:1015) ~[mssql-jdbc-8.4.0.jre8.jar:na]

2020-10-22 16:45:12.078 || [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection ConnectionID:5 ClientConnectionId: 71d096bc-e3b5-49a6-85c0-b72e9af0b4b4: (connection is broken)
2020-10-22 16:45:12.078 || [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection ConnectionID:5 ClientConnectionId: 71d096bc-e3b5-49a6-85c0-b72e9af0b4b4: (connection is broken)

And sometime when the network is weak, the application has been intermittently seen going unresponsive and only Hikari housekeeper logs can be shown as below and nothing else.

Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Broken pipe (Write failed)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:3145)
at com.microsoft.sqlserver.jdbc.TDSChannel.write(IOBuffer.java:2076)
at com.microsoft.sqlserver.jdbc.TDSWriter.flush(IOBuffer.java:4307)
at com.microsoft.sqlserver.jdbc.TDSWriter.writePacket(IOBuffer.java:4209)
at com.microsoft.sqlserver.jdbc.TDSWriter.endMessage(IOBuffer.java:3247)
at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(IOBuffer.java:7737)
at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(SQLServerPreparedStatement.java:600)
at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(SQLServerPreparedStatement.java:524)
at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:7375)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:3200)
at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:247)
at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:222)
at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeQuery(SQLServerPreparedStatement.java:446)
at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:57)
... 40 common frames omitted
Caused by: java.net.SocketException: Broken pipe (Write failed)
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111)
at java.net.SocketOutputStream.write(SocketOutputStream.java:155)
at com.microsoft.sqlserver.jdbc.TDSChannel$ProxyOutputStream.writeInternal(IOBuffer.java:1111)
at com.microsoft.sqlserver.jdbc.TDSChannel$ProxyOutputStream.write(IOBuffer.java:1104)
at sun.security.ssl.OutputRecord.writeBuffer(OutputRecord.java:431)
at sun.security.ssl.OutputRecord.write(OutputRecord.java:417)
at sun.security.ssl.SSLSocketImpl.writeRecordInternal(SSLSocketImpl.java:894)
at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:865)
at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:123)
at com.microsoft.sqlserver.jdbc.TDSChannel.write(IOBuffer.java:2071)
... 54 common frames omitted
2020-10-22 20:00:06.265 || [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection ConnectionID:57 ClientConnectionId: b1d03bb3-f780-477f-97ae-653f43544265
2020-10-22 20:00:06.265 || [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection ConnectionID:57 ClientConnectionId: b1d03bb3-f780-477f-97ae-653f43544265
2020-10-22 20:00:06.266 || [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=10, active=0, idle=10, waiting=0)
2020-10-22 20:00:06.266 || [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=10, active=0, idle=10, waiting=0)
2020-10-22 20:00:20.682 || [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2020-10-22 20:00:20.682 || [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2020-10-22 20:00:50.687 || [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2020-10-22 20:00:50.687 || [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)

Even after new connections getting added, we could just see active=0. How can we make our Hikari connections close gracefully and replace it by another w/out loosing any data. I would appreciate any help on this. Thanks!!

Reply all

Reply to author

Forward

0 new messages