[AMQ-1983] Async error occurred - Slave broker out of sync with master

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 5.2.0
• Fix Version/s: 5.2.0
• Component/s: Broker

Environment

java version "1.6.0_07"
Client is a JBoss 4.2.3.GA cluster using the ActiveMQ resource adapter (from RC2)
ActiveMQ 5.3.0 rev 706043 in pure master/slave setup

• Assignee: Gary Tully
• Reporter: Hans Bausewein
• Created: 19/Oct/08 18:05
• Updated: 10/Nov/08 17:53
• Resolved: 28/Oct/08 12:09

Description

I have tried to reduce the real-life problem to something smaller. See activemqjee-0.0.8.tar.gz

It's a MDB that forwards a message to another queue.

What I did:

• send some messages to queue.A (I did 10 at a time, using the webconsole setting Persistent Delivery)
• the MDB sends each message to queue.B
• if a reply queue was set in the message, the MDB sends a reply

On queue.B is an MDB that just received and logs the message.

Logged on the master:

2008-10-19 18:39:54,114 [127.0.0.1:43972] DEBUG AMQMessageStore                - Journalled transacted message add for:
   ID:selten.cluster-40744-1224434310420-0:2:4:1:1, at: offset = 90045, file = 1, size = 429, type = 1
......
2008-10-19 18:39:54,278 [127.0.0.1:43972] DEBUG AMQMessageStore                - Transacted message add commit for:
   ID:selten.cluster-40744-1224434310420-0:2:4:1:1, at: offset = 90045, file = 1, size = 429, type = 1
......
2008-10-19 18:39:54,305 [127.0.0.1:43962] ERROR MasterBroker                   - Slave Failed
javax.jms.JMSException: Unmatched acknowledege: MessageAck {commandId = 1031, responseRequired = true, ackType = 2, 
  consumerId = ID:selten.cluster-40744-1224434310420-0:0:-1:2, firstMessageId = 
ID:selten.cluster-40744-1224434310420-0:2:4:1:1, lastMessageId = ID:selten.cluster-40744-1224434310420-0:2:4:1:1, 
  destination = queue://queue.B, 
transactionId = XID:131075:312d2d32613062356562303a613535653a34386662363236643a313135:2d32613062356562303a613535653a34386662363236643a313136,
 messageCount = 1}; Could not find Message-ID ID:selten.cluster-40744-1224434310420-0:2:4:1:1 in dispatched-list (start of ack)
        at org.apache.activemq.broker.region.PrefetchSubscription.assertAckMatchesDispatched(PrefetchSubscription.java:438)
        at org.apache.activemq.broker.region.PrefetchSubscription.acknowledge(PrefetchSubscription.java:188)
        at org.apache.activemq.broker.region.AbstractRegion.acknowledge(AbstractRegion.java:373)
        at org.apache.activemq.broker.region.RegionBroker.acknowledge(RegionBroker.java:462)

Logged on the slave:

2008-10-19 18:39:54,112 [.cluster#1] DEBUG AMQMessageStore                - Journalled transacted message add for: ID:selten.cluster-40744-1224434310420-0:2:4:1:1, at: offset = 90045, file = 1, size = 429, type = 1
......
2008-10-19 18:39:54,241 [.cluster#1] DEBUG AMQMessageStore                - Transacted message add commit for: ID:selten.cluster-40744-1224434310420-0:2:4:1:1, at: offset = 90045, file = 1, size = 429, type = 1
......
2008-10-19 18:39:54,288 [.cluster#1] ERROR Service                        - Async error occurred: javax.jms.JMSException: Slave broker out of sync with master: 
  Dispatched message (ID:selten.cluster-40744-1224434310420-0:2:4:1:1) was not in the pending list for queue.B
  javax.jms.JMSException: Slave broker out of sync with master: Dispatched message 
(ID:selten.cluster-40744-1224434310420-0:2:4:1:1) was not in the pending list for queue.B
        at org.apache.activemq.broker.region.PrefetchSubscription.processMessageDispatchNotification(PrefetchSubscription.java:175)
        at org.apache.activemq.broker.region.AbstractRegion.processDispatchNotification(AbstractRegion.java:414)
        at org.apache.activemq.broker.region.RegionBroker.processDispatchNotification(RegionBroker.java:585)

I could not consistently reproduce it with a single JBoss server running. I've sent a few 100 messages without any problem.

I've tested both 5.2.0-RC2 and 5.3.0-SNAPSHOT (rev 706043).