commons-dbcp abandon connection killing

AbandonTest.java

package net.eckenfels.test.dbcp;

import java.io.PrintWriter;
import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.sql.Connection;
import java.sql.PreparedStatement;
import java.sql.SQLException;
import java.util.Locale;
import java.util.TimeZone;

import javax.management.ObjectName;
import javax.sql.DataSource;

import oracle.jdbc.pool.OracleDataSource;

import org.apache.commons.dbcp2.ConnectionFactory;
import org.apache.commons.dbcp2.DataSourceConnectionFactory;
import org.apache.commons.dbcp2.PoolableConnection;
import org.apache.commons.dbcp2.PoolableConnectionFactory;
import org.apache.commons.dbcp2.PoolingDataSource;
import org.apache.commons.dbcp2.SwallowedExceptionLogger;
import org.apache.commons.logging.LogFactory;
import org.apache.commons.logging.impl.SimpleLog;
import org.apache.commons.pool2.impl.AbandonedConfig;
import org.apache.commons.pool2.impl.GenericObjectPool;


public class AbandonTest
{
    public final static int TIMEOUT = 4; // c3 is 10s idle

    @SuppressWarnings("resource")
    public static void main(String[] args) throws SQLException, InterruptedException
    {
        LogFactory.getFactory().setAttribute("org.apache.commons.logging.Log", SimpleLog.class.getName());
        LogFactory.getFactory().setAttribute("org.apache.commons.logging.simplelog.defaultlog", "TRACE");
        // works: LogFactory.getLog(AbandonTest.class).debug("Try debug");

        if (args.length < 2 ||args.length > 3)
        {
            throw new IllegalArgumentException("java " + AbandonTest.class.getName() + "  <user> <pass> [<url>]");
        }

        System.out.printf("Ora Close Test jre=%s loc=%s tz=%s os=%s/%s%n", System.getProperty("java.version"), Locale.getDefault().toString(), TimeZone.getDefault().getID(), System.getProperty("os.name", "N/A"), System.getProperty("os.version"));

        // extract options and arguments
        String url;
        if (args.length > 2)
        {
            url = args[2];
        }
        else
        {
            url = "jdbc:oracle:thin:@eckenfelsb01:1521:eckenfels01";
        }

        OracleDataSource ods = new OracleDataSource();

        ods.setURL(url);
        ods.setUser(args[0]);
        ods.setPassword(args[1]);


        DataSource ds = setupDS(ods);

        System.out.println("1 - get");
        final Connection c1 = ds.getConnection();
        System.out.println("1 - got");
        System.out.println("  Driver=" + c1.getMetaData().getDriverVersion() + " timeout=" + TIMEOUT + "s");
        new Thread() {
            @Override
            public void run()
            {
                System.out.println("1 - create");
                try {
                    PreparedStatement s = c1.prepareStatement("BEGIN DBMS_LOCK.sleep(20); END;");
                    System.out.println("1 - exec");
                    s.execute();
                    System.out.println("1 - close");
                    s.close(); c1.close();
                    System.out.println("1 - done");
                } catch (Exception e) {
                    System.out.println("1 - "); e.printStackTrace();
                }
            }
        }.start();

        Thread.sleep(6*1000);
        System.out.println("thread state after 6s");
        dumpThreads();

        System.out.println("2 - get");
        final Connection c2 = ds.getConnection();
        System.out.println("2 - got");
        new Thread() {
            @Override
            public void run()
            {
                System.out.println("2 - create");
                try {
                    PreparedStatement s = c2.prepareStatement("BEGIN DBMS_LOCK.sleep(20); END;");
                    System.out.println("2 - exec");
                    s.execute();
                    System.out.println("2 - close");
                    s.close(); c2.close();
                    System.out.println("2 - done");
                } catch (Exception e) {
                    System.out.print("2 - "); e.printStackTrace();
                }
            }
        }.start();
        System.out.println("3 - get");
        final Connection c3 = ds.getConnection();
        System.out.println("3 - got");
        Thread.sleep(10 * 1000);
        System.out.println("3 - slept");
        new Thread() {
            @Override
            public void run()
            {
                System.out.println("3 - create");
                try {
                    PreparedStatement s = c3.prepareStatement("BEGIN DBMS_LOCK.sleep(20); END;");
                    System.out.println("3 - exec");
                    s.execute();
                    System.out.println("3 - close");
                    s.close(); c3.close();
                    System.out.println("3 - done");
                } catch (Exception e) {
                    System.out.print("3 - "); e.printStackTrace();
                }
            }
        }.start();

        Thread.sleep(3 * 1000);
        dumpThreads();
    }

