Guice JPA - "This connection has been closed." error

Question

After DB dropps an idle connection or DB is down and back up I'm receiving the following error in my webapp:

javax.persistence.PersistenceException: org.hibernate.exception.JDBCConnectionException: could not inspect JDBC autocommit mode
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1365)
    at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1293)
    at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:265)    
... 60 more
Caused by: org.hibernate.exception.JDBCConnectionException: could not inspect JDBC autocommit mode
    at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:131)
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110)
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.isAutoCommit(LogicalConnectionImpl.java:395)
    at org.hibernate.engine.transaction.internal.TransactionCoordinatorImpl.afterNonTransactionalQuery(TransactionCoordinatorImpl.java:195)
    at org.hibernate.internal.SessionImpl.afterOperation(SessionImpl.java:565)
    at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1220)
    at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101)
    at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:256)
... 70 more
Caused by: org.postgresql.util.PSQLException: This connection has been closed.
    at org.postgresql.jdbc2.AbstractJdbc2Connection.checkClosed(AbstractJdbc2Connection.java:712)
    at org.postgresql.jdbc2.AbstractJdbc2Connection.getAutoCommit(AbstractJdbc2Connection.java:678)
    at sun.reflect.GeneratedMethodAccessor138.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:601)
    at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
    at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:99)
    at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:63)
    at $Proxy66.getAutoCommit(Unknown Source)
    at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.isAutoCommit(LogicalConnectionImpl.java:392)

When this starts I get an

SQL Error: 0, SQLState: 08006 - An I/O error occured while sending to the backend.

but after that it's only:

SQL Error: 0, SQLState: 08003 - This connection has been closed.

The problem is: I have set testOnBorrow, so I'd expect to get only open connections.

If that helps: the pool ususaly contains a mix of good and bad connections, and the problem seems to clear up over time, but I had the server running for >12h and there were still bad connections returned. After a restart evertything is working fine (for a time).

I have debugged the problem some more and it seems like pool is returning bad connections, e.g. if after I have all connections killed on DB I get:

SQL Error: 0, SQLState: 57P01

and then the usual stuff - the killed connections are returned from the pool. The question is: is it an application problem?

I tried purging the pool via JMX but that doesn't seem to have any effect. Another weird thing is that even though app is apparently not doing anything (checked via thread dump) the JMX bean is showing 7 active connections and 0 idle connections. When I execute a request requiring DB access I get a response immediately (depite there being no idle connections available), but JMX shows 7 active and 0 idle connections after that.

PS. Maybe I'm missing something obvious and this is a connection management issue on my part? I'm using JPA EntityManager configured via persistence.xml, so maybe I'm doing something wrong and the connections are not closed(returned) properly after use?

Answer 1

Actually I was right when I suspected an application error.

It's all nicely decribed in Issue 730: Automatically started UnitOfWork is never ended

When using the JpaPersistService, if you attempt to access an EntityManager outside of an active UnitOfWork, Guice will automatically start one for you. However, as Guice does not (and cannot) know when to end this UnitOfWork, it never does.

Result? The offending thread will be stuck with the same EntityManager throughout the life of the application. This is a bad state for the application to run in, and ours inevitably exhaust the available memory after a while and crash.

The real killer here is that it's not at all obvious when you've made this mistake. The only real tip-off is that you're getting inconsistent data from your database between different threads (due to the EMs first-level cache) or that the applications memory consumption keeps on growing. In my case it was the active connection in the pool that got me to suspect it, and then, when I turned on detailed logging I noticed that app was not borrowing the connection from pool at all, instead it was reusing the connection already held by unclosed EntityManager.

Actually there are quite some duplicates of this issue reported: http://code.google.com/p/google-guice/issues/list?can=1&q=UnitOfWork