CAT訊息丟失問題排查Sorry, the message is not there. It could be missing or archived.
當點選CAT的檢視LogViews時出現Sorry, the message is not there. It could be missing or archived.
這時候出現這種問題會一頭霧水，去github上檢視貌似也沒有給出明確答覆。
這裡根據自己的猜想以及原始碼角度的檢視來定位問題。
首先諮詢CAT維護相關人員得到一個非常重要的資訊就是訊息編號中的小時數 不同
專案名-ac13bd78-430207-91
專案名-ac13bd78-430208-91
第二段代表的是IP，第三段代表小時數，第四段代表當前自增數
舉例:
從LogViews中的訊息編號列表中發現當前小時如果屬於430207的話,是可以開啟的,非430207的話就是訊息丟失。
然後從CAT的state報表中發現有一列訊息丟失資料:
兩臺機器時鐘不準導致訊息儲存丟失這個場景用於Pigeon，服務端id是由客戶端產生，客戶端和服務端時鐘差2小時，會導致儲存丟失
猜想這一列是不是統計了我剛好訊息丟失的資料。
有了這些線索，我們開始假設和驗證！
從客戶端編號的訊息編號生成開始入手。
我的客戶端版本是 2.0
原始碼檢視
- 傳送訊息的時候會判斷該訊息是否是EVENT訊息,如果有則放入m_atomicTrees物件中
TcpSocketSender.java
public void send(MessageTree tree) {
if (isAtomicMessage(tree)) {
boolean result = m_atomicTrees.offer(tree, m_manager.getSample());
if (!result) {
logQueueFullInfo(tree);
}
} else {
boolean result = m_queue.offer(tree, m_manager.getSample());
if (!result) {
logQueueFullInfo(tree);
}
}
}
- 一旦放入m_atomicTrees物件時,則會被一個單獨監控的執行緒檢測到
public class MergeAtomicTask implements Task {
@Override
public String getName() {
return "merge-atomic-task";
}
@Override
public void run() {
while (true) {
// 時刻監控這個佇列,一旦有並且是當前小時的訊息則會滿足
if (shouldMerge(m_atomicTrees)) {
MessageTree tree = mergeTree(m_atomicTrees);
boolean result = m_queue.offer(tree);
if (!result) {
logQueueFullInfo(tree);
}
} else {
try {
Thread.sleep(5);
} catch (InterruptedException e) {
break;
}
}
}
}
@Override
public void shutdown() {
}
}
mergeTree這個方法有點重要,其實就是將當前的訊息進行合併，為什麼需要合併？
我猜的話應該是在同一個訊息樹中，每條訊息都對應了一個訊息編號，但是對於訊息樹的編號來說只要第一條訊息的訊息編號就能夠定位到，而第二條往後走的訊息這個編號根本就沒用了,但是不想浪費了，放入訊息編號佇列中，為下一條訊息樹的編號生成所用。
private MessageTree mergeTree(MessageQueue trees) {
int max = MAX_CHILD_NUMBER;
DefaultTransaction t = new DefaultTransaction("_CatMergeTree", "_CatMergeTree", null);
// 先獲取訊息樹中的第一條訊息
MessageTree first = trees.poll();
t.setStatus(Transaction.SUCCESS);
t.setCompleted(true);
t.addChild(first.getMessage());
t.setTimestamp(first.getMessage().getTimestamp());
long lastTimestamp = 0;
long lastDuration = 0;
while (max >= 0) {
// 注意這裡是從第二條開始
MessageTree tree = trees.poll();
if (tree == null) {
t.setDurationInMillis(lastTimestamp - t.getTimestamp() + lastDuration);
break;
}
lastTimestamp = tree.getMessage().getTimestamp();
if (tree.getMessage() instanceof DefaultTransaction) {
lastDuration = ((DefaultTransaction) tree.getMessage()).getDurationInMillis();
} else {
lastDuration = 0;
}
t.addChild(tree.getMessage());
// 這裡非常關鍵，會將本次產生的id編號重新放入生成的佇列中。
m_factory.reuse(tree.getMessageId());
max--;
}
((DefaultMessageTree) first).setMessage(t);
return first;
}
// D:\lib\maven\com\dianping\cat\cat-client\2.0.0\cat-client-2.0.0-sources.jar!\com\dianping\cat\message\internal\MessageIdFactory.java
// m_factory.reuse(tree.getMessageId()); 對應的實現
public void reuse(String id) {
m_reusedIds.offer(id);
}
接下來我們只要看它是如何拿id的
MessageIdFactory.java
public String getNextId() {
// 先從佇列裡面拿到,這裡和上面生成的相關,如果有直接返回。
String id = m_reusedIds.poll();
if (id != null) {
return id;
} else {
long timestamp = getTimestamp();
if (timestamp != m_timestamp) {
m_index = new AtomicInteger(0);
m_timestamp = timestamp;
}
int index = m_index.getAndIncrement();
StringBuilder sb = new StringBuilder(m_domain.length() + 32);
sb.append(m_domain);
sb.append('-');
sb.append(m_ipAddress);
sb.append('-');
sb.append(timestamp);
sb.append('-');
sb.append(index);
return sb.toString();
}
}
這裡就會出現一個小問題,如果當前小時的id沒有拿完，下一個小時來拿id的時候發現還有，則會從佇列裡面繼續獲取生成的id編號，生成的訊息樹傳送到服務端，但問題在於，該編號卻是上個小時殘留的。
這時候服務端是以小時為key儲存的,儲存的時候會發現這個編號是上一個小時的,則會直接丟棄。從state中的
兩臺機器時鐘不準導致訊息儲存丟失 | 這個場景用於Pigeon，服務端id是由客戶端產生，客戶端和服務端時鐘差2小時，會導致儲存丟失
中檢視到!
這部分的原始碼在 :TcpSocketReceiver.MessageDecoder.decode()
中體現出來，最終的實現類是RealtimeConsumer.consume
方法
public void consume(MessageTree tree) {
long timestamp = tree.getMessage().getTimestamp();
Period period = m_periodManager.findPeriod(timestamp);
if (period != null) {
// 將訊息樹交給桶處理 , 然後這裡會放到佇列然後交給另一個PeriodTask執行緒去處理
period.distribute(tree);
} else {
m_serverStateManager.addNetworkTimeError(1);
}
}
PeriodTask.run -> AbstractMessageAnalyzer.analyze ->DumpAnalyzer.process -> processWithStorage 處理
DumpAnalyzer.java - 關鍵程式碼
public void process(MessageTree tree) {
try {
// 根據訊息編號做解析
MessageId messageId = MessageId.parse(tree.getMessageId());
if (!shouldDiscard(messageId)) {
// 這裡會獲取訊息編號的第三段作為引數messageId.getHour()
processWithStorage(tree, messageId, messageId.getHour());
}
} catch (Exception ignored) {
}
}
private void processWithStorage(MessageTree tree, MessageId messageId, int hour) {
// 這個桶是以當前小時為單位 也就是訊息編號的第三段
MessageDumper dumper = m_dumperManager.find(hour);
tree.setFormatMessageId(messageId);
// 這裡根據訊息編號發現訊息編號匹配不到
if (dumper != null) {
dumper.process(tree);
} else {
// 然後state那裡就會多一條資料
m_serverStateManager.addPigeonTimeError(1);
}
}
ServerStatistic.Statistic.m_pigeonTimeError
但這個時候是誤導了使用者，實際上是訊息佇列中殘留了上個小時的訊息生成的編號導致的。
解決方案:
客戶端升級到3.0吧。它已經把佇列去掉了,每次獲取當前時間戳，來生成編號。