Bug #57757 Race condition in simple.StatementsTest.testCancelStatement causes failure
Submitted: 27 Oct 2010 0:58 Modified: 12 Nov 2010 19:16
Reporter: Elena Stepanova Email Updates:
Status: Closed Impact on me:
None 
Category:Connector / J Severity:S3 (Non-critical)
Version:5.1.13 OS:Any
Assigned to: Erica Moss

[27 Oct 2010 0:58] Elena Stepanova
Description:
Test StatementsTest.testCancelStatement tends to fail on the following assertion:

N/A
junit.framework.AssertionFailedError
at testsuite.simple.StatementsTest.testCancelStatement(StatementsTest.java:785)

It happens fairly often in my test environment and in release testing environment, but is not 100% reproducible.

Lines 771-787 of simple.StatementsTest (testCancelStatement method):

Connection forceCancel = getConnectionWithProps("queryTimeoutKillsConnection=true");
Statement forceStmt = forceCancel.createStatement();
forceStmt.setQueryTimeout(1);
				
try {
   forceStmt.execute("SELECT SLEEP(30)");
   fail("Statement should have been cancelled");
} catch (MySQLTimeoutException timeout) {
   // expected
}
try {
   forceCancel.setAutoCommit(true); // should fail too
} catch (SQLException sqlEx) {
   assertTrue(sqlEx.getCause() instanceof MySQLStatementCancelledException);
}

setAutoCommit(true) is expected to fail because queryTimeoutKillsConnection=true and the previous statement is timed out. 

However, from all I see there is no guarantee that the connection will be already closed by the time execute(..) throws an exception -- and there is no check in the test that the connection has been closed by the time setAutoCommit(..) is called. 

As a result, sometimes instead of the instance of MySQLStatementCancelledException we are getting instance of IOException. 

Below are two stack traces -- what we receive versus what we expect to receive (I disabled the try/catch block, but the line numbers should be intact):

In case of failure:

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 1 004 milliseconds ago. The last packet sent successfully to the server was 1 003 milliseconds ago.
at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:409)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1118)
at com.mysql.jdbc.MysqlIO.clearInputStream(MysqlIO.java:952)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1895)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2562)
at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:4956)
at testsuite.simple.StatementsTest.testCancelStatement(StatementsTest.java:783)
Caused by: java.io.IOException: Stream closed.
at java.net.AbstractPlainSocketImpl.available(AbstractPlainSocketImpl.java:418)
at java.net.SocketInputStream.available(SocketInputStream.java:234)
at com.mysql.jdbc.util.ReadAheadInputStream.available(ReadAheadInputStream.java:232)
at com.mysql.jdbc.MysqlIO.clearInputStream(MysqlIO.java:945)

In case of success:

com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed.Connection was implicitly closed by the driver.
at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:409)
at com.mysql.jdbc.Util.getInstance(Util.java:384)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1015)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:989)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:984)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:929)
at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1193)
at com.mysql.jdbc.ConnectionImpl.getMutex(ConnectionImpl.java:3035)
at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:4909)
at testsuite.simple.StatementsTest.testCancelStatement(StatementsTest.java:783)
Caused by: com.mysql.jdbc.exceptions.MySQLStatementCancelledException: Connection closed to due to statement timeout being reached and "queryTimeoutKillsConnection" being set to "true".
at com.mysql.jdbc.StatementImpl$CancelTask$1.run(StatementImpl.java:93)

My guess that it's a race condition is indirectly confirmed by the fact that if I add a sleep before setAutoCommit(..) call, the failure never happens.

How to repeat:
Inspect the test simple.StatementsTest.testCancelStatement code.

For me the failure was nearly deterministic when I ran the entire StatementsTest testcase on 5.5.7, and was quite easily reproducible on 5.1.51 as well.
I was able to reduce the test case significantly, still getting the failure; but I did not observe it when I ran testCancelStatement test in isolation.

However, on other systems and in different environment the ratio can be different.

Suggested fix:
The simplest way is to insert a sleep before setAutoCommit(..) call, although I would suggest adding a loop with forceCancel.isClosed() condition (with a timeout so as not to stay there forever if something goes wrong).
[27 Oct 2010 1:22] Mark Matthews
Proposed fix tested and is now pushed to the 5.1 branch. The change should show up in the nightly snapshots for Oct 28th.
[27 Oct 2010 21:18] Erica Moss
I verified it in my environment and that was the cause.  I'll verify the fix tomorrow when it is available.
[12 Nov 2010 19:16] Erica Moss
Tested latest c/j branch (5.1.14) against server 5.5.7  Patch works fine.