Sergiy Barlabanov created AMQ-4166:
--------------------------------------
Summary: RedeliveryPlugin causes a deadlock with JobSchedulerImpl
Key: AMQ-4166
URL: https://issues.apache.org/jira/browse/AMQ-4166
Project: ActiveMQ
Issue Type: Bug
Components: Broker
Affects Versions: 5.7.0
Environment: Reproduced on Windows 8, Windows Vista, MacOS X
with Oracle jdk 1.7.0_07. ActiveMQ is started embedded using RAR inside
Glassfish 3.1.2.2.
Reporter: Sergiy Barlabanov
Originates from the forum discussion
http://activemq.2283324.n4.nabble.com/RedeliveryPlugin-causes-a-deadlock-with-JobSchedulerImpl-in-ActiveMQ-5-7-0-tt4659019.html
we have RedeliveryPlugin causing thread deadlock together with
JobSchedulerImpl. ActiveMQ version is 5.7.0. We activated RedeliveryPlugin in
our broker config xml (see below). There two stacktraces below as well. One is
from ActiveMQ VMTransport thread, which tries to send a message to a dead
letter queue using RedeliveryPlugin. RedeliveryPlugin just tries to reschedule
the message for redelivery and for that it calls JobSchedulerImpl and blocks on
its synchronized method "schedule". On the way "consumersLock" is locked.
Another stack trace is from JobScheduler:JMS thread, which fires a job to
redeliver some message and tries to send it using the same queue used by the
VMTransport thread. And it blocks on that consumersLock locked by the
VMTransport thread. And this occurs in JobSchedulerImpl#mainLoop method inside
synchronized {} block causing a deadlock, since the VMTransport thread tries to
call another synchronized method of JobSchedulerImpl. The art how
RedeliveryPlugin and JobSchedulerImpl are programmed seems to be quite
dangerous, since they both access the queues and try to acquire queue locks.
And additionally synchronized methods of JobSchedulerImpl are called directly
from RedeliveryPlugin making that to a nice source of thread deadlocks. And I
see no measures taken in the code to avoid these deadlocks.
We can reproduce it quite often if we start ActiveMQ with empty stores (kahadb
and scheduler stores are deleted manually from the file system before startup).
But looking at the code, I would say that the problem may occur in any
situation in any deployment scenario (standalone or embedded in a JEE
container). It is just enough to have some Transport thread redelivering a
message and the JobScheduler thread trying to fire a job at the same moment on
the same queue.
And another strange thing, which is may be has nothing to do with the deadlock
but is still strange, is that according to the stack trace RedeliveryPlugin
tries to redeliver an expired message.
Our broker configuration:
<broker xmlns="http://activemq.apache.org/schema/core"; brokerName="dcdng"
useJmx="true" useShutdownHook="false" schedulerSupport="false">
<managementContext>
<managementContext createConnector="false"/>
</managementContext>
<persistenceAdapter>
<kahaDB directory="${activemq.message.storage}"
journalMaxFileLength="10mb"/>
</persistenceAdapter>
<transportConnectors>
<transportConnector uri="${activemq.connector.address}"/>
</transportConnectors>
<destinationPolicy>
<policyMap>
<policyEntries>
<policyEntry queue=">" producerFlowControl="true">
<deadLetterStrategy>
<individualDeadLetterStrategy queuePrefix="DLQ."
useQueueForQueueMessages="true" processExpired="false" enableAudit="false"/>
</deadLetterStrategy>
</policyEntry>
</policyEntries>
</policyMap>
</destinationPolicy>
<plugins>
<redeliveryPlugin fallbackToDeadLetter="true"
sendToDlqIfMaxRetriesExceeded="true">
<redeliveryPolicyMap>
<redeliveryPolicyMap>
<redeliveryPolicyEntries>
<redeliveryPolicy queue="EventQueue"
maximumRedeliveries="10"
redeliveryDelay="1000"/>
</redeliveryPolicyEntries>
<defaultEntry>
<redeliveryPolicy maximumRedeliveries="3"
redeliveryDelay="1000"/>
</defaultEntry>
</redeliveryPolicyMap>
</redeliveryPolicyMap>
</redeliveryPlugin>
</plugins>
<systemUsage>
<systemUsage sendFailIfNoSpace="true">
<memoryUsage>
<memoryUsage limit="200 mb"/>
</memoryUsage>
<storeUsage>
<storeUsage limit="1000 mb"/>
</storeUsage>
<tempUsage>
<tempUsage limit="200 mb"/>
</tempUsage>
</systemUsage>
</systemUsage>
</broker>
Stack trace #1:
Name: ActiveMQ VMTransport: vm://dcdng#101-1
State: BLOCKED on
org.apache.activemq.broker.scheduler.JobSchedulerImpl@6a135124 owned by:
JobScheduler:JMS
Total blocked: 22 Total waited: 13
org.apache.activemq.broker.scheduler.JobSchedulerImpl.schedule(JobSchedulerImpl.java:110)
org.apache.activemq.broker.scheduler.SchedulerBroker.send(SchedulerBroker.java:185)
org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:317)
org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:135)
org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:135)
org.apache.activemq.broker.util.RedeliveryPlugin.scheduleRedelivery(RedeliveryPlugin.java:190)
org.apache.activemq.broker.util.RedeliveryPlugin.sendToDeadLetterQueue(RedeliveryPlugin.java:144)
org.apache.activemq.broker.MutableBrokerFilter.sendToDeadLetterQueue(MutableBrokerFilter.java:274)
org.apache.activemq.broker.region.RegionBroker.messageExpired(RegionBroker.java:798)
org.apache.activemq.broker.BrokerFilter.messageExpired(BrokerFilter.java:257)
org.apache.activemq.broker.BrokerFilter.messageExpired(BrokerFilter.java:257)
org.apache.activemq.advisory.AdvisoryBroker.messageExpired(AdvisoryBroker.java:284)
org.apache.activemq.broker.BrokerFilter.messageExpired(BrokerFilter.java:257)
org.apache.activemq.broker.BrokerFilter.messageExpired(BrokerFilter.java:257)
org.apache.activemq.broker.MutableBrokerFilter.messageExpired(MutableBrokerFilter.java:269)
org.apache.activemq.broker.MutableBrokerFilter.messageExpired(MutableBrokerFilter.java:269)
org.apache.activemq.broker.region.Queue.messageExpired(Queue.java:1657)
org.apache.activemq.broker.region.PrefetchSubscription.dispatchPending(PrefetchSubscription.java:640)
- locked java.lang.Object@7b97909e
- locked java.lang.Object@1b97b476
org.apache.activemq.broker.region.PrefetchSubscription.add(PrefetchSubscription.java:155)
org.apache.activemq.broker.region.Queue.doActualDispatch(Queue.java:1897)
org.apache.activemq.broker.region.Queue.doDispatch(Queue.java:1824)
org.apache.activemq.broker.region.Queue.removeSubscription(Queue.java:572)
org.apache.activemq.broker.region.AbstractRegion.removeConsumer(AbstractRegion.java:381)
org.apache.activemq.broker.region.RegionBroker.removeConsumer(RegionBroker.java:445)
org.apache.activemq.broker.jmx.ManagedRegionBroker.removeConsumer(ManagedRegionBroker.java:275)
org.apache.activemq.broker.BrokerFilter.removeConsumer(BrokerFilter.java:117)
org.apache.activemq.broker.BrokerFilter.removeConsumer(BrokerFilter.java:117)
org.apache.activemq.advisory.AdvisoryBroker.removeConsumer(AdvisoryBroker.java:254)
org.apache.activemq.broker.BrokerFilter.removeConsumer(BrokerFilter.java:117)
org.apache.activemq.broker.BrokerFilter.removeConsumer(BrokerFilter.java:117)
org.apache.activemq.broker.MutableBrokerFilter.removeConsumer(MutableBrokerFilter.java:123)
org.apache.activemq.broker.MutableBrokerFilter.removeConsumer(MutableBrokerFilter.java:123)
org.apache.activemq.broker.TransportConnection.processRemoveConsumer(TransportConnection.java:593)
org.apache.activemq.command.RemoveInfo.visit(RemoveInfo.java:76)
org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:294)
org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:152)
org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:116)
org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
org.apache.activemq.transport.vm.VMTransport.iterate(VMTransport.java:241)
org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:129)
org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:47)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
java.lang.Thread.run(Thread.java:722)
Stack trace #2:
Name: JobScheduler:JMS
State: WAITING on
java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync@30001430 owned
by: ActiveMQ VMTransport: vm://dcdng#101-1
Total blocked: 15 Total waited: 480
Stack trace:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:964)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1282)
java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:731)
org.apache.activemq.broker.region.Queue.messageSent(Queue.java:1679)
org.apache.activemq.broker.region.Queue.doMessageSend(Queue.java:791)
org.apache.activemq.broker.region.Queue.send(Queue.java:717)
org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:407)
org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:503)
org.apache.activemq.broker.jmx.ManagedRegionBroker.send(ManagedRegionBroker.java:311)
org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
org.apache.activemq.broker.scheduler.SchedulerBroker.scheduledJob(SchedulerBroker.java:251)
org.apache.activemq.broker.scheduler.JobSchedulerImpl.fireJob(JobSchedulerImpl.java:423)
org.apache.activemq.broker.scheduler.JobSchedulerImpl.mainLoop(JobSchedulerImpl.java:473)
- locked org.apache.activemq.broker.scheduler.JobSchedulerImpl@6a135124
org.apache.activemq.broker.scheduler.JobSchedulerImpl.run(JobSchedulerImpl.java:429)
java.lang.Thread.run(Thread.java:722)
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
