You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@activemq.apache.org by "JJ (JIRA)" <ji...@apache.org> on 2018/02/18 14:51:00 UTC
[jira] [Updated] (AMQ-6902) Expected message count (1) differs from
count in dispatched-list (100) & Unexpected ACK received
[ https://issues.apache.org/jira/browse/AMQ-6902?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
JJ updated AMQ-6902:
--------------------
Description:
Following an unexpected server restart the following errors where observed and lead to an apparent loss of messages to the client. (looks related to: AMQ-6622)
AMQ is running as a network broker bridging topics from a private data feed providing client connectivity. The local client topics are persistent.
The chain of events is roughly;
1 - AMQ stops ungracefully due to server issue.
2 - Server restarts & AMQ auto restarts & re-connects to upstream provider.
3 - AMQ buffers messages for all known persistent topics for ~40min
4 - Clients re connect to AMQ and expect to drain down the topics. Several exhibited errors.
Log extracts only;
{code:java}
2018-02-18 12:13:19,442 | WARN | Async error occurred: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 518, responseRequired = false, ackType = 2, consumerId = ID:xs-35265-1518953016334-7:1:-1:1, firstMessageId = null, lastMessageId = ID:xs-35265-1518953016334-4:1:2:1:503, destination = topic://TD_ANG, transactionId = null, messageCount = 1, poisonCause = null}; Expected message count (1) differs from count in dispatched-list (100) | org.apache.activemq.broker.TransportConnection.Service | ActiveMQ Transport: tcp:///172.16.0.2:44808@61618
2018-02-18 12:13:19,443 | WARN | Exception occurred while processing a command: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 518, responseRequired = false, ackType = 2, consumerId = ID:xs-35265-1518953016334-7:1:-1:1, firstMessageId = null, lastMessageId = ID:xs-35265-1518953016334-4:1:2:1:503, destination = topic://TD_ANG, transactionId = null, messageCount = 1, poisonCause = null}; Expected message count (1) differs from count in dispatched-list (100) | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ BrokerService[xs.goth.int] Task-3
2018-02-18 12:20:11,343 | WARN | Async error occurred: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 735, responseRequired = false, ackType = 2, consumerId = ID:xs-35265-1518953016334-7:5:-1:1, firstMessageId = null, lastMessageId = ID:xs-35265-1518953016334-4:1:5:1:323, destination = topic://TRUST_EB, transactionId = null, messageCount = 1, poisonCause = null}; Expected message count (1) differs from count in dispatched-list (100) | org.apache.activemq.broker.TransportConnection.Service | ActiveMQ Transport: tcp:///172.16.0.2:45030@61618
2018-02-18 12:20:11,344 | WARN | Exception occurred while processing a command: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 735, responseRequired = false, ackType = 2, consumerId = ID:xs-35265-1518953016334-7:5:-1:1, firstMessageId = null, lastMessageId = ID:xs-35265-1518953016334-4:1:5:1:323, destination = topic://TRUST_EB, transactionId = null, messageCount = 1, poisonCause = null}; Expected message count (1) differs from count in dispatched-list (100) | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ BrokerService[xs.goth.int] Task-7
2018-02-18 12:20:10,959 | WARN | Exception occurred processing: ACK -> org.apache.activemq.transport.stomp.ProtocolException: Unexpected ACK received for message-id [ID:xs-35265-1518953016334-4:1:5:1:318] | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ Transport: tcp:///172.16.0.2:45030@61618
2018-02-18 12:20:11,053 | WARN | Exception occurred processing: ACK -> org.apache.activemq.transport.stomp.ProtocolException: Unexpected ACK received for message-id [ID:xs-35265-1518953016334-4:1:5:1:319] | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ Transport: tcp:///172.16.0.2:45030@61618
2018-02-18 12:20:11,129 | WARN | Exception occurred processing: ACK -> org.apache.activemq.transport.stomp.ProtocolException: Unexpected ACK received for message-id [ID:xs-35265-1518953016334-4:1:5:1:320] | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ Transport: tcp:///172.16.0.2:45030@61618
{code}
The AMQ Admin console showed the 'Pending Queue Size' as 100+ for the relevant topic and would never drain down to 0. During this time the consumer client was still receiving other messages from the topic.
Nothing was shown in the DLQ.
This is a production environment.
The client consuming the 'TRUST_XX' topic logged the same error but recovered with lots of Unexpected ACK's and duplicated messages, the client consuming the 'TD_ANG' topic was the one which ended up with the 'stuck' messages.
Deleting the persistent subscription from within the AMQ web admin and re-connecting the client resolved the issue.
was:
Following an unexpected server restart the following errors where observed and lead to an apparent loss of messages to the client. (looks related to: [AMQ-6622|https://issues.apache.org/jira/browse/AMQ-6622])
AMQ is running as a network broker bridging topics from a private data feed providing client connectivity. The local client topics are persistent.
The chain of events is roughly;
1 - AMQ stops ungracefully due to server issue.
2 - Server restarts & AMQ auto restarts & re-connects to upstream provider.
3 - AMQ buffers messages for all known persistent topics for ~40min
4 - Clients re connect to AMQ and expect to drain down the topics. Several exhibited errors.
{code:java}
2018-02-18 12:13:19,442 | WARN | Async error occurred: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 518, responseRequired = false, ackType = 2, consumerId = ID:xs-35265-1518953016334-7:1:-1:1, firstMessageId = null, lastMessageId = ID:xs-35265-1518953016334-4:1:2:1:503, destination = topic://TD_ANG, transactionId = null, messageCount = 1, poisonCause = null}; Expected message count (1) differs from count in dispatched-list (100) | org.apache.activemq.broker.TransportConnection.Service | ActiveMQ Transport: tcp:///172.16.0.2:44808@61618
2018-02-18 12:13:19,443 | WARN | Exception occurred while processing a command: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 518, responseRequired = false, ackType = 2, consumerId = ID:xs-35265-1518953016334-7:1:-1:1, firstMessageId = null, lastMessageId = ID:xs-35265-1518953016334-4:1:2:1:503, destination = topic://TD_ANG, transactionId = null, messageCount = 1, poisonCause = null}; Expected message count (1) differs from count in dispatched-list (100) | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ BrokerService[xs.goth.int] Task-3
2018-02-18 12:20:11,343 | WARN | Async error occurred: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 735, responseRequired = false, ackType = 2, consumerId = ID:xs-35265-1518953016334-7:5:-1:1, firstMessageId = null, lastMessageId = ID:xs-35265-1518953016334-4:1:5:1:323, destination = topic://TRUST_EB, transactionId = null, messageCount = 1, poisonCause = null}; Expected message count (1) differs from count in dispatched-list (100) | org.apache.activemq.broker.TransportConnection.Service | ActiveMQ Transport: tcp:///172.16.0.2:45030@61618
2018-02-18 12:20:11,344 | WARN | Exception occurred while processing a command: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 735, responseRequired = false, ackType = 2, consumerId = ID:xs-35265-1518953016334-7:5:-1:1, firstMessageId = null, lastMessageId = ID:xs-35265-1518953016334-4:1:5:1:323, destination = topic://TRUST_EB, transactionId = null, messageCount = 1, poisonCause = null}; Expected message count (1) differs from count in dispatched-list (100) | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ BrokerService[xs.goth.int] Task-7
2018-02-18 12:20:10,959 | WARN | Exception occurred processing: ACK -> org.apache.activemq.transport.stomp.ProtocolException: Unexpected ACK received for message-id [ID:xs-35265-1518953016334-4:1:5:1:318] | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ Transport: tcp:///172.16.0.2:45030@61618
2018-02-18 12:20:11,053 | WARN | Exception occurred processing: ACK -> org.apache.activemq.transport.stomp.ProtocolException: Unexpected ACK received for message-id [ID:xs-35265-1518953016334-4:1:5:1:319] | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ Transport: tcp:///172.16.0.2:45030@61618
2018-02-18 12:20:11,129 | WARN | Exception occurred processing: ACK -> org.apache.activemq.transport.stomp.ProtocolException: Unexpected ACK received for message-id [ID:xs-35265-1518953016334-4:1:5:1:320] | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ Transport: tcp:///172.16.0.2:45030@61618
{code}
The AMQ Admin console showed the 'Pending Queue Size' as 100+ for the relevant topic and would never drain down to 0. During this time the consumer client was still receiving other messages from the topic.
Nothing was shown in the DLQ.
This is a production environment.
The client consuming the 'TRUST_XX' topic logged the same error but recovered with lots of Unexpected ACK's and duplicated messages, the client consuming the 'TD_ANG' topic was the one which ended up with the 'stuck' messages.
Deleting the persistent subscription from within the AMQ web admin and re-connecting the client resolved the issue.
> Expected message count (1) differs from count in dispatched-list (100) & Unexpected ACK received
> ------------------------------------------------------------------------------------------------
>
> Key: AMQ-6902
> URL: https://issues.apache.org/jira/browse/AMQ-6902
> Project: ActiveMQ
> Issue Type: Bug
> Components: Broker, networkbridge, stomp
> Affects Versions: 5.15.2
> Environment: CentOS 6.9 x64
> {code:java}
> Linux xs 4.10.13-1.el6.elrepo.x86_64 #1 SMP Thu Apr 27 12:13:03 EDT 2017 x86_64 x86_64 x86_64 GNU/Linux{code}
> STOP Consumer via;
> {code:java}
> ruby 2.2.3p173 (2015-08-18 revision 51636) [x86_64-linux-gnu]{code}
> {code:java}
> stomp-gem 1.4.3{code}
> Reporter: JJ
> Priority: Major
> Labels: newbie
>
> Following an unexpected server restart the following errors where observed and lead to an apparent loss of messages to the client. (looks related to: AMQ-6622)
> AMQ is running as a network broker bridging topics from a private data feed providing client connectivity. The local client topics are persistent.
> The chain of events is roughly;
> 1 - AMQ stops ungracefully due to server issue.
> 2 - Server restarts & AMQ auto restarts & re-connects to upstream provider.
> 3 - AMQ buffers messages for all known persistent topics for ~40min
> 4 - Clients re connect to AMQ and expect to drain down the topics. Several exhibited errors.
> Log extracts only;
> {code:java}
> 2018-02-18 12:13:19,442 | WARN | Async error occurred: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 518, responseRequired = false, ackType = 2, consumerId = ID:xs-35265-1518953016334-7:1:-1:1, firstMessageId = null, lastMessageId = ID:xs-35265-1518953016334-4:1:2:1:503, destination = topic://TD_ANG, transactionId = null, messageCount = 1, poisonCause = null}; Expected message count (1) differs from count in dispatched-list (100) | org.apache.activemq.broker.TransportConnection.Service | ActiveMQ Transport: tcp:///172.16.0.2:44808@61618
> 2018-02-18 12:13:19,443 | WARN | Exception occurred while processing a command: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 518, responseRequired = false, ackType = 2, consumerId = ID:xs-35265-1518953016334-7:1:-1:1, firstMessageId = null, lastMessageId = ID:xs-35265-1518953016334-4:1:2:1:503, destination = topic://TD_ANG, transactionId = null, messageCount = 1, poisonCause = null}; Expected message count (1) differs from count in dispatched-list (100) | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ BrokerService[xs.goth.int] Task-3
> 2018-02-18 12:20:11,343 | WARN | Async error occurred: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 735, responseRequired = false, ackType = 2, consumerId = ID:xs-35265-1518953016334-7:5:-1:1, firstMessageId = null, lastMessageId = ID:xs-35265-1518953016334-4:1:5:1:323, destination = topic://TRUST_EB, transactionId = null, messageCount = 1, poisonCause = null}; Expected message count (1) differs from count in dispatched-list (100) | org.apache.activemq.broker.TransportConnection.Service | ActiveMQ Transport: tcp:///172.16.0.2:45030@61618
> 2018-02-18 12:20:11,344 | WARN | Exception occurred while processing a command: javax.jms.JMSException: Unmatched acknowledge: MessageAck {commandId = 735, responseRequired = false, ackType = 2, consumerId = ID:xs-35265-1518953016334-7:5:-1:1, firstMessageId = null, lastMessageId = ID:xs-35265-1518953016334-4:1:5:1:323, destination = topic://TRUST_EB, transactionId = null, messageCount = 1, poisonCause = null}; Expected message count (1) differs from count in dispatched-list (100) | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ BrokerService[xs.goth.int] Task-7
> 2018-02-18 12:20:10,959 | WARN | Exception occurred processing: ACK -> org.apache.activemq.transport.stomp.ProtocolException: Unexpected ACK received for message-id [ID:xs-35265-1518953016334-4:1:5:1:318] | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ Transport: tcp:///172.16.0.2:45030@61618
> 2018-02-18 12:20:11,053 | WARN | Exception occurred processing: ACK -> org.apache.activemq.transport.stomp.ProtocolException: Unexpected ACK received for message-id [ID:xs-35265-1518953016334-4:1:5:1:319] | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ Transport: tcp:///172.16.0.2:45030@61618
> 2018-02-18 12:20:11,129 | WARN | Exception occurred processing: ACK -> org.apache.activemq.transport.stomp.ProtocolException: Unexpected ACK received for message-id [ID:xs-35265-1518953016334-4:1:5:1:320] | org.apache.activemq.transport.stomp.ProtocolConverter | ActiveMQ Transport: tcp:///172.16.0.2:45030@61618
> {code}
> The AMQ Admin console showed the 'Pending Queue Size' as 100+ for the relevant topic and would never drain down to 0. During this time the consumer client was still receiving other messages from the topic.
> Nothing was shown in the DLQ.
> This is a production environment.
> The client consuming the 'TRUST_XX' topic logged the same error but recovered with lots of Unexpected ACK's and duplicated messages, the client consuming the 'TD_ANG' topic was the one which ended up with the 'stuck' messages.
> Deleting the persistent subscription from within the AMQ web admin and re-connecting the client resolved the issue.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)