You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@commons.apache.org by "Daniel Dudzika (Jira)" <ji...@apache.org> on 2019/11/27 11:10:00 UTC
[jira] [Updated] (IO-647) Race condition in the GenericObjectPool
in removeAbandoned functionality
[ https://issues.apache.org/jira/browse/IO-647?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Daniel Dudzika updated IO-647:
------------------------------
Description:
Hello,
today I found out a potential issue around GenericObjectPool and removing "abandoned" objects functionality.
During the accident one of our customers faced with database outage.
After this our product become unreachable. This state was caused by two threads.
1st "survived" the outage and still possessing the connection it operates on the database,
2nd one was forced to remove "abandoned" objects.
This situation cause that 2nd thread was waiting for 1st one until this 1st thread end his database operation.
More context can be found in the stack traces attached below.
{code:java}
"1st thread" #434 daemon prio=5 os_prio=0 tid=0x00007f9e7746f000 nid=0x9680 runnable [0x00007f9d29c70000]"1st thread" #434 daemon prio=5 os_prio=0 tid=0x00007f9e7746f000 nid=0x9680 runnable [0x00007f9d29c70000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.FileDispatcherImpl.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) at sun.nio.ch.IOUtil.read(IOUtil.java:197) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380) - locked <0x00007fa23958bc48> (a java.lang.Object) at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:144) at oracle.net.ns.NIOHeader.readHeaderBuffer(NIOHeader.java:82) at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:139) at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:101) at
oracle.net.ns.NIONSDataChannel.readDataFromSocketChannel(NIONSDataChannel.java:80) at oracle.jdbc.driver.T4CMAREngineNIO.prepareForReading(T4CMAREngineNIO.java:102) at oracle.jdbc.driver.T4CMAREngineNIO.getNBytes(T4CMAREngineNIO.java:679) at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalNBytes(T4CMAREngineNIO.java:651) at oracle.jdbc.driver.DynamicByteArray.unmarshalBuffer(DynamicByteArray.java:334) at oracle.jdbc.driver.DynamicByteArray.unmarshalCLR(DynamicByteArray.java:226) at oracle.jdbc.driver.T4CNumberAccessor.unmarshalBytes(T4CNumberAccessor.java:191) at oracle.jdbc.driver.T4CNumberAccessor.unmarshalOneRow(T4CNumberAccessor.java:173) at oracle.jdbc.driver.T4CTTIrxd.unmarshal(T4CTTIrxd.java:1526) at oracle.jdbc.driver.T4CTTIrxd.unmarshal(T4CTTIrxd.java:1289) at oracle.jdbc.driver.T4C8Oall.readRXD(T4C8Oall.java:850) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:543) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612) at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:226) at oracle.jdbc.driver.T4CPreparedStatement.fetch(T4CPreparedStatement.java:1023) at oracle.jdbc.driver.OracleStatement.fetchMoreRows(OracleStatement.java:3353) at oracle.jdbc.driver.InsensitiveScrollableResultSet.fetchMoreRows(InsensitiveScrollableResultSet.java:736) at oracle.jdbc.driver.InsensitiveScrollableResultSet.absoluteInternal(InsensitiveScrollableResultSet.java:692) at oracle.jdbc.driver.InsensitiveScrollableResultSet.next(InsensitiveScrollableResultSet.java:406) - locked <0x00007fa23958e580> (a oracle.jdbc.driver.T4CConnection) at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191) at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
{code}
{code:java}
"2nd thread" #376448 daemon prio=5 os_prio=0 tid=0x00007f9e581db000 nid=0x1239 waiting for monitor entry [0x00007f9a75ff2000]"2nd thread" #376448 daemon prio=5 os_prio=0 tid=0x00007f9e581db000 nid=0x1239 waiting for monitor entry [0x00007f9a75ff2000] java.lang.Thread.State: BLOCKED (on object monitor) at oracle.jdbc.driver.InsensitiveScrollableResultSet.close(InsensitiveScrollableResultSet.java:190) - waiting to lock <0x00007fa23958e580> (a oracle.jdbc.driver.T4CConnection) at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) at org.apache.commons.dbcp2.DelegatingStatement.close(DelegatingStatement.java:150) 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) at org.apache.commons.dbcp2.PoolableConnectionFactory.destroyObject(PoolableConnectionFactory.java:334) at org.apache.commons.pool2.impl.GenericObjectPool.destroy(GenericObjectPool.java:890) at org.apache.commons.pool2.impl.GenericObjectPool.invalidateObject(GenericObjectPool.java:649) - locked <0x00007fa2651f85f8> (a org.apache.commons.pool2.impl.DefaultPooledObject) at org.apache.commons.pool2.impl.GenericObjectPool.removeAbandoned(GenericObjectPool.java:1022) at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:418) at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363) at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134) at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1533)
{code}
Cheers,
Daniel Dudziak
Atlassian Developer
was:
Hello,
today I found out a potential issue around GenericObjectPool and removing "abandoned" objects functionality.
During the accident one of our customers faced with database outage.
After this our product become unreachable. This state was caused by two threads.
1st "survived" the outage and still possessing the connection it operates on the database,
2nd one was forced to remove "abandoned" objects.
This situation cause that 2nd thread was waiting for 1st one until this 1st thread end his database operation.
More context can be found in the stack traces attached below.
{code:java}
"1st thread" #434 daemon prio=5 os_prio=0 tid=0x00007f9e7746f000 nid=0x9680 runnable [0x00007f9d29c70000]"1st thread" #434 daemon prio=5 os_prio=0 tid=0x00007f9e7746f000 nid=0x9680 runnable [0x00007f9d29c70000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.FileDispatcherImpl.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) at sun.nio.ch.IOUtil.read(IOUtil.java:197) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380) - locked <0x00007fa23958bc48> (a java.lang.Object) at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:144) at oracle.net.ns.NIOHeader.readHeaderBuffer(NIOHeader.java:82) at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:139) at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:101) at oracle.net.ns.NIONSDataChannel.readDataFromSocketChannel(NIONSDataChannel.java:80) at oracle.jdbc.driver.T4CMAREngineNIO.prepareForReading(T4CMAREngineNIO.java:102) at oracle.jdbc.driver.T4CMAREngineNIO.getNBytes(T4CMAREngineNIO.java:679) at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalNBytes(T4CMAREngineNIO.java:651) at oracle.jdbc.driver.DynamicByteArray.unmarshalBuffer(DynamicByteArray.java:334) at oracle.jdbc.driver.DynamicByteArray.unmarshalCLR(DynamicByteArray.java:226) at oracle.jdbc.driver.T4CNumberAccessor.unmarshalBytes(T4CNumberAccessor.java:191) at oracle.jdbc.driver.T4CNumberAccessor.unmarshalOneRow(T4CNumberAccessor.java:173) at oracle.jdbc.driver.T4CTTIrxd.unmarshal(T4CTTIrxd.java:1526) at oracle.jdbc.driver.T4CTTIrxd.unmarshal(T4CTTIrxd.java:1289) at oracle.jdbc.driver.T4C8Oall.readRXD(T4C8Oall.java:850) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:543) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612) at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:226) at oracle.jdbc.driver.T4CPreparedStatement.fetch(T4CPreparedStatement.java:1023) at oracle.jdbc.driver.OracleStatement.fetchMoreRows(OracleStatement.java:3353) at oracle.jdbc.driver.InsensitiveScrollableResultSet.fetchMoreRows(InsensitiveScrollableResultSet.java:736) at oracle.jdbc.driver.InsensitiveScrollableResultSet.absoluteInternal(InsensitiveScrollableResultSet.java:692) at oracle.jdbc.driver.InsensitiveScrollableResultSet.next(InsensitiveScrollableResultSet.java:406) - locked <0x00007fa23958e580> (a oracle.jdbc.driver.T4CConnection) at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191) at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
{code}
{code:java}
"2nd thread" #376448 daemon prio=5 os_prio=0 tid=0x00007f9e581db000 nid=0x1239 waiting for monitor entry [0x00007f9a75ff2000]"2nd thread" #376448 daemon prio=5 os_prio=0 tid=0x00007f9e581db000 nid=0x1239 waiting for monitor entry [0x00007f9a75ff2000] java.lang.Thread.State: BLOCKED (on object monitor) at oracle.jdbc.driver.InsensitiveScrollableResultSet.close(InsensitiveScrollableResultSet.java:190) - waiting to lock <0x00007fa23958e580> (a oracle.jdbc.driver.T4CConnection) at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) at org.apache.commons.dbcp2.DelegatingStatement.close(DelegatingStatement.java:150) 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) at org.apache.commons.dbcp2.PoolableConnectionFactory.destroyObject(PoolableConnectionFactory.java:334) at org.apache.commons.pool2.impl.GenericObjectPool.destroy(GenericObjectPool.java:890) at org.apache.commons.pool2.impl.GenericObjectPool.invalidateObject(GenericObjectPool.java:649) - locked <0x00007fa2651f85f8> (a org.apache.commons.pool2.impl.DefaultPooledObject) at org.apache.commons.pool2.impl.GenericObjectPool.removeAbandoned(GenericObjectPool.java:1022) at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:418) at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363) at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134) at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1533)
{code}
Cheers,
Daniel Dudziak
Atlassian Developer
> Race condition in the GenericObjectPool in removeAbandoned functionality
> ------------------------------------------------------------------------
>
> Key: IO-647
> URL: https://issues.apache.org/jira/browse/IO-647
> Project: Commons IO
> Issue Type: Bug
> Affects Versions: 2.1
> Reporter: Daniel Dudzika
> Priority: Minor
>
> Hello,
> today I found out a potential issue around GenericObjectPool and removing "abandoned" objects functionality.
> During the accident one of our customers faced with database outage.
> After this our product become unreachable. This state was caused by two threads.
> 1st "survived" the outage and still possessing the connection it operates on the database,
> 2nd one was forced to remove "abandoned" objects.
> This situation cause that 2nd thread was waiting for 1st one until this 1st thread end his database operation.
> More context can be found in the stack traces attached below.
> {code:java}
> "1st thread" #434 daemon prio=5 os_prio=0 tid=0x00007f9e7746f000 nid=0x9680 runnable [0x00007f9d29c70000]"1st thread" #434 daemon prio=5 os_prio=0 tid=0x00007f9e7746f000 nid=0x9680 runnable [0x00007f9d29c70000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.FileDispatcherImpl.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) at sun.nio.ch.IOUtil.read(IOUtil.java:197) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380) - locked <0x00007fa23958bc48> (a java.lang.Object) at oracle.net.nt.TimeoutSocketChannel.read(TimeoutSocketChannel.java:144) at oracle.net.ns.NIOHeader.readHeaderBuffer(NIOHeader.java:82) at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:139) at oracle.net.ns.NIOPacket.readFromSocketChannel(NIOPacket.java:101) at
> oracle.net.ns.NIONSDataChannel.readDataFromSocketChannel(NIONSDataChannel.java:80) at oracle.jdbc.driver.T4CMAREngineNIO.prepareForReading(T4CMAREngineNIO.java:102) at oracle.jdbc.driver.T4CMAREngineNIO.getNBytes(T4CMAREngineNIO.java:679) at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalNBytes(T4CMAREngineNIO.java:651) at oracle.jdbc.driver.DynamicByteArray.unmarshalBuffer(DynamicByteArray.java:334) at oracle.jdbc.driver.DynamicByteArray.unmarshalCLR(DynamicByteArray.java:226) at oracle.jdbc.driver.T4CNumberAccessor.unmarshalBytes(T4CNumberAccessor.java:191) at oracle.jdbc.driver.T4CNumberAccessor.unmarshalOneRow(T4CNumberAccessor.java:173) at oracle.jdbc.driver.T4CTTIrxd.unmarshal(T4CTTIrxd.java:1526) at oracle.jdbc.driver.T4CTTIrxd.unmarshal(T4CTTIrxd.java:1289) at oracle.jdbc.driver.T4C8Oall.readRXD(T4C8Oall.java:850) at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:543) at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252) at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612) at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:226) at oracle.jdbc.driver.T4CPreparedStatement.fetch(T4CPreparedStatement.java:1023) at oracle.jdbc.driver.OracleStatement.fetchMoreRows(OracleStatement.java:3353) at oracle.jdbc.driver.InsensitiveScrollableResultSet.fetchMoreRows(InsensitiveScrollableResultSet.java:736) at oracle.jdbc.driver.InsensitiveScrollableResultSet.absoluteInternal(InsensitiveScrollableResultSet.java:692) at oracle.jdbc.driver.InsensitiveScrollableResultSet.next(InsensitiveScrollableResultSet.java:406) - locked <0x00007fa23958e580> (a oracle.jdbc.driver.T4CConnection) at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191) at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> {code}
> {code:java}
> "2nd thread" #376448 daemon prio=5 os_prio=0 tid=0x00007f9e581db000 nid=0x1239 waiting for monitor entry [0x00007f9a75ff2000]"2nd thread" #376448 daemon prio=5 os_prio=0 tid=0x00007f9e581db000 nid=0x1239 waiting for monitor entry [0x00007f9a75ff2000] java.lang.Thread.State: BLOCKED (on object monitor) at oracle.jdbc.driver.InsensitiveScrollableResultSet.close(InsensitiveScrollableResultSet.java:190) - waiting to lock <0x00007fa23958e580> (a oracle.jdbc.driver.T4CConnection) at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) at org.apache.commons.dbcp2.DelegatingStatement.close(DelegatingStatement.java:150) 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) at org.apache.commons.dbcp2.PoolableConnectionFactory.destroyObject(PoolableConnectionFactory.java:334) at org.apache.commons.pool2.impl.GenericObjectPool.destroy(GenericObjectPool.java:890) at org.apache.commons.pool2.impl.GenericObjectPool.invalidateObject(GenericObjectPool.java:649) - locked <0x00007fa2651f85f8> (a org.apache.commons.pool2.impl.DefaultPooledObject) at org.apache.commons.pool2.impl.GenericObjectPool.removeAbandoned(GenericObjectPool.java:1022) at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:418) at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363) at org.apache.commons.dbcp2.PoolingDataSource.getConnection(PoolingDataSource.java:134) at org.apache.commons.dbcp2.BasicDataSource.getConnection(BasicDataSource.java:1533)
> {code}
> Cheers,
> Daniel Dudziak
> Atlassian Developer
--
This message was sent by Atlassian Jira
(v8.3.4#803005)