Bug #12357 autoReconnect ineffective during failure in Statement.executeQuery
Submitted: 3 Aug 2005 20:11 Modified: 3 Aug 2005 21:42
Reporter: Peter Andrews Email Updates:
Status: Not a Bug Impact on me:
None 
Category:Connector / J Severity:S2 (Serious)
Version:3.1.10 OS:Windows (Windows/Linux)
Assigned to: CPU Architecture:Any

[3 Aug 2005 20:11] Peter Andrews
Description:
I have been getting a Communications Link failure despite using autoReconnect. It is totally reproducible on my system. Here is the stack trace:

Communications link failure due to underlying exception:

** BEGIN NESTED EXCEPTION **

java.io.EOFException

STACKTRACE:

java.io.EOFException
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1902)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2348)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2858)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1570)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2972)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2902)
        at com.mysql.jdbc.Statement.executeQuery(Statement.java:822)
        at org.apache.commons.dbcp.DelegatingStatement.executeQuery(DelegatingStatement.java:205)
        at com.airs.utilities.server.Entity.find(Entity.java:1241)

I debugged it and here is the code path:
com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1902) finds count of error packet = 0 and throws EOFException

which is caught by:
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2560) which throws a CommunicationException

which is caught by:
com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2860)
which rethrows the exception

which is caught by Connection.execSQL: 2982
Connection.execSQL checks for getHighAvailability (autoreconnect) and set this.needsPing = true on line 2998 and then rethrows the excepion on line 3009

Which is NOT caught but exits Statement.executeQuery at line 831

How to repeat:
I use Tomcat 5.0.28. In my server.xml my jdbc is defined with my jdbc connection properties like this:

<parameter><name>connectionProperties</name><value>autoReconnect=true;sessionVariables=wait_timeout=20;</value></parameter>

I set my db timeout to 20 seconds so I could easily reproduce the problem.

Suggested fix:
don't know.
[3 Aug 2005 20:24] Peter Andrews
My connectionProperties was NOT correct. I also had elideSetAutoCommits=true; and useLocalSessionState=true; (By the way I had to turn on useLocalSessionSate=true or else I still saw lots of 'SET autocommit= 1').

I think turning off the autoCommits is crucial to reproduce: with autocommits going the SET autocommit=1 causes the connection error during the connection creation and there executeQuery is extremely unlikely to run into connection problems. AutoReconnect works properly in that scenario.
[3 Aug 2005 20:25] Mark Matthews
I'm confused. Do you expect Statement.executeQuery() to "replay" the query? It doesn't, or are you saying that needsPing isn't getting set correctly? 

You're always going to get an exception on the operation that failed, the JDBC driver doesn't attempt to do anything fancy to replay a query, since that is a naiive implementation that doesn't take into account everything that has happened before that have taken locks, set variables, created temporary tables, etc., which would cause the results from a replay type recovery to not be consistent.
[3 Aug 2005 20:30] Peter Andrews
Forgot to mention versions:

MySql 4.1.12 64 bit under Linux
commons-dbcp-1.2.1
commons-pool-1.2
mysql-connector-java-3.1.10
[3 Aug 2005 20:44] Peter Andrews
Mark,

Thanks for the quick reply.

Yes I did it expect it to execute the query. It is not really replaying it if the detected failure is a connection problem -- the expectation is that the initial submission of the query failed to get through to MySQL.

I understand that this probably is naive in the sense that I cannot know whether the command actually got through or not.

Is there a way I can get it to send a ping before the execute command and then doing a reconnect if necessary? I am assuming that a ping  lighter weight than sending a validationQuery via the connection pool.

Thanks,

Peter
[3 Aug 2005 21:42] Mark Matthews
Nope. There is no current way to ping before every query. The old MM.MySQL driver used to do this, and it's a performance drain. Sure, a ping operation is lighterweight (by a very little bit), but for many people you're talking about doubling the response time of _each_ query, since many queries were an order of ms. to execute (mostly in network time), and the same thing with a "ping" command being sent out.

There is no magic bullet for this. If a connection goes down in the middle of a transaction (or if not using transactions, a "business operation"), your application needs to figure out what to do.  In some cases, that might be display an error to the user. In other cases it might be "back up, and try again". It's very application dependent, and is not something a database client library can handle for you.

