poolMaximumCheckoutTime logic has problem when leaked a connection.

[ryozi-tn]

MyBatis version

3.4.1

Database vendor and version

MySQL 5.6

Test case or example project

Conditional is ...

• TransactionManager is JDBC
• dataSource is POOLED
• PoolPingEnabled is true
• autoCommit is true (It was active connection.)
• Active connection was disconnected from database (Not from client.)
  • eg. Leaked connection...

Please try this testcase. (If using the MySQL to set wait_timeout is 10 (sec))

  @Test
  public void test() throws SQLException, ClassNotFoundException, InterruptedException{
    PooledDataSource ds = new PooledDataSource();
    ds.setDriver("com.mysql.jdbc.Driver");
    ds.setUrl("jdbc:mysql://localhost:3306/testdb");
    ds.setUsername("test");
    ds.setPassword("test");
    ds.setPoolMaximumActiveConnections(1); // test
    ds.setPoolMaximumIdleConnections(1);
    ds.setDefaultTransactionIsolationLevel(2);

    ds.setPoolMaximumCheckoutTime(10000);

    ds.setPoolPingEnabled(true);
    ds.setPoolPingQuery("select 1");

    ds.setPoolPingConnectionsNotUsedFor(10000);  //  MySQL wait_timeout * 1000 or less. (unit:ms)

    JdbcTransaction t1 = new JdbcTransaction(ds, null, true); // autoCommit = true
    Connection con1 = t1.getConnection();
    exexuteTestQuery(con1);
    // con1.close(); // Leaked connection.

    Thread.sleep(TimeUnit.SECONDS.toMillis(10)); // wait for disconnected from mysql...

    JdbcTransaction t2 = new JdbcTransaction(ds, null, true);
    Connection con2 = t2.getConnection(); // fail. (if t2 autocommit is false.)
    exexuteTestQuery(con2); // fail. (if t2 autocommit is true.)
  }

  private void exexuteTestQuery(Connection con) throws SQLException{
    PreparedStatement st = con.prepareStatement("select 1");
    ResultSet rs = st.executeQuery();
    while(rs.next()){
      assertEquals(1, rs.getInt(1));
    }
    rs.close();
    st.close();
  }

Expected result

successful completion

Actual result

Exception and stacktrace.

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

The last packet successfully received from the server was 10,010 milliseconds ago.  The last packet sent successfully to the server was 9 milliseconds ago.
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:408)
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
    at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1116)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3102)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163)
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2624)
    at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2127)
    at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2293)
    at org.apache.ibatis.jdbc.PooledDataSourceTest.query(PooledDataSourceTest.java:131)
    at org.apache.ibatis.jdbc.PooledDataSourceTest.test(PooledDataSourceTest.java:126)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:483)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
    at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)
    at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:459)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:675)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:382)
    at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:192)
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
    at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2552)
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002)
    ... 32 more

Appendix: I found the three solutions

1. Always disabled autoCommit
   • If auto-commit is disabled, connection will be validated by the rollback of the transaction before the reuse connection.
2. Set PoolPingConnectionsNotUsedFor is 0
   • Always check connection. but require solve mysql invalid connection #713 fix.
3. Apply this patch. (best?)

diff --git a/src/main/java/org/apache/ibatis/datasource/pooled/PooledDataSource.java b/src/main/java/org/apache/ibatis/datasource/pooled/PooledDataSource.java
index c87a23a..775004a 100644
--- a/src/main/java/org/apache/ibatis/datasource/pooled/PooledDataSource.java
+++ b/src/main/java/org/apache/ibatis/datasource/pooled/PooledDataSource.java
@@ -401,9 +401,10 @@ public class PooledDataSource implements DataSource {
                   oldestActiveConnection.getRealConnection().rollback();
                 } catch (SQLException e) {
                   log.debug("Bad connection. Could not roll back");
-                }  
+                }
               }
               conn = new PooledConnection(oldestActiveConnection.getRealConnection(), this);
+              conn.setLastUsedTimestamp(0); // Requiring connection validation if set poolPingConnectionsNotUsedFor.
               oldestActiveConnection.invalidate();
               if (log.isDebugEnabled()) {
                 log.debug("Claimed overdue connection " + conn.getRealHashCode() + ".");

[harawata]

Thank you for the detailed report!

There was a similar code in pushConnection() method, so I have fixed this in the same manner.