Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 1.3
    • Fix Version/s: 1.5.1, 2.0
    • Labels:
      None

      Description

      Under high load commons-dbcp (or commons-pool) exhibits thread safety issues and begins throwing various exceptions. I don't yet know the cause of the issue but it looks like a connection maybe handed out to multiple threads concurrently. Here's a few examples of the exceptions we are getting:

      jvm 1    | Caused by: java.sql.SQLException: Attempted to use PooledConnection after closed() was called.
      jvm 1    |      at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.assertOpen(PooledConnectionImpl.java:163)
      jvm 1    |      at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:174)
      jvm 1    |      at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768)
      jvm 1    |      at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676)
      jvm 1    |      at uk.co.webessence.kernel.database.DriverAdapterConnectionPool.acquireConnection(DriverAdapterConnectionPool.java:101)
      jvm 1    |      ... 94 more
      
      jvm 1    | Caused by: java.sql.SQLException: PooledConnection was reused, withoutits previous Connection being closed.
      jvm 1    |      at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:179)
      jvm 1    |      at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768)
      jvm 1    |      at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676)
      jvm 1    |      at uk.co.webessence.kernel.database.DriverAdapterConnectionPool.acquireConnection(DriverAdapterConnectionPool.java:101)
      jvm 1    |      ... 77 more
      
      jvm 1    | Caused by: java.sql.SQLException: Invalid state, the ResultSet object is closed.
      jvm 1    |      at net.sourceforge.jtds.jdbc.JtdsResultSet.checkOpen(JtdsResultSet.java:299)
      jvm 1    |      at net.sourceforge.jtds.jdbc.JtdsResultSet.getColumn(JtdsResultSet.java:273)
      jvm 1    |      at net.sourceforge.jtds.jdbc.JtdsResultSet.getObject(JtdsResultSet.java:840)
      jvm 1    |      at org.apache.commons.dbcp.DelegatingResultSet.getObject(DelegatingResultSet.java:325)
      jvm 1    |      at uk.co.webessence.kernel.persistence.Preloader.getDataArray(Preloader.java:428)
      jvm 1    |      at uk.co.webessence.kernel.persistence.Preloader.processSingleRow(Preloader.java:175)
      jvm 1    |      at uk.co.webessence.kernel.persistence.PersistenceHandler.processRecordReload(PersistenceHandler.java:471)
      jvm 1    |      at uk.co.webessence.kernel.persistence.PersistenceHandler$1.doLoad(PersistenceHandler.java:447)
      jvm 1    |      ... 71 more
      
      Message:   TDS Protocol error: Invalid packet type 0x4
      jvm 1    | Caused by: java.sql.SQLException: TDS Protocol error: Invalid packet type 0x4
      jvm 1    |      at net.sourceforge.jtds.jdbc.TdsCore.nextToken(TdsCore.java:2314)
      jvm 1    |      at net.sourceforge.jtds.jdbc.TdsCore.getNextRow(TdsCore.java:764)
      jvm 1    |      at net.sourceforge.jtds.jdbc.JtdsResultSet.next(JtdsResultSet.java:593)
      jvm 1    |      at org.apache.commons.dbcp.DelegatingResultSet.next(DelegatingResultSet.java:207)
      jvm 1    |      at uk.co.webessence.kernel.persistence.Preloader.loadData(Preloader.java:142)
      jvm 1    |      at uk.co.webessence.kernel.persistence.PersistenceHandler$3.doLoad(PersistenceHandler.java:592)
      jvm 1    |      ... 111 more
      jvm 1    | Caused by: net.sourceforge.jtds.jdbc.ProtocolException: Invalid packet type 0x4
      jvm 1    |      at net.sourceforge.jtds.jdbc.TdsCore.nextToken(TdsCore.java:2301)
      jvm 1    |      ... 116 more
      
      1. dbcp_bug.tar.gz
        3 kB
        Dave Oxley
      2. DBCP-376.diff
        3 kB
        Dave Oxley

        Activity

        Hide
        Dave Oxley added a comment -

        A sample application that recreates the issue. I've found that after a few runs it stop reproducing the issue on Linux. Clearing the file cache makes reproduce the issue again:

        sudo sync && echo 3 | sudo tee /proc/sys/vm/drop_caches
        

        Here is an example of output from running the application:

        Loading JDBC driver:
        JDBC driver loaded succesfully
        java.sql.SQLException: Attempted to use PooledConnection after closed() was called.
        	at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.assertOpen(PooledConnectionImpl.java:163)
        	at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:174)
        	at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768)
        	at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676)
        	at com.daveoxley.dbcpbug.App$TestThread.run(App.java:140)
        	at java.lang.Thread.run(Thread.java:662)
        
        java.sql.SQLException: Attempted to use PooledConnection after closed() was called.
        	at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.assertOpen(PooledConnectionImpl.java:163)
        	at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:174)
        	at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768)
        	at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676)
        	at com.daveoxley.dbcpbug.App$TestThread.run(App.java:140)
        	at java.lang.Thread.run(Thread.java:662)
        
        Show
        Dave Oxley added a comment - A sample application that recreates the issue. I've found that after a few runs it stop reproducing the issue on Linux. Clearing the file cache makes reproduce the issue again: sudo sync && echo 3 | sudo tee /proc/sys/vm/drop_caches Here is an example of output from running the application: Loading JDBC driver: JDBC driver loaded succesfully java.sql.SQLException: Attempted to use PooledConnection after closed() was called. at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.assertOpen(PooledConnectionImpl.java:163) at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:174) at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768) at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676) at com.daveoxley.dbcpbug.App$TestThread.run(App.java:140) at java.lang.Thread.run(Thread.java:662) java.sql.SQLException: Attempted to use PooledConnection after closed() was called. at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.assertOpen(PooledConnectionImpl.java:163) at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:174) at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768) at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676) at com.daveoxley.dbcpbug.App$TestThread.run(App.java:140) at java.lang.Thread.run(Thread.java:662)
        Hide
        Dave Oxley added a comment -

        I've just recreated the same issue with snapshots of dbcp2 and pool2. Here is the output:

        Loading JDBC driver:
        JDBC driver loaded succesfully
        INFO  - checkpointClose start
        INFO  - checkpointClose end
        CLOSING DOWN CONNECTION AS IT COULD NOT BE RETURNED TO THE POOL
        java.sql.SQLException: PooledConnection was reused, withoutits previous Connection being closed.
        	at org.apache.commons.dbcp2.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:184)
        	at org.apache.commons.dbcp2.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:778)
        	at org.apache.commons.dbcp2.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:685)
        	at com.daveoxley.dbcpbug.App$TestThread.run(App.java:143)
        	at java.lang.Thread.run(Thread.java:662)
        
        CLOSING DOWN CONNECTION AS IT COULD NOT BE RETURNED TO THE POOL
        CLOSING DOWN CONNECTION AS IT COULD NOT BE RETURNED TO THE POOL
        java.sql.SQLException: Attempted to use PooledConnection after closed() was called.
        	at org.apache.commons.dbcp2.cpdsadapter.PooledConnectionImpl.assertOpen(PooledConnectionImpl.java:167)
        	at org.apache.commons.dbcp2.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:179)
        	at org.apache.commons.dbcp2.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:778)
        	at org.apache.commons.dbcp2.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:685)
        	at com.daveoxley.dbcpbug.App$TestThread.run(App.java:143)
        	at java.lang.Thread.run(Thread.java:662)
        
        Show
        Dave Oxley added a comment - I've just recreated the same issue with snapshots of dbcp2 and pool2. Here is the output: Loading JDBC driver: JDBC driver loaded succesfully INFO - checkpointClose start INFO - checkpointClose end CLOSING DOWN CONNECTION AS IT COULD NOT BE RETURNED TO THE POOL java.sql.SQLException: PooledConnection was reused, withoutits previous Connection being closed. at org.apache.commons.dbcp2.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:184) at org.apache.commons.dbcp2.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:778) at org.apache.commons.dbcp2.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:685) at com.daveoxley.dbcpbug.App$TestThread.run(App.java:143) at java.lang.Thread.run(Thread.java:662) CLOSING DOWN CONNECTION AS IT COULD NOT BE RETURNED TO THE POOL CLOSING DOWN CONNECTION AS IT COULD NOT BE RETURNED TO THE POOL java.sql.SQLException: Attempted to use PooledConnection after closed() was called. at org.apache.commons.dbcp2.cpdsadapter.PooledConnectionImpl.assertOpen(PooledConnectionImpl.java:167) at org.apache.commons.dbcp2.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:179) at org.apache.commons.dbcp2.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:778) at org.apache.commons.dbcp2.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:685) at com.daveoxley.dbcpbug.App$TestThread.run(App.java:143) at java.lang.Thread.run(Thread.java:662)
        Hide
        Mark Thomas added a comment -

        That the pooling implementation has been completely re-written between 1.x and 2.x yet the problem continues points to a problem in DBCP or the app.

        I'll try and take a look at this when I get some cycles but that might not be for a while. On the plus side, having the test case you provided should make investigating this a lot easier.

        Show
        Mark Thomas added a comment - That the pooling implementation has been completely re-written between 1.x and 2.x yet the problem continues points to a problem in DBCP or the app. I'll try and take a look at this when I get some cycles but that might not be for a while. On the plus side, having the test case you provided should make investigating this a lot easier.
        Hide
        William R. Speirs added a comment -

        For what it's worth, all of the creating of the table and selects calls don't impact the issue. I've stripped down the run method in the thread to the following and still get similar errors (SELECT_LOOPS = 5000):

                public void run() {
                    Connection c = null;
                    try {
                        for (int j=0; j < SELECT_LOOPS; j++) {
                            c = ds.getConnection();
        
                            c.close();
                        }
                    } catch (SQLException sqle) {
                        handleException(sqle);
                    }
                }
        
        Loading JDBC driver:
        JDBC driver loaded succesfully
        Exception in thread "Thread-161" java.lang.IllegalStateException: close() was called on a Connection, but I have no record of the underlying PooledConnection.
        	at org.apache.commons.dbcp.datasources.KeyedCPDSConnectionFactory.connectionClosed(KeyedCPDSConnectionFactory.java:249)
        	at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.notifyListeners(PooledConnectionImpl.java:229)
        	at org.apache.commons.dbcp.cpdsadapter.ConnectionImpl.close(ConnectionImpl.java:78)
        	at com.daveoxley.dbcpbug.App$TestThread.run(App.java:96)
        	at java.lang.Thread.run(Thread.java:662)
        
        Exception in thread "Thread-143" java.lang.IllegalStateException: close() was called on a Connection, but I have no record of the underlying PooledConnection.
        	at org.apache.commons.dbcp.datasources.KeyedCPDSConnectionFactory.connectionClosed(KeyedCPDSConnectionFactory.java:249)
        	at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.notifyListeners(PooledConnectionImpl.java:229)
        	at org.apache.commons.dbcp.cpdsadapter.ConnectionImpl.close(ConnectionImpl.java:78)
        	at com.daveoxley.dbcpbug.App$TestThread.run(App.java:96)
        	at java.lang.Thread.run(Thread.java:662)
        
        java.sql.SQLException: PooledConnection was reused, withoutits previous Connection being closed.
        	at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:179)
        	at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768)
        	at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676)
        	at com.daveoxley.dbcpbug.App$TestThread.run(App.java:94)
        	at java.lang.Thread.run(Thread.java:662)
        
        java.sql.SQLException: PooledConnection was reused, withoutits previous Connection being closed.
        	at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:179)
        	at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768)
        	at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676)
        	at com.daveoxley.dbcpbug.App$TestThread.run(App.java:94)
        	at java.lang.Thread.run(Thread.java:662)
        
        java.sql.SQLException: Attempted to use PooledConnection after closed() was called.
        	at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.assertOpen(PooledConnectionImpl.java:163)
        	at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:174)
        	at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768)
        	at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676)
        	at com.daveoxley.dbcpbug.App$TestThread.run(App.java:94)
        	at java.lang.Thread.run(Thread.java:662)
        
        java.sql.SQLException: PooledConnection was reused, withoutits previous Connection being closed.
        	at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:179)
        	at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768)
        	at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676)
        	at com.daveoxley.dbcpbug.App$TestThread.run(App.java:94)
        	at java.lang.Thread.run(Thread.java:662)
        
        Show
        William R. Speirs added a comment - For what it's worth, all of the creating of the table and selects calls don't impact the issue. I've stripped down the run method in the thread to the following and still get similar errors (SELECT_LOOPS = 5000): public void run() { Connection c = null ; try { for ( int j=0; j < SELECT_LOOPS; j++) { c = ds.getConnection(); c.close(); } } catch (SQLException sqle) { handleException(sqle); } } Loading JDBC driver: JDBC driver loaded succesfully Exception in thread "Thread-161" java.lang.IllegalStateException: close() was called on a Connection, but I have no record of the underlying PooledConnection. at org.apache.commons.dbcp.datasources.KeyedCPDSConnectionFactory.connectionClosed(KeyedCPDSConnectionFactory.java:249) at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.notifyListeners(PooledConnectionImpl.java:229) at org.apache.commons.dbcp.cpdsadapter.ConnectionImpl.close(ConnectionImpl.java:78) at com.daveoxley.dbcpbug.App$TestThread.run(App.java:96) at java.lang.Thread.run(Thread.java:662) Exception in thread "Thread-143" java.lang.IllegalStateException: close() was called on a Connection, but I have no record of the underlying PooledConnection. at org.apache.commons.dbcp.datasources.KeyedCPDSConnectionFactory.connectionClosed(KeyedCPDSConnectionFactory.java:249) at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.notifyListeners(PooledConnectionImpl.java:229) at org.apache.commons.dbcp.cpdsadapter.ConnectionImpl.close(ConnectionImpl.java:78) at com.daveoxley.dbcpbug.App$TestThread.run(App.java:96) at java.lang.Thread.run(Thread.java:662) java.sql.SQLException: PooledConnection was reused, withoutits previous Connection being closed. at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:179) at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768) at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676) at com.daveoxley.dbcpbug.App$TestThread.run(App.java:94) at java.lang.Thread.run(Thread.java:662) java.sql.SQLException: PooledConnection was reused, withoutits previous Connection being closed. at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:179) at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768) at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676) at com.daveoxley.dbcpbug.App$TestThread.run(App.java:94) at java.lang.Thread.run(Thread.java:662) java.sql.SQLException: Attempted to use PooledConnection after closed() was called. at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.assertOpen(PooledConnectionImpl.java:163) at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:174) at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768) at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676) at com.daveoxley.dbcpbug.App$TestThread.run(App.java:94) at java.lang.Thread.run(Thread.java:662) java.sql.SQLException: PooledConnection was reused, withoutits previous Connection being closed. at org.apache.commons.dbcp.cpdsadapter.PooledConnectionImpl.getConnection(PooledConnectionImpl.java:179) at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:768) at org.apache.commons.dbcp.datasources.InstanceKeyDataSource.getConnection(InstanceKeyDataSource.java:676) at com.daveoxley.dbcpbug.App$TestThread.run(App.java:94) at java.lang.Thread.run(Thread.java:662)
        Hide
        Dave Oxley added a comment -

        Attached patch fixes this issue by synchronising validatingMap and pcMap in KeyedCPDSConnectionFactory and CPDSConnectionFactory.

        Show
        Dave Oxley added a comment - Attached patch fixes this issue by synchronising validatingMap and pcMap in KeyedCPDSConnectionFactory and CPDSConnectionFactory.
        Hide
        Mark Thomas added a comment -

        Thanks for the report and test case. Sorry it has taken so long to fix this.

        A variation of the fix has been applied to trunk for 2.0 and to the 1.5.x branch. Assuming that the next 1.3.x and 1.4.x releases are auto generated from the 1.5.x branch they should pick up the fix too.

        I have also added a unit test, again based on your sample code.

        Show
        Mark Thomas added a comment - Thanks for the report and test case. Sorry it has taken so long to fix this. A variation of the fix has been applied to trunk for 2.0 and to the 1.5.x branch. Assuming that the next 1.3.x and 1.4.x releases are auto generated from the 1.5.x branch they should pick up the fix too. I have also added a unit test, again based on your sample code.

          People

          • Assignee:
            Unassigned
            Reporter:
            Dave Oxley
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development