[
https://issues.apache.org/jira/browse/AMQ-6866?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16260611#comment-16260611
]
Chris Chou edited comment on AMQ-6866 at 11/21/17 11:46 AM:
------------------------------------------------------------
long time before this, in the activemq server log , we always see something
like this: The connection to 'xxx' is taking a long time to shutdown.
but why the connection is being shutdown, we cannot find it out from the log.
{code:java}
[2017-11-11
06:58:37,561]-[main]-[]-[org.apache.activemq.broker.BrokerService.doStartBroker(BrokerService.java:761)]-[INFO]
For help or more information please see: http://activemq.apache.org
[2017-11-11 06:59:09,436]-[ActiveMQ Transport:
ssl:///220.51.13.51:33248]-[]-[org.apache.activemq.broker.TransportConnection.serviceTransportException(TransportConnection.java:240)]-[WARN]
Transport Connection to: tcp://220.51.13.51:33248 failed: java.io.EOFException
[2017-11-11 06:59:09,459]-[ActiveMQ Transport:
ssl:///220.51.13.85:55936]-[]-[org.apache.activemq.broker.TransportConnection.serviceTransportException(TransportConnection.java:240)]-[WARN]
Transport Connection to: tcp://220.51.13.85:55936 failed: java.io.EOFException
[2017-11-11 06:59:09,539]-[ActiveMQ Transport:
ssl:///220.51.13.56:44800]-[]-[org.apache.activemq.broker.TransportConnection.serviceTransportException(TransportConnection.java:240)]-[WARN]
Transport Connection to: tcp://220.51.13.56:44800 failed: java.io.EOFException
[2017-11-11 06:59:10,809]-[ActiveMQ Transport:
ssl:///220.51.13.51:33260]-[]-[org.apache.activemq.broker.TransportConnection.serviceTransportException(TransportConnection.java:240)]-[WARN]
Transport Connection to: tcp://220.51.13.51:33260 failed: java.io.EOFException
[2017-11-11 06:59:10,810]-[ActiveMQ Transport:
ssl:///220.51.13.50:47032]-[]-[org.apache.activemq.broker.TransportConnection.serviceTransportException(TransportConnection.java:240)]-[WARN]
Transport Connection to: tcp://220.51.13.50:47032 failed: java.io.EOFException
[2017-11-11 11:19:01,722]-[ActiveMQ Transport:
ssl:///220.51.13.51:45900]-[]-[org.apache.activemq.broker.TransportConnection.stop(TransportConnection.java:1104)]-[INFO]
The connection to 'tcp://220.51.13.51:33246' is taking a long time to shutdown.
[2017-11-11 11:19:06,723]-[ActiveMQ Transport:
ssl:///220.51.13.51:45900]-[]-[org.apache.activemq.broker.TransportConnection.stop(TransportConnection.java:1104)]-[INFO]
The connection to 'tcp://220.51.13.51:33246' is taking a long time to
shutdown.\
...
// a lot of logs like this
{code}
was (Author: mhsjlove):
long time before this, in the activemq server log , we always see something
like this: The connection to 'xxx' is taking a long time to shutdown
{code:java}
[2017-11-11
06:58:37,561]-[main]-[]-[org.apache.activemq.broker.BrokerService.doStartBroker(BrokerService.java:761)]-[INFO]
For help or more information please see: http://activemq.apache.org
[2017-11-11 06:59:09,436]-[ActiveMQ Transport:
ssl:///220.51.13.51:33248]-[]-[org.apache.activemq.broker.TransportConnection.serviceTransportException(TransportConnection.java:240)]-[WARN]
Transport Connection to: tcp://220.51.13.51:33248 failed: java.io.EOFException
[2017-11-11 06:59:09,459]-[ActiveMQ Transport:
ssl:///220.51.13.85:55936]-[]-[org.apache.activemq.broker.TransportConnection.serviceTransportException(TransportConnection.java:240)]-[WARN]
Transport Connection to: tcp://220.51.13.85:55936 failed: java.io.EOFException
[2017-11-11 06:59:09,539]-[ActiveMQ Transport:
ssl:///220.51.13.56:44800]-[]-[org.apache.activemq.broker.TransportConnection.serviceTransportException(TransportConnection.java:240)]-[WARN]
Transport Connection to: tcp://220.51.13.56:44800 failed: java.io.EOFException
[2017-11-11 06:59:10,809]-[ActiveMQ Transport:
ssl:///220.51.13.51:33260]-[]-[org.apache.activemq.broker.TransportConnection.serviceTransportException(TransportConnection.java:240)]-[WARN]
Transport Connection to: tcp://220.51.13.51:33260 failed: java.io.EOFException
[2017-11-11 06:59:10,810]-[ActiveMQ Transport:
ssl:///220.51.13.50:47032]-[]-[org.apache.activemq.broker.TransportConnection.serviceTransportException(TransportConnection.java:240)]-[WARN]
Transport Connection to: tcp://220.51.13.50:47032 failed: java.io.EOFException
[2017-11-11 11:19:01,722]-[ActiveMQ Transport:
ssl:///220.51.13.51:45900]-[]-[org.apache.activemq.broker.TransportConnection.stop(TransportConnection.java:1104)]-[INFO]
The connection to 'tcp://220.51.13.51:33246' is taking a long time to shutdown.
[2017-11-11 11:19:06,723]-[ActiveMQ Transport:
ssl:///220.51.13.51:45900]-[]-[org.apache.activemq.broker.TransportConnection.stop(TransportConnection.java:1104)]-[INFO]
The connection to 'tcp://220.51.13.51:33246' is taking a long time to
shutdown.\
...
// a lot of logs like this
{code}
> deadlock when using async dispatch
> ----------------------------------
>
> Key: AMQ-6866
> URL: https://issues.apache.org/jira/browse/AMQ-6866
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.14.0
> Environment: linux suse 11 sp3
> activemq 5.14.0
> Reporter: Chris Chou
>
> we use activemq as out message system.
> we use jdbc master slave for activemq server.
> we have several node and each node has two connection, one
> connection(useAsyncSend=true) is used to send topic message, and another
> connection(useAsyncSend=false) is used to send queue message and register
> message consumer listener, both of the connection is use fail over transport.
> when we send queue message, we set persist to true and the TTL is half an
> hour.
> when we send topic message, we set persist to false and TTL is 7 days.
> both topic and queue consumer is not durable.
> after some time, we get java level deadlock in the MQ server. this problem
> only occurs in one of our envs, it can only be reproduced in this env after
> sevaral hours, cannot be reproduced in other envs.
>
> {code:java}
> Found one Java-level deadlock:
> =============================
> "ActiveMQ Transport: ssl:///220.51.13.50:46440":
> waiting to lock monitor 0x00007fa7b0069f98 (object 0x00000006a0455eb0, a
> org.apache.activemq.broker.region.Topic),
> which is held by "ActiveMQ Transport: ssl:///220.51.13.57:44446"
> "ActiveMQ Transport: ssl:///220.51.13.57:44446":
> waiting to lock monitor 0x00007fa7a800e468 (object 0x00000006a16161c8, a
> java.lang.Object),
> which is held by "ActiveMQ BrokerService[localhost] Task-95"
> "ActiveMQ BrokerService[localhost] Task-95":
> waiting to lock monitor 0x00007fa7b40302f8 (object 0x00000006a02f0e20, a
> org.apache.activemq.thread.PooledTaskRunner$1),
> which is held by "ActiveMQ Transport: ssl:///220.51.13.57:44446"
> Java stack information for the threads listed above:
> ===================================================
> "ActiveMQ Transport: ssl:///220.51.13.50:46440":
> at org.apache.activemq.broker.region.Topic.doMessageSend(Topic.java:498)
> - waiting to lock <0x00000006a0455eb0> (a
> org.apache.activemq.broker.region.Topic)
> at org.apache.activemq.broker.region.Topic.send(Topic.java:479)
> at
> org.apache.activemq.broker.region.DestinationFilter.send(DestinationFilter.java:132)
> at
> org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:503)
> at
> org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:468)
> at
> org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
> at
> org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:293)
> at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:153)
> at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:153)
> at
> org.apache.activemq.security.AuthorizationBroker.send(AuthorizationBroker.java:226)
> at
> org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:158)
> at
> org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:578)
> at
> org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:768)
> at
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:333)
> at
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:197)
> at
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> at
> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:125)
> at
> org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:300)
> at
> org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
> at
> org.apache.activemq.transport.tcp.SslTransport.doConsume(SslTransport.java:108)
> at
> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:233)
> at
> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:215)
> at java.lang.Thread.run(Thread.java:745)
> "ActiveMQ Transport: ssl:///220.51.13.57:44446":
> at
> org.apache.activemq.broker.region.PrefetchSubscription.dispatchPending(PrefetchSubscription.java:683)
> - waiting to lock <0x00000006a16161c8> (a java.lang.Object)
> at
> org.apache.activemq.broker.region.PrefetchSubscription.onDispatch(PrefetchSubscription.java:813)
> at
> org.apache.activemq.broker.region.PrefetchSubscription$3.onSuccess(PrefetchSubscription.java:775)
> at
> org.apache.activemq.broker.TransportConnection.processDispatch(TransportConnection.java:995)
> at
> org.apache.activemq.broker.TransportConnection.iterate(TransportConnection.java:1024)
> at
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> at
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> at
> java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(ThreadPoolExecutor.java:2022)
> at
> java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:823)
> at
> java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1369)
> at
> org.apache.activemq.thread.PooledTaskRunner.wakeup(PooledTaskRunner.java:83)
> - locked <0x00000006a02f0e20> (a
> org.apache.activemq.thread.PooledTaskRunner$1)
> at
> org.apache.activemq.broker.TransportConnection.dispatchAsync(TransportConnection.java:950)
> at
> org.apache.activemq.broker.region.TopicSubscription.dispatch(TopicSubscription.java:680)
> at
> org.apache.activemq.broker.region.TopicSubscription.add(TopicSubscription.java:122)
> - locked <0x00000006a2a0af58> (a java.lang.Object)
> at
> org.apache.activemq.broker.region.policy.SimpleDispatchPolicy.dispatch(SimpleDispatchPolicy.java:48)
> at org.apache.activemq.broker.region.Topic.dispatch(Topic.java:761)
> at org.apache.activemq.broker.region.Topic.doMessageSend(Topic.java:553)
> - locked <0x00000006a0455eb0> (a
> org.apache.activemq.broker.region.Topic)
> at org.apache.activemq.broker.region.Topic.send(Topic.java:479)
> at
> org.apache.activemq.broker.region.DestinationFilter.send(DestinationFilter.java:132)
> at
> org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:503)
> at
> org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:468)
> at
> org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
> at
> org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:293)
> at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:153)
> at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:153)
> at
> org.apache.activemq.security.AuthorizationBroker.send(AuthorizationBroker.java:226)
> at
> org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:158)
> at
> org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:578)
> at
> org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:768)
> at
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:333)
> at
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:197)
> at
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> at
> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:125)
> at
> org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:300)
> at
> org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
> at
> org.apache.activemq.transport.tcp.SslTransport.doConsume(SslTransport.java:108)
> at
> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:233)
> at
> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:215)
> at java.lang.Thread.run(Thread.java:745)
> "ActiveMQ BrokerService[localhost] Task-95":
> at
> org.apache.activemq.thread.PooledTaskRunner.wakeup(PooledTaskRunner.java:62)
> - waiting to lock <0x00000006a02f0e20> (a
> org.apache.activemq.thread.PooledTaskRunner$1)
> at
> org.apache.activemq.broker.TransportConnection.dispatchAsync(TransportConnection.java:950)
> at
> org.apache.activemq.broker.region.PrefetchSubscription.dispatch(PrefetchSubscription.java:793)
> at
> org.apache.activemq.broker.region.PrefetchSubscription.dispatchPending(PrefetchSubscription.java:717)
> - locked <0x00000006a16161e0> (a java.lang.Object)
> - locked <0x00000006a16161c8> (a java.lang.Object)
> at
> org.apache.activemq.broker.region.PrefetchSubscription.add(PrefetchSubscription.java:162)
> at
> org.apache.activemq.broker.region.Queue.doActualDispatch(Queue.java:2071)
> at org.apache.activemq.broker.region.Queue.doDispatch(Queue.java:2019)
> at
> org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:2160)
> at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1601)
> - locked <0x00000006a1ed9c58> (a java.lang.Object)
> at
> org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:133)
> at
> org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:48)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Found 1 deadlock.
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
