[QPID-4276] Java client - deadlock on concurrent close of consumer and connection

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 0.16, 0.18, 0.29
• Fix Version/s: 0.31
• Component/s: JMS AMQP 0-x
• Assignee: Unassigned
• Reporter: Phil Harvey
• Created: 31/Aug/12 14:28
• Updated: 19/Mar/15 12:23
• Resolved: 10/Feb/15 09:42

Description

We have observed a deadlock on the Java client when the following are done concurrently:

• An application thread closes a consumer
• The corresponding JMS connection is closed inside onMessage()

See attached stack trace for details.

We think this locking bug was introduced when fixing QPID-3911.

See thread dump excerpt below:

Found one Java-level deadlock:
=============================
"Thread-11-Consumer_0":
  waiting to lock monitor 0x000000004342b4c0 (object 0x00000000ed1e6a40, a java.lang.Object),
  which is held by "Dispatcher-1-Conn-1"
"Dispatcher-1-Conn-1":
  waiting to lock monitor 0x000000004342b568 (object 0x00000000ed060c48, a java.lang.Object),
  which is held by "Thread-11-Consumer_0"

Java stack information for the threads listed above:
===================================================
"Thread-11-Consumer_0":
        at org.apache.qpid.client.BasicMessageConsumer.close(BasicMessageConsumer.java:598)
        - waiting to lock <0x00000000ed1e6a40> (a java.lang.Object)
        - locked <0x00000000ed060c48> (a java.lang.Object)
        at org.apache.qpid.client.BasicMessageConsumer.close(BasicMessageConsumer.java:558)
        at org.apache.qpid.disttest.jms.ClientJmsDelegate.closeTestConsumer(ClientJmsDelegate.java:612)
        at org.apache.qpid.disttest.client.ConsumerParticipant.releaseResources(ConsumerParticipant.java:244)
        at org.apache.qpid.disttest.client.ParticipantExecutor$ParticipantRunnable.runParticipantAndSendResults(ParticipantExecutor.java:112)
        at org.apache.qpid.disttest.client.ParticipantExecutor$ParticipantRunnable.run(ParticipantExecutor.java:84)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
"Dispatcher-1-Conn-1":
        at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:857)
        - waiting to lock <0x00000000ed060c48> (a java.lang.Object)
        - locked <0x00000000ed060c58> (a java.lang.Object)
        at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:848)
        - locked <0x00000000ed0bedd8> (a java.lang.Object)
        - locked <0x00000000ed060c58> (a java.lang.Object)
        at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:848)
        - locked <0x00000000ed1e6a40> (a java.lang.Object)
        - locked <0x00000000ed060c58> (a java.lang.Object)
        at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:832)
        at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:823)
        at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:818)
        at org.apache.qpid.disttest.jms.ClientJmsDelegate.tearDownTest(ClientJmsDelegate.java:574)
        at org.apache.qpid.disttest.client.Client.tearDownTest(Client.java:179)
        at org.apache.qpid.disttest.client.ClientCommandVisitor.visit(ClientCommandVisitor.java:90)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.qpid.disttest.Visitor.invokeVisitMethod(Visitor.java:61)
        at org.apache.qpid.disttest.Visitor.visit(Visitor.java:39)
        at org.apache.qpid.disttest.message.Command.accept(Command.java:48)
        at org.apache.qpid.disttest.client.Client.processInstruction(Client.java:113)
        at org.apache.qpid.disttest.jms.ClientJmsDelegate$1.onMessage(ClientJmsDelegate.java:122)
        at org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:751)
        at org.apache.qpid.client.BasicMessageConsumer.notifyMessage(BasicMessageConsumer.java:725)
        at org.apache.qpid.client.AMQSession$Dispatcher.notifyConsumer(AMQSession.java:3479)
        at org.apache.qpid.client.AMQSession$Dispatcher.dispatchMessage(AMQSession.java:3418)
        - locked <0x00000000ed1a30f0> (a java.lang.Object)
        - locked <0x00000000ed186400> (a java.lang.Object)
        at org.apache.qpid.client.AMQSession$Dispatcher.access$1000(AMQSession.java:3205)
        at org.apache.qpid.client.AMQSession.dispatch(AMQSession.java:3198)
        at org.apache.qpid.client.message.UnprocessedMessage.dispatch(UnprocessedMessage.java:54)
        at org.apache.qpid.client.AMQSession$Dispatcher.run(AMQSession.java:3341)
        at java.lang.Thread.run(Thread.java:662)

Found 1 deadlock.

Issue Links

• is part of: QPID-6374 [Java Client] Eliminate deadlocks by acquiring locks in a consistent order
• is related to: QPID-4275 Java Performance Tests - race condition between closing test consumer and test connection