Broken Connection Remains in Pool

[Philip Vegdahl]

I'm having an occasional problem where a single connection fails, but is not removed from the pool.  From there, that closed connection continues to be used, each time resulting in a failure and forcing us to restart the instance manually.  Perhaps worse, this happens only infrequently (sometimes less than 1 / week), and has been impossible to reproduce but trying to manually kill connections, so it has been very difficult to investigate.  It doesn't bother me that a connection fails.  However, I'm trying to figure out why it is not correctly recognized as a closed connection, removed from the pool, and replaced.  Some relevant information below:

Hibernate: 5.2.10.Final

HikariCP: 2.7.8

PostgreSQL: 9.3

The initial failure is a reset connection:

  logger_name:  com.zaxxer.hikari.proxy.ConnectionProxy

  message:      Connection org.postgresql.jdbc4.Jdbc4Connection@74f5ea12 (HikariPool-0) marked as broken because of SQLSTATE(08006), ErrorCode(0).

  stack_trace:  j.n.SocketException: Connection reset

        at j.n.SocketInputStream.read(SocketInputStream.java:210) ~[na:1.8.0_152]

        at j.n.SocketInputStream.read(SocketInputStream.java:141)

        at o.p.c.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:143) ~[retail-paths-main.jar:2.2.1679]

        at o.p.c.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:112)

        at o.p.c.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:71)

        at o.p.core.PGStream.ReceiveChar(PGStream.java:269)

        at o.p.c.v.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1704)

        at o.p.c.v.QueryExecutorImpl.execute(QueryExecutorImpl.java:255)
        ...

Leading to a transaction exception:

  message:     Unable to rollback against JDBC Connection

  stacktrace:  org.hibernate.TransactionException: Unable to rollback against JDBC Connection

        at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.rollback(AbstractLogicalConnectionImplementor.java:121)

        at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.rollback(JdbcResourceLocalTransactionCoordinatorImpl.java:239)

        at org.hibernate.engine.transaction.internal.TransactionImpl.rollback(TransactionImpl.java:100)

        at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.rollbackIfNecessary(JpaLocalTxnInterceptor.java:153)

        at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke(JpaLocalTxnInterceptor.java:74)
        ...

And then many many subsequent failures that all look like this:

  message:     org.hibernate.exception.GenericJDBCException: could not prepare statement

  stacktrace:  javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: could not prepare statement

        at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:147)

        at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:155)

        at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1423)

        at org.hibernate.query.internal.AbstractProducedQuery.getSingleResult(AbstractProducedQuery.java:1463)
        ...

    Caused by: java.lang.Throwable: Connection is closed

        at com.zaxxer.hikari.pool.ProxyConnection$ClosedConnection.lambda$getClosedConnection$0(ProxyConnection.java:490) ~[ltigradepassback-server.jar:1.0.78]

        at com.sun.proxy.$Proxy103.prepareStatement(null) ~[na:na]

        at com.zaxxer.hikari.pool.ProxyConnection.prepareStatement(ProxyConnection.java:318) ~[ltigradepassback-server.jar:1.0.78]

        at com.zaxxer.hikari.pool.HikariProxyConnection.prepareStatement(HikariProxyConnection.java) ~[ltigradepassback-server.jar:1.0.78]

        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:146) ~[ltigradepassback-server.jar:1.0.78]

        at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172) ~[ltigradepassback-server.jar:1.0.78]

        ... 89 common frames omitted

I thought that this was the sort of case that Hikari was designed to handle.  A connection goes dead.  Detect it, replace it, move on.  I've read the docs and can't find any clear knobs to turn.  Also, remember that this happens very infrequently, but it does always reoccur.  Any help is appreciated.

Thank you!

[Brett Wooldridge]

It would be of some use to see stacktraces that extend down into the HikariCP classes (in the case of the first and second stacktraces above).  Enabling DEBUG logging for com.zaxxer.hikari would also be useful.  HikariCP is not terribly noisy.  Debug logging would allow us to see when/if a connection that is detected as broken is actually evicted.

Generally speaking, HikariCP should be bulletproof with regards to broken connections.  In the case where the broken connection is detected by the com.zaxxer.hikari.proxy.ConnectionProxy there should absolutely be no way that that connection ever comes out of the pool again.

However, there is a possibility that the application (or framework in the stack) acquires a Connection, performs some action (which succeeds at commit()), but hangs onto the Connection rather than releasing it back quickly.  Subsequently, upon attempting to use the Connection, the application may find that it is dead.  In this case, HikariCP never got the connection back, and therefore could not detect that it was broken.  I have definitely seen Hibernate do this in the past -- based on configuration of its acquisition_mode or release_mode.

I suggest reading this issue to see if it helps, especially the last few comments.

-Brett

[Philip Vegdahl]

Thank you for the insights.  I've made some updates to our logging and will post an update when we observe another occurrence (generally less than 1 / week).  I will also look into the hibernate settings mentioned in the linked issue.