[ARTEMIS-3260] Already consumed messages are redelivered after server restart (possible Journal corruption)

• Type: Bug
• Status: Open
• Priority: Blocker
• Resolution: Unresolved
• Affects Version/s: 2.17.0
• Component/s: AMQP, Broker

Environment

Embedded Apache Artemis 2.17.0
Windows Server 2016 Standard (10.0.14393)
Java(TM) SE Runtime Environment (build 1.8.0_152-b16)
Java HotSpot(TM) 64-Bit Server VM (build 25.152-b16, mixed mode)

• Assignee: Unassigned
• Reporter: Christian Danner
• Created: 22/Apr/21 19:41
• Updated: 19/Sep/22 22:44

Description

After upgrading from Artemis 2.15.0 to 2.17.0 we are experiencing situations (non-deterministic but quite regular) where the embedded Apache Artemis instance re-delivers messages to a client again after a server restart.

Those messages were already processed successfully before restart and the web console shows a message count of 0 prior to restarting the process.

It is also important to note once those stuck messages (which seemingly appear from out of nowhere) have been reprocessed newly added messages are processed just fine - so what we are seeing is the following:

1. At some point in time messages A,B,C were routed to Queue Q and successfully consumed
2. Q is empty (web console)
3. perform broker restart
4. client consumes A,B,C from Q again
5. Q is empty (web console)
6. another client sends X,Y,Z to Q
7. client consumes X,Y,Z
8. Q is empty (web console)
9. perform broker restart
10. client consumes A,B,C from Q again!

This happens again and again on each boker restart up to a point where the broker finally manages to recover from this situation by detecting an invalid (negative) address size as indicated by the following log output:

2021-04-22 21:04:51.897 WARN org.apache.activemq.artemis.core.paging.impl.PagingStoreImpl.addSize(PagingStoreImpl.java:753) [Thread-1 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@26bb92e2)]

[ARTEMIS] AMQ222214: Destination incoming.message has an inconsistent and negative address size=-3,379.

2021-04-22 21:04:51.897 WARN org.apache.activemq.artemis.core.paging.impl.PagingStoreImpl.addSize(PagingStoreImpl.java:753) [Thread-1 (ActiveMQ-server-org.apache.activemq.artemis.core.server.impl.ActiveMQServerImpl$6@26bb92e2)]

[ARTEMIS] AMQ222214: Destination incoming.message has an inconsistent and negative address size=-3,451.

 

The full log file of such a situation (where the broker managed to recover) is attached together with the broker.xml file that we use as a template to configure the embedded instance programmatically.

The broker runs embedded with the client which consumes messages via AMQP using the Apache QPID library (JMS2.0 - v0.57.0) - there is only a single Thread ever consuming from a queue and we use transactions to explicitly commit or rollback received messages with prefetch disabled (jms.prefetchPolicy.all=0)

Further investigation / debugging has shown that when messages are redelivered the above log outputs concerning the negative address size are absent and the reason is that the value returned by messageReference.getMessageMemoryEstimate() is different for the exact same message in line 1022 of class org.apache.activemq.artemis.core.server.impl.QueueImpl.

This difference stems from a different value being calculated in AMQPStandardMessage class (getMemoryEstimate()) and the difference is equal to the value returned by unmarshalledApplicationPropertiesMemoryEstimateFromData() so I assume that the applicationProperties are sometimes not being considered (I still have to verify this).

I can also provide the complete broker journal for such a situation which we currently use for debugging if this helps to analyze the issue (approx. ~25MB of files, compressed ~100kB)