    /**
     *
     */
    private static void dumpThreads()
    {
        ThreadInfo[] dump = ManagementFactory.getThreadMXBean().dumpAllThreads(true,  true);
        for(int i=0;i<dump.length;i++)
            System.out.println(dump[i]);
    }

    static DataSource setupDS(DataSource ods)
    {
        SwallowedExceptionLogger log = new SwallowedExceptionLogger(LogFactory.getLog("dbcp"), true);
        PrintWriter printer = new PrintWriter(System.out, true);
        ConnectionFactory cf = new DataSourceConnectionFactory(ods);
        PoolableConnectionFactory pcf = new PoolableConnectionFactory(cf, (ObjectName)null);
        GenericObjectPool<PoolableConnection> pool = new GenericObjectPool<>(pcf);
        pcf.setPool(pool);

        AbandonedConfig acfg = new AbandonedConfig();
        acfg.setLogAbandoned(true);
        acfg.setRemoveAbandonedOnMaintenance(true);
        acfg.setRemoveAbandonedOnBorrow(true);
        acfg.setRemoveAbandonedTimeout(TIMEOUT);
        acfg.setUseUsageTracking(true);
        acfg.setLogWriter(printer);

        pool.setAbandonedConfig(acfg);
        pool.setMaxTotal(2);
        pool.setMinIdle(1);
        pool.setTimeBetweenEvictionRunsMillis(1000);
        pool.setSwallowedExceptionListener(log);
        LogFactory.getLog("setupDS").debug("pool.getLogAbandoned()=" + pool.getLogAbandoned());

        PoolingDataSource<PoolableConnection> pds = new PoolingDataSource<>(pool);
        pds.setLogWriter(printer);
        return pds;
    }

}

pom.xml

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>net.eckenfels.test</groupId>
    <artifactId>dbcp-test</artifactId>
    <version>0.0.1-SNAPSHOT</version>

    <properties>
        <maven.compiler.source>1.7</maven.compiler.source>
        <maven.compiler.target>1.7</maven.compiler.target>
    </properties>

    <dependencies>
        <dependency>
            <groupId>org.apache.commons</groupId>
            <artifactId>commons-pool2</artifactId>
            <version>2.3</version>
        </dependency>
        <dependency>
            <groupId>org.apache.commons</groupId>
            <artifactId>commons-dbcp2</artifactId>
            <version>2.1</version>
        </dependency>
        <dependency>
            <groupId>commons-logging</groupId>
            <artifactId>commons-logging</artifactId>
            <version>1.2</version>
        </dependency>
        <dependency>
            <groupId>com.oracle</groupId>
            <artifactId>ojdbc6</artifactId>
            <version>12.1.0.1.0</version>
            <scope>provided</scope>
        </dependency>
    </dependencies>

</project>

result-12s.txt

Ora Close Test jre=1.8.0_40 loc=de_DE tz=Europe/Berlin os=Windows 7/6.1
1 - get
1 - got
  Driver=12.1.0.1.0 timeout=12s
1 - create
1 - exec

thread state after 6s
"Thread-2" Id=14 RUNNABLE (in native)
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:170)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at oracle.net.ns.Packet.receive(Packet.java:311)
	at oracle.net.ns.DataPacket.receive(DataPacket.java:105)
	at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:305)
	at oracle.net.ns.NetInputStream.read(NetInputStream.java:249)
	...


