HikariCP broken connections goes unresponsive

136 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 - allowPoolSuspension.............false
DEBUG com.zaxxer.hikari.HikariConfig - allowPoolSuspension.............false
DEBUG com.zaxxer.hikari.HikariConfig - autoCommit......................false
DEBUG com.zaxxer.hikari.HikariConfig - autoCommit......................false
DEBUG com.zaxxer.hikari.HikariConfig - autoCommit......................false
DEBUG com.zaxxer.hikari.HikariConfig - catalog.........................none
DEBUG com.zaxxer.hikari.HikariConfig - catalog.........................none
DEBUG com.zaxxer.hikari.HikariConfig - catalog.........................none
DEBUG com.zaxxer.hikari.HikariConfig - connectionInitSql...............none
DEBUG com.zaxxer.hikari.HikariConfig - connectionInitSql...............none
DEBUG com.zaxxer.hikari.HikariConfig - connectionInitSql...............none
DEBUG com.zaxxer.hikari.HikariConfig - connectionTestQuery.............none
DEBUG com.zaxxer.hikari.HikariConfig - connectionTestQuery.............none
DEBUG com.zaxxer.hikari.HikariConfig - connectionTestQuery.............none
DEBUG com.zaxxer.hikari.HikariConfig - connectionTimeout...............30000
DEBUG com.zaxxer.hikari.HikariConfig - connectionTimeout...............30000
DEBUG com.zaxxer.hikari.HikariConfig - connectionTimeout...............30000
DEBUG com.zaxxer.hikari.HikariConfig - dataSource......................none
DEBUG com.zaxxer.hikari.HikariConfig - dataSource......................none
DEBUG com.zaxxer.hikari.HikariConfig - dataSource......................none
DEBUG com.zaxxer.hikari.HikariConfig - dataSourceClassName.............none
DEBUG com.zaxxer.hikari.HikariConfig - dataSourceClassName.............none
DEBUG com.zaxxer.hikari.HikariConfig - dataSourceClassName.............none
DEBUG com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................none
DEBUG com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................none
DEBUG com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................none
DEBUG com.zaxxer.hikari.HikariConfig - dataSourceProperties............{password=<masked>}
DEBUG com.zaxxer.hikari.HikariConfig - dataSourceProperties............{password=<masked>}
DEBUG com.zaxxer.hikari.HikariConfig - dataSourceProperties............{password=<masked>}
DEBUG com.zaxxer.hikari.HikariConfig - driverClassName................."com.microsoft.sqlserver.jdbc.SQLServerDriver"
DEBUG com.zaxxer.hikari.HikariConfig - driverClassName................."com.microsoft.sqlserver.jdbc.SQLServerDriver"
DEBUG com.zaxxer.hikari.HikariConfig - driverClassName................."com.microsoft.sqlserver.jdbc.SQLServerDriver"
DEBUG com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
DEBUG com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
DEBUG com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
DEBUG com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............none
DEBUG com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............none
DEBUG com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............none
DEBUG com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000
DEBUG com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000
DEBUG com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000
DEBUG com.zaxxer.hikari.HikariConfig - initializationFailTimeout.......1
DEBUG com.zaxxer.hikari.HikariConfig - initializationFailTimeout.......1
DEBUG com.zaxxer.hikari.HikariConfig - initializationFailTimeout.......1
DEBUG com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false
DEBUG com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false
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 - 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 - 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 - leakDetectionThreshold..........0
DEBUG com.zaxxer.hikari.HikariConfig - leakDetectionThreshold..........0
DEBUG com.zaxxer.hikari.HikariConfig - maxLifetime.....................1800000
DEBUG com.zaxxer.hikari.HikariConfig - maxLifetime.....................1800000
DEBUG com.zaxxer.hikari.HikariConfig - maxLifetime.....................1800000
DEBUG com.zaxxer.hikari.HikariConfig - maximumPoolSize.................10
DEBUG com.zaxxer.hikari.HikariConfig - maximumPoolSize.................10
DEBUG com.zaxxer.hikari.HikariConfig - maximumPoolSize.................10
DEBUG com.zaxxer.hikari.HikariConfig - metricRegistry..................none
DEBUG com.zaxxer.hikari.HikariConfig - metricRegistry..................none
DEBUG com.zaxxer.hikari.HikariConfig - metricRegistry..................none
DEBUG com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........none
DEBUG com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........none
DEBUG com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........none
DEBUG com.zaxxer.hikari.HikariConfig - minimumIdle.....................10
DEBUG com.zaxxer.hikari.HikariConfig - minimumIdle.....................10
DEBUG com.zaxxer.hikari.HikariConfig - minimumIdle.....................10
DEBUG com.zaxxer.hikari.HikariConfig - password........................<masked>
DEBUG com.zaxxer.hikari.HikariConfig - password........................<masked>
DEBUG com.zaxxer.hikari.HikariConfig - password........................<masked>
DEBUG com.zaxxer.hikari.HikariConfig - poolName........................"HikariPool-1"
DEBUG com.zaxxer.hikari.HikariConfig - poolName........................"HikariPool-1"
DEBUG com.zaxxer.hikari.HikariConfig - poolName........................"HikariPool-1"
DEBUG com.zaxxer.hikari.HikariConfig - readOnly........................false
DEBUG com.zaxxer.hikari.HikariConfig - readOnly........................false
DEBUG com.zaxxer.hikari.HikariConfig - readOnly........................false
DEBUG com.zaxxer.hikari.HikariConfig - registerMbeans..................false
DEBUG com.zaxxer.hikari.HikariConfig - registerMbeans..................false
DEBUG com.zaxxer.hikari.HikariConfig - registerMbeans..................false
DEBUG com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none
DEBUG com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none
DEBUG com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none
DEBUG com.zaxxer.hikari.HikariConfig - schema..........................none
DEBUG com.zaxxer.hikari.HikariConfig - schema..........................none
DEBUG com.zaxxer.hikari.HikariConfig - schema..........................none
DEBUG com.zaxxer.hikari.HikariConfig - threadFactory...................internal
DEBUG com.zaxxer.hikari.HikariConfig - threadFactory...................internal
DEBUG com.zaxxer.hikari.HikariConfig - threadFactory...................internal
DEBUG com.zaxxer.hikari.HikariConfig - transactionIsolation............default
DEBUG com.zaxxer.hikari.HikariConfig - transactionIsolation............default
DEBUG com.zaxxer.hikari.HikariConfig - transactionIsolation............default
DEBUG com.zaxxer.hikari.HikariConfig - username........................<masked>
DEBUG com.zaxxer.hikari.HikariConfig - username........................<masked>
DEBUG com.zaxxer.hikari.HikariConfig - username........................<masked>
DEBUG com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
DEBUG com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
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