Short of having an entire transaction log on the client, along with a full-fledged SQL parser, recovery from communications errors can't be done transpartently, and even with those things in place you'd still have indeterminate conditions (i.e. what happens if the backend commits, and the network goes down immediately after that and before the message gets back to the client?).
[3 Aug 2005 22:00] Peter Andrews
Once again, thanks you Mark for the thorough and rapid reply.

I understand al of your points. In truth I suspect that we have a serious intermittent network problem. Until we can diagnose and fix that however, I have little choice but to incur the overhead of a ping. I modified if on line 2952 of Connection.java to always return true so that an internal ping occurs before every command. I re-ran my test case, verified the pings were occurring in the debugger and with Ethereal and as expected it solves my problem.

Once the network issue is resolved, I will remove the fix.

May I suggest that you add a parameter to do the ping? As long as the docs clearly explain the cost, there are times such as my current situation when it is useful. Without this, people are instead using the dbcp testOnBorrow=true parameter which incurs even greater cost. Not only is a ping lighter weight, but by executing closer to the query there is less time for a context switch to occur and therefore less chance the network connection could 'go bad' between the test and the query.

Thanks for your help,

Peter Andrews
[2 Jan 2006 21:10] [ name withheld ]
This problem happens with Tomcat 5.5.9, mysql J/Connector 3.1.10 using Velocity 2.1 when an application stay without use for a few hours.

The Resource in server.xml that I'm using is:

	<Resource 
		name="jdbc/dsProjectManager"
		auth="Container"
		type="javax.sql.DataSource"
		maxActive="100" 
		maxIdle="30" 
		maxWait="10000"
		username="projectmanager" 
		password="projectmanager" 
		driverClassName="com.mysql.jdbc.Driver" 
		url="jdbc:mysql://localhost/projectmanager?autoReconnect=true"
		/>

The test case is:

- I start my application.
- At the next day someone try to login to the application.
- At login time the application try to make a "select".

I get this exception:

** I LL SEND IT IN A NEXT MESSAGE **

I mean, in this case THERE IS NOT a network problem. I suspect that this error could be provocated because something close an unused sql connection and "forget" to reopen again.

If you need more data I'll glad to help you.

Regards

Pablo
[2 Jan 2006 21:11] [ name withheld ]
This is the exception of the previous message: 

com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception:

** BEGIN NESTED EXCEPTION **

java.io.EOFException

STACKTRACE:

java.io.EOFException
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1902)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2348)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2858)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1570)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2972)
        at com.mysql.jdbc.Connection.setAutoCommit(Connection.java:4870)
        at org.apache.tomcat.dbcp.dbcp.DelegatingConnection.setAutoCommit(DelegatingConnection.java:268)
        at org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.setAutoCommit(PoolingDataSource.java:293)
        at net.sf.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:44)
        at net.sf.hibernate.transaction.JDBCTransactionFactory.beginTransaction(JDBCTransactionFactory.java:19)
        at net.sf.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:2252)
        at com.siainteractive.projectmanager.pmvc.seguridad.GestorSeguridadSia.getUsuario(GestorSeguridadSia.java:385)
        at com.siainteractive.projectmanager.pmvc.seguridad.GestorSeguridadSia.login(GestorSeguridadSia.java:242)
        at com.siainteractive.projectmanager.pmvc.LoginServlet.handleRequest(LoginServlet.java:64)
        at org.apache.velocity.servlet.VelocityServlet.doRequest(VelocityServlet.java:358)
        at org.apache.velocity.servlet.VelocityServlet.doPost(VelocityServlet.java:327)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:307)
        at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:385)
        at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:748)
        at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:678)
        at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:871)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)

** END NESTED EXCEPTION **
[2 Jan 2006 21:12] [ name withheld ]
This is the second part of the exception:

Last packet sent to the server was 0 ms ago.
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2560)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2858)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1570)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2972)
        at com.mysql.jdbc.Connection.setAutoCommit(Connection.java:4870)
        at org.apache.tomcat.dbcp.dbcp.DelegatingConnection.setAutoCommit(DelegatingConnection.java:268)
        at org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.setAutoCommit(PoolingDataSource.java:293)
        at net.sf.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:44)
        at net.sf.hibernate.transaction.JDBCTransactionFactory.beginTransaction(JDBCTransactionFactory.java:19)
        at net.sf.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:2252)
        at com.siainteractive.projectmanager.pmvc.seguridad.GestorSeguridadSia.getUsuario(GestorSeguridadSia.java:385)
        at com.siainteractive.projectmanager.pmvc.seguridad.GestorSeguridadSia.login(GestorSeguridadSia.java:242)
        at com.siainteractive.projectmanager.pmvc.LoginServlet.handleRequest(LoginServlet.java:64)
        at org.apache.velocity.servlet.VelocityServlet.doRequest(VelocityServlet.java:358)
        at org.apache.velocity.servlet.VelocityServlet.doPost(VelocityServlet.java:327)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:307)
        at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:385)
        at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:748)
        at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:678)
        at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:871)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)
