[
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)
