You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@activemq.apache.org by "Andy Hanton (JIRA)" <ji...@apache.org> on 2014/08/19 23:51:19 UTC
[jira] [Created] (AMQ-5324) JMSXDeliveryCount incremented
unexpectedly after EOFException
Andy Hanton created AMQ-5324:
--------------------------------
Summary: 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.2#6252)