2006-01-02 17:34:51,954 ERROR com.siainteractive.projectmanager.pmvc.seguridad.GestorSeguridadSia - Error al login
net.sf.hibernate.TransactionException: Begin failed with SQL exception:
        at net.sf.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:49)
        at net.sf.hibernate.transaction.JDBCTransactionFactory.beginTransaction(JDBCTransactionFactory.java:19)
        at net.sf.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:2252)
        at com.siainteractive.projectmanager.pmvc.seguridad.GestorSeguridadSia.getUsuario(GestorSeguridadSia.java:385)
        at com.siainteractive.projectmanager.pmvc.seguridad.GestorSeguridadSia.login(GestorSeguridadSia.java:242)
        at com.siainteractive.projectmanager.pmvc.LoginServlet.handleRequest(LoginServlet.java:64)
        at org.apache.velocity.servlet.VelocityServlet.doRequest(VelocityServlet.java:358)
        at org.apache.velocity.servlet.VelocityServlet.doPost(VelocityServlet.java:327)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:307)
        at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:385)
        at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:748)
        at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:678)
        at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:871)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)
Caused by: com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception:

** BEGIN NESTED EXCEPTION **
[2 Jan 2006 21:12] [ name withheld ]
this is the third part of the exception:

java.io.EOFException

STACKTRACE:

java.io.EOFException
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1902)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2348)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2858)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1570)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2972)
        at com.mysql.jdbc.Connection.setAutoCommit(Connection.java:4870)
        at org.apache.tomcat.dbcp.dbcp.DelegatingConnection.setAutoCommit(DelegatingConnection.java:268)
        at org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.setAutoCommit(PoolingDataSource.java:293)
        at net.sf.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:44)
        at net.sf.hibernate.transaction.JDBCTransactionFactory.beginTransaction(JDBCTransactionFactory.java:19)
        at net.sf.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:2252)
        at com.siainteractive.projectmanager.pmvc.seguridad.GestorSeguridadSia.getUsuario(GestorSeguridadSia.java:385)
        at com.siainteractive.projectmanager.pmvc.seguridad.GestorSeguridadSia.login(GestorSeguridadSia.java:242)
        at com.siainteractive.projectmanager.pmvc.LoginServlet.handleRequest(LoginServlet.java:64)
        at org.apache.velocity.servlet.VelocityServlet.doRequest(VelocityServlet.java:358)
        at org.apache.velocity.servlet.VelocityServlet.doPost(VelocityServlet.java:327)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:307)
        at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:385)
        at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:748)
        at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:678)
        at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:871)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)

** END NESTED EXCEPTION **

Last packet sent to the server was 0 ms ago.
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2560)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2858)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1570)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1665)
        at com.mysql.jdbc.Connection.execSQL(Connection.java:2972)
        at com.mysql.jdbc.Connection.setAutoCommit(Connection.java:4870)
        at org.apache.tomcat.dbcp.dbcp.DelegatingConnection.setAutoCommit(DelegatingConnection.java:268)
        at org.apache.tomcat.dbcp.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.setAutoCommit(PoolingDataSource.java:293)
        at net.sf.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:44)
        ... 24 more
[2 Jan 2006 21:14] [ name withheld ]
Well. That's all! :-)

I think that it is probably a bug. 

Regards 

Pablo
[11 May 2009 10:55] S KR
This might be a bug. I would rather say autoReconnect doesnt work out.

I got the same exception & resolved the issue after 3 hectic days.Check if you are using I hibernate3. In this version it is req to explicitly mention the connection class name. Also check if the jar is in classpath. Check steps & comments in below link 

http://hibernatedb.blogspot.com/2009/05/automatic-reconnect-from-hibernate-to.html

Remove autoReconnec=true