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)