"commons-pool-EvictionTimer" Id=12 TIMED_WAITING on java.util.TaskQueue@366e2eef
	at java.lang.Object.wait(Native Method)
	-  waiting on java.util.TaskQueue@366e2eef
	at java.util.TimerThread.mainLoop(Timer.java:552)
	at java.util.TimerThread.run(Timer.java:505)


"main" Id=1 RUNNABLE
	at sun.management.ThreadImpl.dumpThreads0(Native Method)
	at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:446)
	at net.eckenfels.test.dbcp.AbandonTest.dumpThreads(AbandonTest.java:152)
	at net.eckenfels.test.dbcp.AbandonTest.main(AbandonTest.java:98)


2 - get
2 - got
3 - get
2 - create
2 - exec
org.apache.commons.pool2.impl.DefaultPooledObject$AbandonedObjectCreatedException: Pooled object created 2015-07-27 22:36:20 +0200 by the following code has not been returned to the pool:
	at org.apache.commons.pool2.impl.DefaultPooledObject.allocate(DefaultPooledObject.java:198)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:452)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
	at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
	at net.eckenfels.test.dbcp.AbandonTest.main(AbandonTest.java:75)
1 - close
1 - done
3 - got
org.apache.commons.pool2.impl.DefaultPooledObject$AbandonedObjectCreatedException: Pooled object created 2015-07-27 22:36:26 +0200 by the following code has not been returned to the pool:
	at org.apache.commons.pool2.impl.DefaultPooledObject.allocate(DefaultPooledObject.java:198)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:452)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
	at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
	at net.eckenfels.test.dbcp.AbandonTest.main(AbandonTest.java:101)
2 - close
2 - done
3 - slept
3 - create
3 - exec

"Thread-4" Id=16 RUNNABLE (in native)
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:170)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at oracle.net.ns.Packet.receive(Packet.java:311)
	at oracle.net.ns.DataPacket.receive(DataPacket.java:105)
	at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:305)
	at oracle.net.ns.NetInputStream.read(NetInputStream.java:249)
	...

"commons-pool-EvictionTimer" Id=12 TIMED_WAITING on java.util.TaskQueue@366e2eef
	at java.lang.Object.wait(Native Method)
	-  waiting on java.util.TaskQueue@366e2eef
	at java.util.TimerThread.mainLoop(Timer.java:552)
	at java.util.TimerThread.run(Timer.java:505)

"main" Id=1 RUNNABLE
	at sun.management.ThreadImpl.dumpThreads0(Native Method)
	at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:446)
	at net.eckenfels.test.dbcp.AbandonTest.dumpThreads(AbandonTest.java:152)
	at net.eckenfels.test.dbcp.AbandonTest.main(AbandonTest.java:144)


org.apache.commons.pool2.impl.DefaultPooledObject$AbandonedObjectCreatedException: Pooled object created 2015-07-27 22:36:40 +0200 by the following code has not been returned to the pool:
	at org.apache.commons.pool2.impl.DefaultPooledObject.allocate(DefaultPooledObject.java:198)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:452)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
	at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
	at net.eckenfels.test.dbcp.AbandonTest.main(AbandonTest.java:121)
3 - close
3 - done

result-4s.txt

Ora Close Test jre=1.8.0_40 loc=de_DE tz=Europe/Berlin os=Windows 7/6.1
1 - get
1 - got
  Driver=12.1.0.1.0 timeout=4s
1 - create
1 - exec
org.apache.commons.pool2.impl.DefaultPooledObject$AbandonedObjectCreatedException: Pooled object created 2015-07-27 22:33:59 +0200 by the following code has not been returned to the pool:
	at org.apache.commons.pool2.impl.DefaultPooledObject.allocate(DefaultPooledObject.java:198)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:452)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
	at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
	at net.eckenfels.test.dbcp.AbandonTest.main(AbandonTest.java:75)

