Details
Major 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;
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
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.