Hikaricp: Hikari connections when TCP connection dropped

[i-dellbridge]

Environment

HikariCP version: 2.6.1
JDK version: 1.8
Database: PostgreSQL
Driver version: 9.4.1209.jre7

---

We're having some problems with TCP connections being dropped between our application server and our database server. When that happens we see the following in our db logs:

20170620 10:36:57:598 WARN  com.zaxxer.hikari.pool.PoolBase  [http-8080-5] - database.usermanager.read-kappserver5|fab_servlet|test-pgholidaydb1.prod.eu.gcp - Failed to validate connection Pooled connection wrapping physical connection org.postgresql.jdbc.PgConnection@644c8570 (An I/O error occurred while sending to the backend.)
20170620 10:36:57:599 DEBUG com.zaxxer.hikari.pool.PoolBase  [database.usermanager.read-kappserver5|fab_servlet|test-pgholidaydb1.prod.eu.gcp connection closer] - database.usermanager.read-kappserver5|fab_servlet|test-pgholidaydb1.prod.eu.gcp - Closing connection Pooled connection wrapping physical connection org.postgresql.jdbc.PgConnection@644c8570: (connection is evicted or dead)
20170620 10:36:57:599 DEBUG com.zaxxer.hikari.pool.HikariPool  [database.usermanager.read-kappserver5|fab_servlet|test-pgholidaydb1.prod.eu.gcp connection adder] - database.usermanager.read-kappserver5|fab_servlet|test-pgholidaydb1.prod.eu.gcp - Added connection Pooled connection wrapping physical connection org.postgresql.jdbc.PgConnection@cb0a7dd
20170620 10:36:57:647 WARN  com.zaxxer.hikari.pool.ProxyConnection  [http-8080-5] - database.usermanager.read-kappserver5|fab_servlet|test-pgholidaydb1.prod.eu.gcp - Connection Pooled connection wrapping physical connection org.postgresql.jdbc.PgConnection@cb0a7dd marked as broken because of SQLSTATE(08006), ErrorCode(0)
org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:226)
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:424)
    at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:161)
    at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:114)
    at sun.reflect.GeneratedMethodAccessor34.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.postgresql.ds.PGPooledConnection$StatementHandler.invoke(PGPooledConnection.java:426)
    at com.sun.proxy.$Proxy8.executeQuery(Unknown Source)
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
    at  *** application code ***

My understanding of what is happening here is:
1/ We attempt to get a db connection, but the validation fails (probably because the TCP connection has been dropped)

20170620 10:36:57:598 WARN  com.zaxxer.hikari.pool.PoolBase  [http-8080-5] - database.usermanager.read-kappserver5|fab_servlet|test-pgholidaydb1.prod.eu.gcp - Failed to validate connection Pooled connection wrapping physical connection org.postgresql.jdbc.PgConnection@644c8570 (An I/O error occurred while sending to the backend.)

2/ The validation has failed, so Hikari closes that connection

20170620 10:36:57:599 DEBUG com.zaxxer.hikari.pool.PoolBase  [database.usermanager.read-kappserver5|fab_servlet|test-pgholidaydb1.prod.eu.gcp connection closer] - database.usermanager.read-kappserver5|fab_servlet|test-pgholidaydb1.prod.eu.gcp - Closing connection Pooled connection wrapping physical connection org.postgresql.jdbc.PgConnection@644c8570: (connection is evicted or dead)

3/ Hikari has closed the last connection in the pool, so it opens another one

20170620 10:36:57:599 DEBUG com.zaxxer.hikari.pool.HikariPool  [database.usermanager.read-kappserver5|fab_servlet|test-pgholidaydb1.prod.eu.gcp connection adder] - database.usermanager.read-kappserver5|fab_servlet|test-pgholidaydb1.prod.eu.gcp - Added connection Pooled connection wrapping physical connection org.postgresql.jdbc.PgConnection@cb0a7dd

4/ We use that connection in the application, but it doesn't work, probably because of the dropped TCP connection

5/ On releasing the connection, Hikari logs the exceptions thrown while using it

20170620 10:36:57:647 WARN  com.zaxxer.hikari.pool.ProxyConnection  [http-8080-5] - database.usermanager.read-kappserver5|fab_servlet|test-pgholidaydb1.prod.eu.gcp - Connection Pooled connection wrapping physical connection org.postgresql.jdbc.PgConnection@cb0a7dd marked as broken because of SQLSTATE(08006), ErrorCode(0)

If this is correct, and if the TCP connection has been dropped, should it have been possible for Hikari to create that new db connection in step 3?

Given that our TCP connection problems are currently ongoing, is there any way I can configure Hikari to help? I know I can reduce the aliveBypassWindowMs value so that Hikari validates the new connection every time, but obviously that will have a performance hit. Should Hikari have the option to validate new connections after a previous one is closed because of a problem?

I've enabled TCP keepalive between the servers every 30 seconds, perhaps this value needs tweaking. Do you have any other suggestions?

[brettwooldridge]

It seems extremely strange to me that a connection acquisition would succeed at 10:36:57.599 and that SQL query on that same connection would fail 48ms later at 10:36:57.647.

Changing the aliveBypassWindow will not help in this case unless it is set extremely short, which will as you noted affect performance.

You can try setting connectionInitSql to something like "SELECT 1". That will force HikariCP to run that query when a connection is created and before adding it to the pool.

But that is merely a bandaid over some underlying issue. You need to run wireshark or tcpdump to figure out which side is terminating the connection and the start figuring out why that is occurring.

[i-dellbridge]

Thanks for your quick response.

It seems this was ultimately caused by using the org.postgresql.ds.PGPoolingDataSource driver which caused a second layer of pooling meaning Hikari was occasionally obtaining connections from this pool that had already been dropped. This was an ongoing problem with the application that only came to light when trying to connect to databases over the VPN. Replacing this with org.postgresql.ds.PGSimpleDataSource means Hikari can now manage the connection lifetimes properly.

Thanks again for your help.