[
https://issues.apache.org/jira/browse/AMQ-5508?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14284983#comment-14284983
]
Tim Bain commented on AMQ-5508:
-------------------------------
I think that your "bigger concern" described just above the stack trace is the
more important issue here, and I think that fixing that should make your patch
(which just deals with the fallout when that fundamental failure occurs)
unnecessary. So I'd recommend that we fix the underlying issue in this JIRA
(in 5.11) rather than using the supplied patch to Band-Aid the symptoms and
submitting a separate JIRA for the underlying issue, unless for some reason
it's not possible to get the underlying issue fixed for 5.11.
> Broker shutdown race condition leads to "IllegalStateException: Timer already
> cancelled"
> ----------------------------------------------------------------------------------------
>
> Key: AMQ-5508
> URL: https://issues.apache.org/jira/browse/AMQ-5508
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.10.0
> Reporter: Pero Atanasov
> Priority: Minor
> Attachments: AMQ5508.patch
>
>
> This issue is seen on the surface with the broker failing to remove a
> consumer:
> 2014-12-19 10:45:42,586 | WARN | Failed to remove consumer:
> ID:hack-34927-1419007505006-2:3:0:0 |
> org.apache.activemq.broker.TransportConnection | ActiveMQ
> BrokerService[broker0] Task-6
> java.lang.IllegalStateException: Timer already cancelled.
> The full stack trace [STACK_TRACE] will be specified at the end of this
> report.
> In this case, the race condition is exposed via some of the AdvisoryBroker
> code while trying to send an advisory message as part of the
> consumer/producer addition/removal code. Below are excerpts of code to
> explain this race condition:
> activemq-broker/src/main/java/org/apache/activemq/advisory/AdvisoryBroker.java
> Lines 605 - 637 [in fireAdvisory(...)]
> if (getBrokerService().isStarted()) {
> // code to create and populate an advisory message
> next.send(producerExchange, advisoryMessage);
> // send will trigger destination creation/addition for this advisory
> message topic
> }
> However, it can easily happen that a client (consumer or producer) connects
> and is added _before_ getBrokerService().isStarted() is true, so in that
> case, the boolean expression in the block above will evaluate to false and
> hence skip the entire advisory message send and create/add destination
> process. At this point, the consumer/producer destination does not have its
> advisory message destination created. If no other consumer/producer connects
> on the same destination until the broker is shutting down, then no advisory
> destination pairing will be created for that consumer/producer. When the
> broker starts the shutdown process, the event that will trigger an advisory
> message will be the removal of a consumer/producer as part of the
> TransportConnection stopping process. The sequence of calls with line numbers
> can be seen within the STACK_TRACE.
> Back to the above specified code block, when the broker is shutting down, the
> broker is still in the started state. Then, the boolean expression will
> evaluate to true and hence proceed with the advisory message creation/sending
> and destination creation/addition process. However, in the meantime, as part
> of the shutdown process, the Scheduler timer is being cancelled. Consider the
> following blocks of code:
> activemq-broker/src/main/java/org/apache/activemq/broker/BrokerService.java
> Lines 756 - 761 [in stop()]
> // for each service
> stopper.stop(service);
> activemq-client/src/main/java/org/apache/activemq/util/ServiceSupport.java
> Lines 67 - 84 [in stop()]
> if (stopped.compareAndSet(false, true)) {
> ... some code ...
> doStop(stopper);
> ... some code ...
> }
> activemq-client/src/main/java/org/apache/activemq/thread/Scheduler.java
> Lines 69 - 71 [in doStop(...)]
> if (this.timer != null) {
> this.timer.cancel();
> }
> At this point, the timer is cancelled. Now, back to the thread removing the
> consumer. From the STACK_TRACE, it can be seen that after many calls related
> to the advisory message destination creation, it ends up in AbstractRegion’s
> addDestination method.
> activemq-broker/src/main/java/org/apache/activemq/broker/region/AbstractRegion.java
> Lines 132 - 145 [in addDestination(...)]
> if (dest == null) {
> ... some code ...
> dest = createDestination(context, destination);
> ... some code ...
> dest.start();
> ... some code ...
> }
> As it can be seen in the STACK_TRACE below, dest.start() call will trigger
> the need for a timer to be scheduled on the same timer that has already been
> cancelled. Some debug prints to confirm the race condition:
> 1. Fail to send advisory message for this consumer advisory topic because
> getBrokerService().isStarted() is false:
> 2015-01-06 08:49:26,215 | INFO | patanasov: from AdvisoryBroker fireAdvisory
> would have sent advisoryMessage: topic
> ActiveMQ.Advisory.Consumer.Queue.2015.01.06-08.23.00.16401 |
> org.apache.activemq.advisory.AdvisoryBroker
> 2. Broker shutting down and cancelling timer:
> 2015-01-06 08:49:43,602 | INFO | Apache ActiveMQ 5.10.0 (broker0,
> ID:host-40197-1420555763149-0:1) is shutting down |
> org.apache.activemq.broker.BrokerService | ActiveMQ ShutdownHook
> 2015-01-06 08:49:43,603 | INFO | patanasov: from ServiceSupport calling
> doStop(stopper) | org.apache.activemq.util.ServiceSupport | ActiveMQ
> ShutdownHook
> 2015-01-06 08:49:43,603 | INFO | patanasov: from Scheduler
> doStop(ServiceStopper stopper) calling this.timer.cancel(): timer
> java.util.Timer@7df33bb0 | org.apache.activemq.thread.Scheduler | ActiveMQ
> ShutdownHook
> 3. Adding destination and scheduling on cancelled timer (7df33bb0):
> 2015-01-06 08:49:43,767 | INFO | patanasov: broker0 adding destination:
> qualified:
> topic://ActiveMQ.Advisory.Consumer.Queue.2015.01.06-08.23.00.16401, physical:
> ActiveMQ.Advisory.Consumer.Queue.2015.01.06-08.23.00.16401 |
> org.apache.activemq.broker.region.AbstractRegion | ActiveMQ
> BrokerService[broker0] Task-12
> 2015-01-06 08:49:43,782 | INFO | patanasov: from schedualPeriodically:
> timer: java.util.Timer@7df33bb0 | org.apache.activemq.thread.Scheduler |
> ActiveMQ BrokerService[broker0] Task-12
> 2015-01-06 08:49:43,785 | INFO | patanasov: caught an exception in
> schedualPeriodically: | org.apache.activemq.thread.Scheduler | ActiveMQ
> BrokerService[broker0] Task-12
> java.lang.IllegalStateException: Timer already cancelled.
> I will provide a patch to fix this issue. However, the bigger concern here is
> that advisory message destination creations fail for clients that connect
> while getBrokerService().isStarted() is false. If there is only one
> consumer/producer on one destination and if it connects while
> getBrokerService().isStarted() is false, then it will fail to create/send
> advisory message for that destination, at least until the producer/consumer
> is removed at the end. I will continue looking to learn more about this state
> of the broker and open a separate JIRA issue if needed.
> STACK_TRACE:
> java.lang.IllegalStateException: Timer already cancelled.
> at java.util.Timer.sched(Timer.java:354)
> at java.util.Timer.schedule(Timer.java:222)
> at
> org.apache.activemq.thread.Scheduler.schedualPeriodically(Scheduler.java:53)
> at org.apache.activemq.broker.region.Topic.start(Topic.java:563)
> at
> org.apache.activemq.broker.region.AbstractRegion.addDestination(AbstractRegion.java:141)
> at
> org.apache.activemq.broker.region.RegionBroker.addDestination(RegionBroker.java:325)
> at
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:167)
> at
> org.apache.activemq.advisory.AdvisoryBroker.addDestination(AdvisoryBroker.java:184)
> at
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:167)
> at
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:167)
> at
> org.apache.activemq.broker.MutableBrokerFilter.addDestination(MutableBrokerFilter.java:172)
> at
> org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:439)
> at
> org.apache.activemq.broker.jmx.ManagedRegionBroker.send(ManagedRegionBroker.java:297)
> at
> org.apache.activemq.advisory.AdvisoryBroker.fireAdvisory(AdvisoryBroker.java:615)
> at
> org.apache.activemq.advisory.AdvisoryBroker.fireConsumerAdvisory(AdvisoryBroker.java:564)
> at
> org.apache.activemq.advisory.AdvisoryBroker.fireConsumerAdvisory(AdvisoryBroker.java:550)
> at
> org.apache.activemq.advisory.AdvisoryBroker.removeConsumer(AdvisoryBroker.java:271)
> at
> org.apache.activemq.broker.BrokerFilter.removeConsumer(BrokerFilter.java:132)
> at
> org.apache.activemq.broker.BrokerFilter.removeConsumer(BrokerFilter.java:132)
> at
> org.apache.activemq.broker.MutableBrokerFilter.removeConsumer(MutableBrokerFilter.java:137)
> at
> org.apache.activemq.broker.TransportConnection.processRemoveConsumer(TransportConnection.java:651)
> at
> org.apache.activemq.broker.TransportConnection.processRemoveSession(TransportConnection.java:690)
> at
> org.apache.activemq.broker.TransportConnection.processRemoveConnection(TransportConnection.java:802)
> at
> org.apache.activemq.broker.TransportConnection.doStop(TransportConnection.java:1143)
> at
> org.apache.activemq.broker.TransportConnection$4.run(TransportConnection.java:1073)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
> at java.lang.Thread.run(Thread.java:619)
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
