前天發完版本好不容易休息一下，又遇到一個問題，項目組反饋說RocketMQ的一個消費組一條消息，消費了兩次，但兩者之間的間隔超過了10個小時，現象如下圖所示：

這是為什么呢?兩者之間相差了差不多10個多小時，是不是這條消息重復消費了16次，但從日志中并沒有打印出16次消息題，只打印了兩條消息，從日志角度來看應該不是重復消費了16次。

本著不輕易相信日志的原則，我覺得應該去RocketMQ服務器上看看這條消息存儲的重試次數，從而推斷出消息是否消費失敗而進行消費重試，正好項目組也提供了消息的Key，根據消息key、發送主題名稱去查找消息，只能查詢到一條消息：

說明發送端確實只發送了一條消息。

那個時候服務集群并沒有發現什么異常，消費者沒有重啟、隊列也沒發生重平衡，不符合RocketMQ會重復推送消息給客戶端的場景，那基本就可以斷定是消息消費失敗重啟引起的，但RocketMQ消息消費重試重試延遲是采取間隔的，往往第一次重試只需10秒就會發生重試，不應該是10個小時?

為此，我特意根據Key分別查找了主題SCHEDULE_TOPIC_XXXX與%RETRY%重試主題，發現這個key也只有一條消息，說明這還僅僅是第一次重試，如下圖：

但從這里可以看到消息寫入到SCHEDULE_TOPIC_XXXX的時間為2022-05-27 22:26:20，然后過了10s就通過調度機制進入到重試主題，并開始被消費，故進行了第一次重試。

擴展機制知識：RocketMQ并發消費的消費者，在客戶端消費失敗后會向服務端發送ACK，根據重試次數進入到SCHEDULE_TOPIC_XXXX主題不同的隊列中，每一個隊列代表的延遲時間不一樣，經過一定延遲時間后再次調度到消費組的重試主題，被消費者再次消費，實現時間間隔的重試，提高重試成功率。

那為什么第一次消費是12點51分，為什么這么久才進入到Broker的SCHEDULE_TOPIC_XXXX呢?

這個就是問題的關鍵所在，這個細節我平時也沒關注，故接下來得分析這段代碼，代碼具體定義在ConsumeMessageConcurrentlyService的processConsumeResult方法中。

原來，如果客戶端消費失敗后向Broker發生ACK失敗后，會加入到msgBack失敗隊列中，并重新提交到消費者這邊消費，并且這條消息的位點不會提交，因為有關鍵代碼：

consumeRequest.getMsgs().removeAll(msgBackFailed);

long offset = consumeRequest.getProcessQueue().removeMessage(consumeRequest.getMsgs());
if (offset >= 0 && !consumeRequest.getProcessQueue().isDropped()) {
   this.defaultMQPushConsumerImpl.getOffsetStore().updateOffset(consumeRequest.getMessageQueue(), offset, true);
}

RocketMQ消費位點采取最小位點提交，只要消息存在于本地處理隊列，位點就不會提交，從而會觸發消息積壓。但尷尬的是這個主題平時消息量很少，并沒有通過積壓來發現該問題。

根據現象與代碼結合，原因是客戶端一直消費失敗，但向Broker提交ACK一直失敗，直到晚上22:26分才發送成功，從而才觸發重新消費。

那現在的關鍵是為什么會發生ACK會失敗呢?這次比較遺憾，因為項目組使用的是容器，這塊代碼并沒有采集到日志集群，導致無法查看錯誤日志，而且所在的集群是正常的，這個疑問后續等我分析完畢后，再和大家來分享。