Hello, I've observed a somewhat unexpected behavior of message delivery after a recover with the following setup:
- Artemis broker (tested with 2.24.0 and 3.0.0) - JMSConsumer (shared durable) *C* with *ActiveMQJMSConstants.INDIVIDUAL_ACKNOWLEDGE* - JMSProducer (shared durable) *P* - C consumes one message at a time * message is received via *JMSConsumer#receive* * if the handling is successful the message will be acknowledged * if an error occurs *JMSContext#recover* is called to ensure redelivery of the message The Javadoc of *JMSContext*#recover states: > Restarting a session causes it to take the following actions: > > - Stop message delivery > - Mark all messages that might have been delivered but not > acknowledged as "redelivered" > - Restart the delivery sequence including all unacknowledged messages > that had been previously delivered. *Redelivered messages do not have > to be delivered in exactly their original delivery order.* > > The way I understand it is that I first get all messages that have to be redelivered in (a potential) arbitrary order and then new messages that haven't been delivered yet. I've written a testcase to test the redelivery of messages s.t. on each unique message *recover* is called once. For example: - *P* sends messages *M1*, *M2*, and *M3* - *C* will consume one message at a time and calls *JMSContext#recover* upon first sight of *M1*, *M2*, and *M3* The order I would expect messages to arrive is *M1*, *M1*, *M2*, *M2*, *M3*, *M3*, since *C* only consumes one message at a time. However, what I sometimes observe is the following: *M1*, *M1*, *M2*, *M3*, *M2*, *M3* This order occurs randomly and I cannot easily reproduce it (only by running the test hundreds of times). I've also tried to wait before calling *recover* to ensure that the producer already sent all messages before we even recover the first time. In that case I've mostly observed the expected behavior, so it doesn't seem to be an issue of available messages in the queue. My gut feeling is, that there might be a race condition somewhere in the client that prefetches a message before the recover is fully done. I've extracted the following logs when the mixed up order occurs (color coding: M1, M2, M3): 2023-05-26 12:11:33,557 INFO [org.apache.activemq.audit.message] > AMQ601500: User user(amq)@10.5.0.1:45494 sent a message > CoreMessage[messageID=95,durable=true,userID=74849faa-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.subevent,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M1]]@519914725, > context: RoutingContextImpl(Address=events.subevent, routingType=MULTICAST, > PreviousAddress=events.subevent previousRoute:MULTICAST, reusable=true, > version=-2147483626) > 2023-05-26 12:11:33,559 INFO [org.apache.activemq.audit.message] > AMQ601501: User user(amq)@10.5.0.1:45546 is consuming a message from > test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > Reference[95]:RELIABLE:CoreMessage[messageID=95,durable=true,userID=74849faa-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.subevent,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M1]]@519914725 > 2023-05-26 12:11:33,563 INFO [org.apache.activemq.audit.message] > AMQ601759: User user(amq)@10.5.0.1:45546 added acknowledgement of a > message from test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > CoreMessage[messageID=95,durable=true,userID=74849faa-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.subevent,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M1]]@519914725 > to transaction: TransactionImpl [xid=null, txID=88, xid=null, state=ACTIVE, > createTime=1685103093536(Fri May 26 12:11:33 UTC 2023), timeoutSeconds=300, > nr operations = 1]@18da0874 > 2023-05-26 12:11:33,563 INFO [org.apache.activemq.audit.message] > AMQ601500: User user(amq)@10.5.0.1:45494 sent a message > CoreMessage[messageID=96,durable=true,userID=7485b11b-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.users,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M2]]@419565464, > context: RoutingContextImpl(Address=events.users, routingType=MULTICAST, > PreviousAddress=events.users previousRoute:MULTICAST, reusable=true, > version=-2147483624) > 2023-05-26 12:11:33,566 INFO [org.apache.activemq.audit.message] > AMQ601761: User user(amq)@10.5.0.1:45546 rolled back transaction > TransactionImpl [xid=null, txID=88, xid=null, state=ROLLEDBACK, > createTime=1685103093536(Fri May 26 12:11:33 UTC 2023), timeoutSeconds=300, > nr operations = 0]@18da0874 involving > Reference[95]:RELIABLE:CoreMessage[messageID=95,durable=true,userID=74849faa-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.subevent,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M1]]@519914725 > 2023-05-26 12:11:33,568 INFO [org.apache.activemq.audit.message] > AMQ601501: User user(amq)@10.5.0.1:45546 is consuming a message from > test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > Reference[95]:RELIABLE:CoreMessage[messageID=95,durable=true,userID=74849faa-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.subevent,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M1]]@519914725 > 2023-05-26 12:11:33,568 INFO [org.apache.activemq.audit.message] > AMQ601501: User user(amq)@10.5.0.1:45546 is consuming a message from > test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > Reference[96]:RELIABLE:CoreMessage[messageID=96,durable=true,userID=7485b11b-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.users,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M2]]@419565464 > 2023-05-26 12:11:33,570 INFO [org.apache.activemq.audit.message] > AMQ601759: User user(amq)@10.5.0.1:45546 added acknowledgement of a > message from test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > CoreMessage[messageID=95,durable=true,userID=74849faa-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.subevent,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M1]]@519914725 > to transaction: TransactionImpl [xid=null, txID=97, xid=null, state=ACTIVE, > createTime=1685103093563(Fri May 26 12:11:33 UTC 2023), timeoutSeconds=300, > nr operations = 1]@4497eca5 > 2023-05-26 12:11:33,570 INFO [org.apache.activemq.audit.message] > AMQ601500: User user(amq)@10.5.0.1:45494 sent a message > CoreMessage[messageID=98,durable=true,userID=74869b7c-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.groups,size=877,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M3]]@301600413, > context: RoutingContextImpl(Address=events.groups, routingType=MULTICAST, > PreviousAddress=events.groups previousRoute:MULTICAST, reusable=true, > version=-2147483625) > 2023-05-26 12:11:33,574 INFO [org.apache.activemq.audit.message] > AMQ601502: User user(amq)@10.5.0.1:45546 acknowledged message from > test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > CoreMessage[messageID=95,durable=true,userID=74849faa-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.subevent,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M1]]@519914725, > transaction: TransactionImpl [xid=null, txID=97, xid=null, state=COMMITTED, > createTime=1685103093563(Fri May 26 12:11:33 UTC 2023), timeoutSeconds=300, > nr operations = 0]@4497eca5 > 2023-05-26 12:11:33,575 INFO [org.apache.activemq.audit.message] > AMQ601759: User user(amq)@10.5.0.1:45546 added acknowledgement of a > message from test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > CoreMessage[messageID=96,durable=true,userID=7485b11b-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.users,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M2]]@419565464 > to transaction: TransactionImpl [xid=null, txID=99, xid=null, state=ACTIVE, > createTime=1685103093570(Fri May 26 12:11:33 UTC 2023), timeoutSeconds=300, > nr operations = 1]@114f7426 > 2023-05-26 12:11:33,576 INFO [org.apache.activemq.audit.message] > AMQ601501: User user(amq)@10.5.0.1:45546 is consuming a message from > test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > Reference[98]:RELIABLE:CoreMessage[messageID=98,durable=true,userID=74869b7c-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.groups,size=877,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M3]]@301600413 > 2023-05-26 12:11:33,578 INFO [org.apache.activemq.audit.message] > AMQ601761: User user(amq)@10.5.0.1:45546 rolled back transaction > TransactionImpl [xid=null, txID=99, xid=null, state=ROLLEDBACK, > createTime=1685103093570(Fri May 26 12:11:33 UTC 2023), timeoutSeconds=300, > nr operations = 0]@114f7426 involving > Reference[96]:RELIABLE:CoreMessage[messageID=96,durable=true,userID=7485b11b-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.users,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M2]]@419565464 > 2023-05-26 12:11:33,578 INFO [org.apache.activemq.audit.message] > AMQ601501: User user(amq)@10.5.0.1:45546 is consuming a message from > test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > Reference[96]:RELIABLE:CoreMessage[messageID=96,durable=true,userID=7485b11b-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.users,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M2]]@419565464 > 2023-05-26 12:11:33,581 INFO [org.apache.activemq.audit.message] > AMQ601759: User user(amq)@10.5.0.1:45546 added acknowledgement of a > message from test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > CoreMessage[messageID=98,durable=true,userID=74869b7c-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.groups,size=877,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M3]]@301600413 > to transaction: TransactionImpl [xid=null, txID=100, xid=null, > state=ACTIVE, createTime=1685103093575(Fri May 26 12:11:33 UTC 2023), > timeoutSeconds=300, nr operations = 1]@54f892c6 > 2023-05-26 12:11:33,583 INFO [org.apache.activemq.audit.message] > AMQ601761: User user(amq)@10.5.0.1:45546 rolled back transaction > TransactionImpl [xid=null, txID=100, xid=null, state=ROLLEDBACK, > createTime=1685103093575(Fri May 26 12:11:33 UTC 2023), timeoutSeconds=300, > nr operations = 0]@54f892c6 involving > Reference[98]:RELIABLE:CoreMessage[messageID=98,durable=true,userID=74869b7c-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.groups,size=877,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M3]]@301600413 > 2023-05-26 12:11:33,584 INFO [org.apache.activemq.audit.message] > AMQ601501: User user(amq)@10.5.0.1:45546 is consuming a message from > test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > Reference[96]:RELIABLE:CoreMessage[messageID=96,durable=true,userID=7485b11b-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.users,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M2]]@419565464 > 2023-05-26 12:11:33,585 INFO [org.apache.activemq.audit.message] > AMQ601501: User user(amq)@10.5.0.1:45546 is consuming a message from > test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > Reference[98]:RELIABLE:CoreMessage[messageID=98,durable=true,userID=74869b7c-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.groups,size=877,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M3]]@301600413 > 2023-05-26 12:11:33,587 INFO [org.apache.activemq.audit.message] > AMQ601759: User user(amq)@10.5.0.1:45546 added acknowledgement of a > message from test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > CoreMessage[messageID=96,durable=true,userID=7485b11b-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.users,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M2]]@419565464 > to transaction: TransactionImpl [xid=null, txID=101, xid=null, > state=ACTIVE, createTime=1685103093581(Fri May 26 12:11:33 UTC 2023), > timeoutSeconds=300, nr operations = 1]@30b952be > 2023-05-26 12:11:33,588 INFO [org.apache.activemq.audit.message] > AMQ601759: User user(amq)@10.5.0.1:45546 added acknowledgement of a > message from test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > CoreMessage[messageID=98,durable=true,userID=74869b7c-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.groups,size=877,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M3]]@301600413 > to transaction: TransactionImpl [xid=null, txID=102, xid=null, > state=ACTIVE, createTime=1685103093587(Fri May 26 12:11:33 UTC 2023), > timeoutSeconds=300, nr operations = 1]@620746a1 > 2023-05-26 12:11:33,590 INFO [org.apache.activemq.audit.message] > AMQ601502: User user(amq)@10.5.0.1:45546 acknowledged message from > test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > CoreMessage[messageID=96,durable=true,userID=7485b11b-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.users,size=873,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M2]]@419565464, > transaction: TransactionImpl [xid=null, txID=101, xid=null, > state=COMMITTED, createTime=1685103093581(Fri May 26 12:11:33 UTC 2023), > timeoutSeconds=300, nr operations = 0]@30b952be > 2023-05-26 12:11:33,591 INFO [org.apache.activemq.audit.message] > AMQ601502: User user(amq)@10.5.0.1:45546 acknowledged message from > test-4b29335f-ff7d-4eb3-b793-5199ad5d1090: > CoreMessage[messageID=98,durable=true,userID=74869b7c-fbbe-11ed-9ddd-2c6dc1916789,priority=4, > timestamp=Fri May 26 12:11:33 UTC 2023,expiration=Sat May 27 12:11:33 UTC > 2023, durable=true, > address=events.groups,size=877,properties=TypedProperties[messageEncoding=PLAIN,__AMQ_CID=7400c991-fbbe-11ed-9ddd-2c6dc1916789,messageFormat=JSON,_AMQ_ROUTING_TYPE=0,JMSCorrelationID=M3]]@301600413, > transaction: TransactionImpl [xid=null, txID=102, xid=null, > state=COMMITTED, createTime=1685103093587(Fri May 26 12:11:33 UTC 2023), > timeoutSeconds=300, nr operations = 0]@620746a1 Regards, Moritz
