Locked datasource connection returned from pool?

[porobd]

I am using WildFly 10.1 in my product and I see a deadlock in the thread dump which has left me puzzled about the way connection pooling is done in WildFly 10.1.

I see the following thread waiting to get a lock on the BaseWrapperManagedConnection object.

"default task-91" #1016 prio=5 os_prio=0 tid=0x00007f399c1a48a0 nid=0x3ee9 waiting on condition [0x00007f395b7a3000]

   java.lang.Thread.State: WAITING (parking)

        at sun.misc.Unsafe.park(Native Method)

        - parking to wait for  <0x0000000682a00250> (a java.util.concurrent.locks.ReentrantLock$FairSync)

        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)

        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)

        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)

        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)

        at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)

        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)

        at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.lock(BaseWrapperManagedConnection.java:374)

        at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.start(XAManagedConnection.java:245)

        at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.start(XAResourceWrapperImpl.java:215)

        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:662)

        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:423)

        at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener$TransactionSynchronization.enlist(TxConnectionListener.java:986)

        at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:379)

        at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:553)

        at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:928)

        at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:750)

        at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:138)

        at org.jboss.as.connector.subsystems.datasources.WildFlyDataSource.getConnection(WildFlyDataSource.java:66)

.......

.......

And the following thread seems to own that lock. This thread is blocked on another lock which is specific to my product.

"default task-45" #965 prio=5 os_prio=0 tid=0x00007f399c19c3d0 nid=0x3e42 waiting for monitor entry [0x00007f3a01816000]

.......

.......

at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)

        at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292)

        at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)

        at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)

        at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)

        at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)

        at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)

        at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)

        at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)

        at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)

        at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)

        at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)

        at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)

        at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)

        at io.undertow.servlet.handlers.ServletInitialHandler$1$1.run(ServletInitialHandler.java:110)

        at java.security.AccessController.doPrivileged(Native Method)

        at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:107)

        at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)

        at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:805)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:

        - <0x0000000682a00250> (a java.util.concurrent.locks.ReentrantLock$FairSync)

        - <0x00000006e54960b8> (a java.util.concurrent.ThreadPoolExecutor$Worker)

        - <0x00000006f0360cd0> (a java.util.concurrent.locks.ReentrantLock$FairSync)

        - <0x00000006f0360e88> (a java.util.concurrent.locks.ReentrantLock$FairSync)

I am not able to provide the entire stack trace but my general question is why a locked connection is returned as an available connection from the pool to the thread named 'default task-91' ? If the connection is locked, I would assume it is currently being used by another thread (in this case 'default task-45') and so should not have been returned from the pool (as part org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection). Isn't this a correct assumption ? OR can a connection, which is currently being used by another thread (and hence another transaction), be returned as an available connection from the pool ?

Thanks,

Datta.

[andey]

It seems that a connection is concurrency being used by two different threads. The second thread is attempting to close a connection, but there are active locks on it. The first thread is the one that is holding the lock on the connection

In order to resolve the issue please check with your developers and make sure that a connection is not allowed to be used by multiple threads at once.

It's probably this one.

https://issues.jboss.org/browse/JBTM-1951

[porobd]

Hi Anup, Thanks for the reply. How did you figure out that one thread is trying to close the connection; I don't see that in the stack trace. As per the trace of "default task-91". that thread was allocated that connection from the pool and is trying to enlist that in the transaction. So, what I did not understand is why it was allocated a connection which is already being used by another thread (in this case "default task-45". We have a common datasource which is used by multiple web/EJB applications. I would think it's the datasource pool's responsibility to ensure that a connection is being used by only one transaction/thread at one time. I do not understand how I can write an application that can force the connection pooling mechanism to provide the same connection to multiple threads. Or is there are option to do that in WildFly 10.1 which I am missing. We had the same code in JBOss AS 6.1 and it was working fine. Thanks, Datta.