[
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)
