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).
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).