You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@activemq.apache.org by "Timothy Bish (JIRA)" <ji...@apache.org> on 2014/11/01 14:10:33 UTC
[jira] [Closed] (AMQ-5324) JMSXDeliveryCount incremented
unexpectedly after EOFException
[ https://issues.apache.org/jira/browse/AMQ-5324?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Timothy Bish closed AMQ-5324.
-----------------------------
Resolution: Cannot Reproduce
No test case available to reproduce. Recommend that you try a later relase of the broker to see if the problem still exists.
> JMSXDeliveryCount incremented unexpectedly after EOFException
> -------------------------------------------------------------
>
> Key: AMQ-5324
> URL: https://issues.apache.org/jira/browse/AMQ-5324
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker
> Affects Versions: 5.9.0
> Environment: jdk 1.7.0_45, atomikos 3.7.1, tomcat 7.0.26
> Reporter: Andy Hanton
>
> While testing recovery of my application after tomcat fails, I am seeing messages delivered with an unexpectedly high redelivery count after a a tomcat instance restarts. When tomcat stops, several transports receive an EOFException which causes the transports and the associated connections and consumers to stop. If any of the consumers had unacknowledged messages, the messages are immediately dispatched to another consumer. In some cases, the messages are dispatched to another consumer that is in the process of closing in response to one of the EOFExceptions. This dispatch fails and causes the redelivery count for the message to be incremented one or more times even though the consumer couldn't possibly deliver the message to the client because its tcp connection is already closed.
> My MessageListener is ignoring messages with a redelivery count of 4 or higher because the messages are expensive to process. In some cases, restarting the application server causes the message to be delivered a second time with a redelivery count of 4 instead of 2. I attempted to work around this problem by enabling the redelivery policy plugin, but the plugin does not appear to be invoked in this case.
> The problem is easiest to reproduce when at least three consumers are processing messages from a queue when tomcat is killed. While killing the application server in production is not ideal, it may be necessary if the application server hangs or runs out of memory. Other conditions such as a jvm crash or a networking failure would also produce a similar situation.
> While I understand that ensuring that messages are never delivered to consumers that are stopping might be difficult, I would expect a consumer to be marked as stopping within much less that a third of a second after its tcp connection closes. I would also expect that when the redelivery count of a message is incremented, the redelivery plugin would have a chance to delay the dispatch of the message based on the configured policy.
> Here are the log messages related to a message that is dispatched multiple times:
> 2014-08-19 15:49:54,024 | localhost adding consumer: ID:hostname-58095-1408405246656-1:10:114166:1 for destination queue://queueName | org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport: tcp://xx.xx.xx.xx:59625@61616
> 2014-08-19 15:49:54,626 | ack MessageAck {commandId = 559437, responseRequired = false, ackType = 0, consumerId = ID:hostname-58095-1408405246656-1:10:114166:1, firstMessageId = ID:hostname-58095-1408405246656-1:8:114134:1:1, lastMessageId = ID:hostname-58095-1408405246656-1:8:114134:1:1, destination = queue://queueName, transactionId = XID:[...], messageCount = 1, poisonCause = null} | org.apache.activemq.broker.region.PrefetchSubscription | ActiveMQ Transport: tcp://xx.xx.xx.xx:59625@61616
> 2014-08-19 15:49:54,624 | ID:hostname-58095-1408405246656-1:10:114166:1 dispatched: ID:hostname-58095-1408405246656-1:8:114134:1:1 - queue://queueName, dispatched: 1, inflight: 1 | org.apache.activemq.broker.region.PrefetchSubscription | ActiveMQ Connection Dispatcher: tcp://xx.xx.xx.xx:59625
> 2014-08-19 15:49:57,915 | localhost adding consumer: ID:hostname-58095-1408405246656-1:1:114032:1 for destination: queue://queueName | org.apache.activemq.broker.region.AbstractRetion | ActiveMQ Transport: tcp:///xx.xx.xx.xx:59607@61616
> 2014-08-19 15:49:58,291 | DEBUG | Transport Connection to: tcp://xx.xx.xx.xx:59607 failed: java.io.EOFException | org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ Transport: tcp://xx.xx.xx.xx:59607@61616
> 2014-08-19 15:49:58,293 | DEBUG | Transport Connection to: tcp://xx.xx.xx.xx:59625 failed: java.io.EOFException | org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ Transport: tcp://xx.xx.xx.xx:59625@61616
> 2014-08-19 15:49:58,370 | DEBUG | Stopping connection: tcp://xx.xx.xx.xx:59625 | org.apache.activemq.broker.TransportConnection | ActiveMQ BrokerService[localhost] Task-478
> 2014-08-19 15:49:58,430 | DEBUG | Stopped transport: tcp://xx.xx.xx.xx:59625 | org.apache.activemq.broker.TransportConnection | ActiveMQ BrokerService[localhost] Task-478
> 2014-08-19 15:49:58,435 | DEBUG | Stopping connection: tcp://xx.xx.xx.xx:59607 | org.apache.activemq.broker.TransportConnection | ActiveMQ BrokerService[localhost] Task-487
> 2014-08-19 15:49:58,437 | DEBUG | Cleaning up connection resources: tcp://xx.xx.xx.xx:59625 | org.apache.activemq.broker.TransportConnection | ActiveMQ BrokerService[localhost] Task-478
> 2014-08-19 15:49:58,524 | DEBUG | Stopped transport: tcp://xx.xx.xx.xx:59607 | org.apache.activemq.broker.TransportConnection | ActiveMQ BrokerService[localhost] Task-487
> 2014-08-19 15:49:58,543 | DEBUG | Cleaning up connection resources: tcp://xx.xx.xx.xx:59607 | org.apache.activemq.broker.TransportConnection | ActiveMQ Brokerwserice[localhost] Task-487
> 2014-08-19 15:49:58,874 | DEBUG | Connection Stopped: tcp://xx.xx.xx.xx:59625 | org.apache.activemq.broker.TransportConnection | ActiveMQ BrokerService[localhost] Task-478
> 2014-08-19 15:49:59,264 | DEBUG | Connection Stopped: tcp://xx.xx.xx.xx:59607 | org.apache.activemq.broker.TransportConnection | ActiveMQ BrokerService[localhost] Task-487
> 2014-08-19 15:49:58,492 | DEBUG | localhost removing consumer: ID:hostname-58095-1408405246656-1:10:114166:1 for destination: queue://queueName | org.apache.activemq.broker.region.AbstractRegion | ActiveMQ BrokerService[localhost] Task-478
> 2014-08-19 15:49:58,493 | DEBUG | queue://queueName remove sub: QueueSubscription: consumer=ID:hostname-58095-1408405246656-1:10:114166:1, destinations=1, dispatched=1, delivered=1, pending=0, lastDeliveredSeqId: 0, dequeues: 184, dispatched: 187, infligh: 3 | org.apache.activemq.broker.region.Queue | ActiveMQ BrokerService[localhost] Task-478
> 2014-08-19 15:49:58,604 | DEBUG | localhost removing consumer: ID:hostname-58095-1408405246656-1:1:114032:1 for destination: queue://queueName | org.apache.activemq.broker.region.AbstractRegion | ActiveMQ BrokerService[localhost] Task-487
> 2014-08-19 15:49:58,864 | TRACE | ID:hostname-58095-1408405246656-1:1:114032:1 failed to dispatch: ID:hostname-58095-1408405246656-1:8:114134:1:1 - queue://queueName, dispatched: 1, inflight: 1 | org.apache.activemq.broker.region.PrefetchSubscription | ActiveMQ BrokerService[localhost] Task-478
> 2014-08-19 15:49:58,966 | TRACE | Subscription full QueueSubscription: consumer=ID:hostname-58095-1408405246656-1:1:114032:1, destinations=1, dispatched=1, delivered=1, pending=0 | org.apache.activemq.broker.retgion.Queue | ActiveMQ BrokerService[localhost] Task-476
> 2014-08-19 15:49:58,978 | TRACE | Subscription full QueueSubscription: consumer=ID:hostname-58095-1408405246656-1:1:114032:1, destinations=1, dispatched=1, delivered=1, pending=0 | org.apache.activemq.broker.retgion.Queue | ActiveMQ BrokerService[localhost] Task-479
> 2014-08-19 15:49:59,175 | TRACE | Subscription full QueueSubscription: consumer=ID:hostname-58095-1408405246656-1:1:114032:1, destinations=1, dispatched=1, delivered=1, pending=0 | org.apache.activemq.broker.retgion.Queue | ActiveMQ BrokerService[localhost] Task-485
> 2014-08-19 15:49:59,176 | DEBUG | queue://queueName remove sub: QueueSubscription: consumer=ID:hostname-58095-1408405246656-1:1:114032:1, destinations=1, dispatched=1, delivered=1, pending=0, lastDeliveredSeqId: 0, dequeues: 184, dispatched: 185, inflight: 1 | org.apache.activemq.broker.region.Queue | ActiveMQ BrokerService[localhost] task-487
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)