Could not inspect JDBC autocommit mode
After switching to the DBCP (Database Connection Pool) drivers that comes bundled with Tomcat 5+, we started seeing a weird exception on our web app. If we leave our server idle for a long time (5-6 hrs) or if we put our laptop to sleep and 5-6+ hrs later when we bring up the laptop and try to access any page on our web app, we get the following error on the web page:
(The error was “could not inspect JDBC autocommit mode”)
When we see our logs, we find the following exception:
18:26:34,845 ERROR JDBCExceptionReporter:72 - Connection com.mysql.jdbc.JDBC4Connection@36fbe6ab is closed. SEVERE: could not inspect JDBC autocommit mode org.hibernate.exception.GenericJDBCException: could not inspect JDBC autocommit mode at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103) at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91) at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43) at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29) at org.hibernate.jdbc.JDBCContext.afterNontransactionalQuery(JDBCContext.java:248) at org.hibernate.impl.SessionImpl.afterOperation(SessionImpl.java:417) at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1577) at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:283) ... at javax.servlet.http.HttpServlet.service(HttpServlet.java:617) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.ha.tcp.ReplicationValve.invoke(ReplicationValve.java:347) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:637) Caused by: java.sql.SQLException: Connection com.mysql.jdbc.JDBC4Connection@36fbe6ab is closed. at org.apache.tomcat.dbcp.dbcp.DelegatingConnection.checkOpen(DelegatingConnection.java:354) at org.apache.tomcat.dbcp.dbcp.DelegatingConnection.getAutoCommit(DelegatingConnection.java:304) at org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.getAutoCommit(PoolingDataSource.java:224) at org.hibernate.jdbc.ConnectionManager.isAutoCommit(ConnectionManager.java:185) at org.hibernate.jdbc.JDBCContext.afterNontransactionalQuery(JDBCContext.java:239) ... 29 more
On carefully looking at the exception, we find:
Caused by: java.sql.SQLException: Connection com.mysql.jdbc.JDBC4Connection@36fbe6ab is closed.
From the exception its clear that the reason for this exception is that the db connection is closed. Which is in sync with our finding so far, idle server causes this problem.
What happens is, the Database closes the connections since they are inactive. But DBCP & hence hibernate still thinks those connections are active and tries to execute some command on them. This is when an exception is thrown.
We can easily simulate this exception. When everything is running fine, restart your DB and you’ll see the same exception when you try to access any dynamic page on your site.
On reading DBCP configuration, I found:
| Parameter | Default | Description |
|---|---|---|
| validationQuery |
The SQL query that will be used to validate connections from this pool before returning them to the caller. If specified, this query MUST be an SQL SELECT statement that returns at least one row. |
|
| testOnBorrow | true |
The indication of whether objects will be validated before being borrowed from the pool. If the object fails to validate, it will be dropped from the pool, and we will attempt to borrow another. NOTE - for a true value to have any effect,the validationQuery parameter must be set to a non-nullstring. |
Basically testOnBorrow is true by default, which means DBCP will test if the connection is valid (alive) before returning. But to test it, it needs a query using which it would validate the connection. Since in our case we did not specify any value, when hibernate would ask DBCP for a connection, it would just return a connection without testing if its a valid connection before returning. And then the stale connection throws an exception when we try to perform any operation on it. But if the validation query is specified, then DBCP will drop the connection and give us another valid connection. This avoiding this problem.
So the simple solution to this problem is to add a validationQuery to the connection pooling configuration (in our case it was the context.xml file).
validationQuery="select version();"
Q.E.D
