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: | |
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
[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