thread state after 6s
"Thread-2" Id=14 RUNNABLE (in native)
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:170)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at oracle.net.ns.Packet.receive(Packet.java:311)
	at oracle.net.ns.DataPacket.receive(DataPacket.java:105)
	at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:305)
	at oracle.net.ns.NetInputStream.read(NetInputStream.java:249)
	...

"commons-pool-EvictionTimer" Id=12 BLOCKED on oracle.jdbc.driver.T4CConnection@3cd1f1c8 owned by "Thread-2" Id=14
	at oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1343)
	-  blocked on oracle.jdbc.driver.T4CConnection@3cd1f1c8
	at oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:100)
	at oracle.jdbc.driver.OraclePreparedStatementWrapper.close(OraclePreparedStatementWrapper.java:82)
	at org.apache.commons.dbcp2.DelegatingStatement.close(DelegatingStatement.java:156)
	at org.apache.commons.dbcp2.DelegatingConnection.passivate(DelegatingConnection.java:631)
	at org.apache.commons.dbcp2.PoolableConnection.passivate(PoolableConnection.java:127)
	at org.apache.commons.dbcp2.DelegatingConnection.closeInternal(DelegatingConnection.java:232)
	at org.apache.commons.dbcp2.PoolableConnection.reallyClose(PoolableConnection.java:243)
	...
"main" Id=1 RUNNABLE
	at sun.management.ThreadImpl.dumpThreads0(Native Method)
	at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:446)
	at net.eckenfels.test.dbcp.AbandonTest.dumpThreads(AbandonTest.java:152)
	at net.eckenfels.test.dbcp.AbandonTest.main(AbandonTest.java:98)


2 - get
2 - got
3 - get
2 - create
2 - exec
1 - close
1 - done
3 - got
org.apache.commons.pool2.impl.DefaultPooledObject$AbandonedObjectCreatedException: Pooled object created 2015-07-27 22:34:05 +0200 by the following code has not been returned to the pool:
	at org.apache.commons.pool2.impl.DefaultPooledObject.allocate(DefaultPooledObject.java:198)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:452)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
	at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
	at net.eckenfels.test.dbcp.AbandonTest.main(AbandonTest.java:101)
2 - close
2 - done
org.apache.commons.pool2.impl.DefaultPooledObject$AbandonedObjectCreatedException: Pooled object created 2015-07-27 22:34:19 +0200 by the following code has not been returned to the pool:
	at org.apache.commons.pool2.impl.DefaultPooledObject.allocate(DefaultPooledObject.java:198)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:452)
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
	at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134)
	at net.eckenfels.test.dbcp.AbandonTest.main(AbandonTest.java:121)
3 - slept
3 - create
3 - java.sql.SQLException: Connection oracle.jdbc.driver.T4CConnection@34edac28 is closed.
	at org.apache.commons.dbcp2.DelegatingConnection.checkOpen(DelegatingConnection.java:605)
	at org.apache.commons.dbcp2.DelegatingConnection.prepareStatement(DelegatingConnection.java:286)
	at org.apache.commons.dbcp2.DelegatingConnection.prepareStatement(DelegatingConnection.java:288)
	at net.eckenfels.test.dbcp.AbandonTest$3.run(AbandonTest.java:131)

"commons-pool-EvictionTimer" Id=12 TIMED_WAITING on java.util.TaskQueue@35fb3008
	at java.lang.Object.wait(Native Method)
	-  waiting on java.util.TaskQueue@35fb3008
	at java.util.TimerThread.mainLoop(Timer.java:552)
	at java.util.TimerThread.run(Timer.java:505)


"main" Id=1 RUNNABLE
	at sun.management.ThreadImpl.dumpThreads0(Native Method)
	at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:446)
	at net.eckenfels.test.dbcp.AbandonTest.dumpThreads(AbandonTest.java:152)
	at net.eckenfels.test.dbcp.AbandonTest.main(AbandonTest.java:144)

Logging requires autoflush till POOL-300 is fixed.