[QPIDJMS-458] Potential race condition in JmsConnection.destroyResource

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Done
• Affects Version/s: 0.42.0
• Component/s: qpid-jms-client

Environment

OS: Windows 10 64Bit
Broker: Apache Artemis 2.8.0
JVM: Java HotSpot(TM) Client VM (25.40-b25, mixed mode)
Java: version 1.8.0_40, vendor Oracle Corporation

• Assignee: Unassigned
• Reporter: Christian Danner
• Created: 21/May/19 12:33
• Updated: 21/Aug/19 14:53
• Resolved: 21/Aug/19 14:53

Description

It seems there is a race condition when attempting to close a JmsMessageProducer as indicated by the stack trace below. The corresponding Thread is stuck waiting for the JmsMessageProducer to be destroyed for a JmsConnection.

This behaviour was observed while testing Apache Artemis with low disk space. 

In the provided trace we attempt to close a broker connection due to a JMSException (TransactionRolledBackException caused by a duplicate message ID), however the Thread gets stuck indefinitely waiting for the JmsMessageProducer to be destroyed.

We keep track of all sessions for a JmsConnection (one session per Thread) and attempt to perform a graceful connection shutdown by closing all producers and consumers, followed by each session before finally calling close on the connection.

We use external synchronization to ensure that the connection can only be closed by a single Thread (so in this example all other Threads attempting to use the broker connection are blocked waiting for the lock from the closing Thread to be released).

 

Stack Trace:

{{"Replicator_node1-->node2_[0ms]" #25 prio=5 os_prio=0 tid=0x49383c00 nid=0x3918 in Object.wait() [0x4b1ef000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:502)
at org.apache.qpid.jms.provider.BalancedProviderFuture.sync(BalancedProviderFuture.java:137)

• locked <0x04e60300> (a org.apache.qpid.jms.provider.BalancedProviderFuture)
  at org.apache.qpid.jms.JmsConnection.destroyResource(JmsConnection.java:755)
  at org.apache.qpid.jms.JmsConnection.destroyResource(JmsConnection.java:744)
  at org.apache.qpid.jms.JmsMessageProducer.doClose(JmsMessageProducer.java:103)
  at org.apache.qpid.jms.JmsMessageProducer.close(JmsMessageProducer.java:89)
  at acme.broker.client.jms.impl.JMSMessageProducer.closeInternal(JMSMessageProducer.java:48)
  at acme.broker.client.jms.impl.JMSMessageProducer.close(JMSMessageProducer.java:43)
  at acme.broker.client.AbstractSession.tryClose(AbstractSession.java:108)
  at acme.broker.client.AbstractSession.close(AbstractSession.java:90)
  at acme.broker.client.AbstractThreadedSessionManager.close(AbstractThreadedSessionManager.java:108)
• locked <0x1d321078> (a java.util.concurrent.ConcurrentHashMap)
  at acme.broker.client.AbstractBrokerConnection.closeInternal(AbstractBrokerConnection.java:204)
  at acme.broker.client.AbstractBrokerConnection.close(AbstractBrokerConnection.java:84)
  at acme.replication.jms.JMSMessageBridge.trySend(JMSMessageBridge.java:109)
  at acme.replication.jms.JMSMessageBridge.access$6(JMSMessageBridge.java:99)
  at acme.replication.jms.JMSMessageBridge$ReplicatorRunnable.run(JMSMessageBridge.java:62)
  at java.lang.Thread.run(Thread.java:745)

Locked ownable synchronizers:

• <0x1cfa76b0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)}}