Java Database Connectivity (JDBC)

We've been using the old OracleDataSource for connection pooling, but since that usage is deprecated, I'm trying to switch over to Universal Connection Pooling.

As far as I can tell I am setting everything up just as it outlines in the UCP documentation. And it mostly works. The problem is the abandoned connection timeout. This worked fine with OracleDataSource, but now it doesn't - I have a unit test which abandons a requested connection (by sleeping) and then tries to use it. It can be used just fine.

My first thought was that the timeout wasn't being checked properly for some reason, but I turned on FINEST level tracing for UCP and it sure looks as if the pool is handling it properly - except that my test code still has a handle to it and can use it.

Here's a simple test case that shows the problem:

import java.sql.Connection;
import java.sql.Statement;
import java.sql.ResultSet;

import oracle.ucp.jdbc.PoolDataSourceFactory;
import oracle.ucp.jdbc.PoolDataSource;


public class ConnectionTest
{
    ConnectionTest() {
        /* empty */
    }

    public static void main(String args[])
    {
        try {
            String jdbcURL = args[0];
            if (jdbcURL == null) {
                throw new IllegalArgumentException("jdbcURL is null");
            }

            int atPos = jdbcURL.indexOf('@');
            String credentials = jdbcURL.substring((jdbcURL.lastIndexOf(':', atPos) + 1), atPos);
            String userName = credentials.substring(0, credentials.indexOf('/'));
            String password = credentials.substring((credentials.indexOf('/') + 1));

            PoolDataSource dataSource = PoolDataSourceFactory.getPoolDataSource();
            dataSource.setConnectionFactoryClassName("oracle.jdbc.pool.OracleDataSource");

            dataSource.setURL(jdbcURL);
            dataSource.setUser(userName);
            dataSource.setPassword(password);

            dataSource.setTimeoutCheckInterval(2);
            dataSource.setAbandonedConnectionTimeout(2);

            Connection conn = dataSource.getConnection();
            Thread.sleep(4100);
            Statement st = conn.createStatement();
            ResultSet rs = st.executeQuery("select count(*) from user_objects");
            rs.next();
            int result = rs.getInt(1);
            rs.close();

            System.out.println("Connection still usable after timeout: " + result);
            System.exit(1);

        } catch (Exception e) {
            System.out.println("Exception: " + e.getMessage());
            System.exit(0);
        }
    }
}

Here's the relevant section of the log. Note that the createStatement() call clearly comes after the timeout bits:

2012-11-28T02:47:11.665-0500 UCP FINEST seq-108,thread-11 oracle.ucp.common.UniversalConnectionPoolBase.processAbandonedConnections processing abandoned connections
2012-11-28T02:47:11.666-0500 UCP FINEST seq-109,thread-11 oracle.ucp.common.UniversalConnectionPoolBase.processAbandonedConnections abandoned connections processed
2012-11-28T02:47:11.666-0500 UCP FINEST seq-110,thread-14 oracle.ucp.common.UniversalConnectionPoolImpl$UniversalConnectionPoolInternal.getInUseConnectionsArrayInternal in use connections: 1
2012-11-28T02:47:11.667-0500 UCP FINEST seq-111,thread-14 oracle.ucp.jdbc.oracle.OracleJDBCConnectionPool.processTimedOutConnection UniversalPooledConnection: Instance Name: orcl, DBUniq Name: orcl, Host Name: e-oracle-02, Service Name: orcl.bbn.com
2012-11-28T02:47:11.667-0500 UCP FINEST seq-112,thread-14 oracle.ucp.jdbc.JDBCUniversalPooledConnection.getSQLConnection physicalConnection: oracle.jdbc.driver.T4CConnection@546c585a
2012-11-28T02:47:11.667-0500 UCP FINEST seq-113,thread-14 oracle.ucp.jdbc.oracle.FailoverablePooledConnectionHelper.cancelOnOracleConnection conn cancelled successfully
2012-11-28T02:47:11.667-0500 UCP FINEST seq-114,thread-14 oracle.ucp.common.UniversalPooledConnectionImpl.removeConnectionHarvestingCallback connection harvesting callback removed
2012-11-28T02:47:11.668-0500 UCP FINEST seq-115,thread-14 oracle.ucp.common.AvailableConnectionsManyCollections.createAvailableConnectionsCollection available connections collection created
2012-11-28T02:47:11.668-0500 UCP FINEST seq-116,thread-14 oracle.ucp.common.AvailableConnectionsManyCollections.addAvailableConnection available connection added
2012-11-28T02:47:11.668-0500 UCP FINEST seq-117,thread-14 oracle.ucp.common.UniversalPooledConnectionImpl.setAvailableStartTime availableStartTime: 1354132031668
2012-11-28T02:47:12.107-0500 UCP FINEST seq-118,thread-10 oracle.ucp.jdbc.proxy.StatementProxyFactory.setStatementPooling statementObj=oracle.jdbc.driver.OracleStatementWrapper@2f87c55c, poolable=false
2012-11-28T02:47:12.117-0500 UCP FINEST seq-119,thread-10 oracle.ucp.jdbc.proxy.StatementProxyFactory.createStatementProxy returns $Proxy1@f593af
2012-11-28T02:47:12.243-0500 UCP FINEST seq-120,thread-10 oracle.ucp.jdbc.proxy.ResultSetProxyFactory.createResultSetProxy returns $Proxy2@558352d8

So - what am I doing wrong?

Edited by: Dan Blum on Nov 28, 2012 3:00 PM