一場 Kafka CRC 異常引發的血案

昔久發表於2024-09-02
Kafka

一、問題概述

客戶的生產環境突然在近期間歇式的收到了Kafka CRC的相關異常，異常內容如下

Record batch for partition skywalking-traces-0 at offset 292107075 is invalid, cause: Record is corrupt (stored crc = 1016021496, compute crc = 1981017560)

報錯沒有規律性，有可能半天都不出現一次，也有可能一小時出現2、3次

而這個報錯會導致Kafka的Consumer hang死，即無法繼續消費後續的訊息，只能手動重啟Consumer才能繼續，是非常嚴厲的報錯，導致生產不可用

簡單解釋一下這個異常的原因，Kafka會在每個Batch的header中儲存持久化下來的訊息體的CRC，所謂CRC可以簡單理解為TCP的checkSum，而後Consumer在收到這條訊息後，將Batch header中儲存的CRC取出來，然後再根據統一的CRC演算法計算收到的訊息體的CRC值，而後拿上這兩個值做一下比對，如果一樣，說明訊息沒有被篡改，如果不一樣，就會扔出CRC異常

由於是公司的重保客戶，又出現如此嚴重的驚天bug，一時間公司的高層領導均高度重視此事，每天晚上的夕會（均是領導）也都要單獨詢問解決進度，一時間，壓力山大

二、分析定位

2.1、問題分析

在公司另外一個專案中（簡稱A客戶，我們當前要處理的簡稱B客戶），這個報錯並不陌生，且報錯的內容一模一樣，那這兩者會不會是同一個bug呢？答案是否定的

  • A客戶：確實會報CRC異常，但穩定復現，只要出現了，不論Consumer重啟多少次，也不論多少個Consumer來消費，均是會報CRC異常（最終定位是A客戶的磁碟出現的壞點，導致資料異常，更換磁碟後，問題消失）
  • B客戶：問題只會出現一次，如果手動重啟Consumer，該問題便會消失，如果換個Consumer來消費，問題也會消失，好像它只是曇花一現，且再也無法復現，如同鬼魅

那這個問題不是常規問題，就比較棘手了

2.2、Kafka自身bug ？

筆者長期活躍在Kafka社群，是Kafka社群的Contributer，且在阿里的公有云工作多年，但這個報錯在之前卻是一次沒有遇到過

在我印象中，CRC錯誤已經好久沒見到了，而後我排查了社群所有CRC有關的issue list，發現只有在0.10之前的低版本中出現過類似異常，而我們的B客戶生產環境使用的是2.8.2，這是整個2版本中的最後一個版本，而Kafka 2.0以後的版本卻很少出現這個異常

而Kafka自身計算CRC的邏輯卻非常簡潔，只有幾十行java程式碼，綜上，筆者認為Kafka自身出bug的機率相對較小，不能把重要精力放在這塊

2.3、報錯傾向分析

接下來我們便對這個異常的報錯傾向開始分析，經過各種排查，它具備以下特質：

  • 間歇性、機率性、不確定性；有時候可能半天都不出現一次，也有可能一小時出現2、3次
  • 無法復現；出現問題的訊息，重新消費，CRC異常會消失
  • B客戶現場有8套環境，現只有一套環境存在此問題，對比其他7套環境，粗略看在磁碟型號、CPU型號等硬體裝置是保持一致的
  • 檢視出問題的Broker，其不具備統一性，也沒有落在同一臺宿主機上
  • 懷疑是記憶體條錯誤，排查對應的日誌沒有發現異常資訊
  • 與作業系統的同學確認，咱們現在雖然使用的是我們自研的OS，但TCP協議這塊卻沒有改動過，使用的是Linux原生的
  • 在家裡的環境模擬網路丟包、錯包的場景，沒有復現CRC異常

至此，好像均一切正常，粗略排查後，沒有發現有價值的線索。因此我們便將重心轉移至“網路”+“磁碟”這兩塊看似不太可能出現問題的基礎能力上

三、網路排查

3.1、埋點

進行網路排查的話，我們就要執行TCP抓包，即執行tcpdump命令，但抓包也不是簡單在機器上執行一個命令那麼簡單，當前的部署環境是3臺Broker、3臺Consumer，異常會暴露在Consumer中，但單臺Consumer可能會與多臺Broker建連

一場 Kafka CRC 異常引發的血案

因此抓包的思路是在3臺Broker上均建立監聽，且在某一臺consumer也建立監聽，而後觀察TCP傳送出去的資料與接收到的資料是否一致

首先在3臺Broker上執行dump命令，由於出現問題的機率不高，可能導致網路dump包非常大，因此在命令中將TCP包拆成500M大小的檔案，且只保留最近的5個檔案，3臺Broker的IP如下：

  • 10.0.0.70
  • 10.0.0.71
  • 10.0.0.72

而3臺Consumer的IP為：

  • 10.0.0.18
  • 10.0.0.19
  • 10.0.0.20

首先在1臺consumer上執行如下命令：

sudo nuhup tcpdump -i vethfe2axxxx -nve host 10.0.0.70 or host 10.0.0.71 or host 10.0.0.72 -w broker_18.pcap -C 500 -W 5 -Z ccadmin &
sudo nuhup tcpdump -i vethfe2axxxx -nve host 10.0.0.70 or host 10.0.0.71 or host 10.0.0.72 -w broker_19.pcap -C 500 -W 5 -Z ccadmin &
sudo nuhup tcpdump -i vethfe2axxxx -nve host 10.0.0.70 or host 10.0.0.71 or host 10.0.0.72 -w broker_20.pcap -C 500 -W 5 -Z ccadmin &

其次在3臺Broker上分別執行如下：

sudo nuhup tcpdump -i xxxxxxxxx1 -nve host 10.0.0.18 -w broker_18.pcap -C 500 -W 5 -Z ccadmin &
sudo nuhup tcpdump -i xxxxxxxxx2 -nve host 10.0.0.19 -w broker_19.pcap -C 500 -W 5 -Z ccadmin &
sudo nuhup tcpdump -i xxxxxxxxx3 -nve host 10.0.0.20 -w broker_20.pcap -C 500 -W 5 -Z ccadmin &

簡單解釋一下命令含義：

  • -i vethfe2axxxx 後面新增的是網路卡名稱
  • -nve host 需要新增的是需要監聽的IP
  • -w broker_18.pcap 會將記錄生成到broker_18.pcap的檔案中
  • -C 500 每隔500M生成一個檔案
  • -W 5 保留最近生成的5個檔案
  • -Z ccadmin 指定使用者名稱

3.2、異常浮現

而後我們在螢幕前等待了漫長的近2個小時後，終於捕獲到了一條異常資訊，因此馬不停蹄地將資料下載下來，進行對照分析。首先看到的便是Wireshark幫助解析生成的前後報文

一場 Kafka CRC 異常引發的血案

報文總長度為2712個位元組，約3K的資料，但我們驚訝地發現，其中有15個位元組的資料出現了偏差

一場 Kafka CRC 異常引發的血案

至此，定位可能就是網路傳輸出現了問題，不過我們還需要做更多的校驗工作。Wireshark工具雖然好用，但卻不是萬能的，它只能解析Kafka的傳輸協議，無法對內容進行校驗與還原

（我們在樣本中隨機取了3個正常互動的訊息進行對比，發現在網路傳送前與傳送後的資料完全一致）

3.3、Kafka協議解析

Kafka的協議分為傳輸協議及儲存協議，筆者對它們相對比較熟悉，因此開始直接對前後傳輸的報文進行了解析，首先是Request

import org.apache.kafka.common.requests.FetchRequest;
import org.apache.kafka.common.requests.RequestHeader;

import javax.xml.bind.DatatypeConverter;
import java.nio.ByteBuffer;

public class MyTest {
    public static void main(String[] args) {

        // 08-30 15:06:40.820028
        String hexString =
            "0e 1f 48 2d 7e 32 06 82 25 e9 a3 d9 08 00 45 00 " +
                "00 ab 3f b3 40 00 40 06 35 ed 62 02 00 55 62 02 " +
                "00 54 eb 2e 23 85 68 57 32 37 b5 08 3f b2 80 18 " +
                "7d 2c c5 4a 00 00 01 01 08 0a b7 d1 e6 5c 26 30 " +
                "b9 11 00 00 00 73 00 01 00 0c 11 85 6f bf 00 15 " +
                "62 72 6f 6b 65 72 2d 31 30 30 32 2d 66 65 74 63 " +
                "68 65 72 2d 30 00 00 00 03 ea 00 00 01 f4 00 00 " +
                "00 01 00 a0 00 00 00 72 52 11 e0 11 85 6f bf 02 " +
                "13 5f 5f 63 6f 6e 73 75 6d 65 72 5f 6f 66 66 73 " +
                "65 74 73 02 00 00 00 15 00 00 00 03 00 00 00 00 " +
                "13 36 67 3a 00 00 00 03 00 00 00 00 00 00 00 00 " +
                "00 10 00 00 00 00 01 01 00";
        // FetchRequestData(clusterId=null, replicaId=1002, maxWaitMs=500, minBytes=1, maxBytes=10485760,
        // isolationLevel=0, sessionId=1917981152, sessionEpoch=293957567,
        // topics=[FetchTopic(topic='__consumer_offsets', partitions=[FetchPartition(partition=21, currentLeaderEpoch=3,
        // fetchOffset=322332474, lastFetchedEpoch=3, logStartOffset=0, partitionMaxBytes=1048576)])], forgottenTopicsData=[], rackId='')



        StringBuilder sb = new StringBuilder();
        char[] charArray = hexString.toCharArray();
        for (char c : charArray) {
            if (c != ' ') {
                sb.append(c);
            }
        }
        hexString = sb.toString();
        byte[] byteArray = DatatypeConverter.parseHexBinary(hexString);
        ByteBuffer byteBuffer = ByteBuffer.wrap(byteArray);
        System.out.println("len is : " + byteBuffer.array().length);
        byteBuffer.get(new byte[66]);
        byteBuffer.getInt();

        RequestHeader header = RequestHeader.parse(byteBuffer);
        System.out.println(header);
        FetchRequest fetchRequest = FetchRequest.parse(byteBuffer, (short) 12);
        System.out.println(fetchRequest);
    }
}

最終輸出如下

len is : 185
RequestHeader(apiKey=FETCH, apiVersion=12, clientId=broker-1002-fetcher-0, correlationId=293957567)
FetchRequestData(clusterId=null, replicaId=1002, maxWaitMs=500, minBytes=1, maxBytes=10485760, isolationLevel=0, sessionId=1917981152, sessionEpoch=293957567, topics=[FetchTopic(topic='__consumer_offsets', partitions=[FetchPartition(partition=21, currentLeaderEpoch=3, fetchOffset=322332474, lastFetchedEpoch=3, logStartOffset=0, partitionMaxBytes=1048576)])], forgottenTopicsData=[], rackId='')

且TCP傳輸前後的內容一致，因此問題沒有出現在Request上

接下來就需要進行Response的二進位制協議解析，程式碼如下

import org.apache.kafka.common.TopicPartition;
import org.apache.kafka.common.record.MemoryRecords;
import org.apache.kafka.common.requests.FetchResponse;
import org.apache.kafka.common.requests.ResponseHeader;

import javax.xml.bind.DatatypeConverter;
import java.nio.ByteBuffer;
import java.util.LinkedHashMap;
import java.util.Map;

public class MyTest2 {
    public static void main(String[] args) {

        08-30 15:06:41.853611
               String hexString =
                   "0e 1f 48 2d 7e 32 06 82 25 e9 a3 d9 08 00 45 00 " +
                       "00 ab 3f b3 40 00 40 06 35 ed 62 02 00 55 62 02 " +
                       "00 54 eb 2e 23 85 68 57 32 37 b5 08 3f b2 80 18 " +
                       "7d 2c c5 4a 00 00 01 01 08 0a b7 d1 e6 5c 26 30 " +
                       "b9 11 00 00 00 f9 11 85 6f c1 00 00 00 00 00 00 " +
                       "00 72 52 11 e0 02 13 5f 5f 63 6f 6e 73 75 6d 65 " +
                       "72 5f 6f 66 66 73 65 74 73 03 00 00 00 03 00 00 " +
                       "00 00 00 00 15 09 0c 9c 00 00 00 00 15 09 0c 9c " +
                       "00 00 00 00 00 00 00 00 00 ff ff ff ff 89 01 " +
        
                       "      00 00 00 00 15 09 0c 9c 00 00 00 7c 00 00 " +
                       "00 03 02 08 16 d8 10 00 00 00 00 00 00 00 00 01 " +
                       "91 a2 1b 8f 3c 00 00 01 91 a2 1b 8f 3c ff ff ff " +
                       "ff ff ff ff ff ff ff 00 00 00 00 00 00 00 01 92 " +
                       "01 00 00 00 56 00 01 00 0b 43 43 4d 2d 65 6e 63 " +
                       "72 79 70 74 00 16 43 53 53 2d 49 49 53 2d 53 69 " +
                       "74 75 61 74 69 6f 6e 51 75 65 72 79 00 00 00 00 " +
                       "30 00 03 00 00 00 00 00 00 00 00 ff ff ff ff 00 " +
                       "00 00 00 01 91 a2 1b 8f 3b 00 " +
        
        
        
                       "      00 00 00 00 15 00 00 00 00 00 00 13 36 67 " +
                       "47 00 00 00 00 13 36 67 47 00 00 00 00 00 00 00 " +
                       "00 00 ff ff ff ff 01 00 00 00 ";


//        String hexString =
//                "0e 1f 48 2d 7e 32 06 82 25 e9 a3 d9 08 00 45 00 " +
//                "00 ab 3f b3 40 00 40 06 35 ed 62 02 00 55 62 02 " +
//                "00 54 eb 2e 23 85 68 57 32 37 b5 08 3f b2 80 18 " +
//                "7d 2c c5 4a 00 00 01 01 08 0a b7 d1 e6 5c 26 30 " +
//                "b9 11 00 00 04 65 11 85 6f c0 00 00 00 00 00 00 " +
//                "00 72 52 11 e0 03 13 5f 5f 63 6f 6e 73 75 6d 65 " +
//                "72 5f 6f 66 66 73 65 74 73 02 00 00 00 15 00 00 " +
//                "00 00 00 00 13 36 67 3b 00 00 00 00 13 36 67 3b " +
//                "00 00 00 00 00 00 00 00 00 ff ff ff ff da 07 " +
//
//                "      00 00 00 00 13 36 67 3b 00 00 03 cd 00 00 " +
//                "00 03 02 5c 37 79 85 00 00 00 00 00 0b 00 00 01 " +
//                "91 a2 1b 8f 3c 00 00 01 91 a2 1b 8f 37 ff ff ff " +
//                "ff ff ff ff ff ff ff 00 00 00 00 00 00 00 0c 96 " +
//                "01 00 00 00 5a 00 01 00 0b 43 43 4d 2d 65 6e 63 " +
//                "72 79 70 74 00 16 43 53 53 2d 49 49 53 2d 53 69 " +
//                "74 75 61 74 69 6f 6e 51 75 65 72 79 00 00 00 00 " +
//                "30 00 03 00 00 00 00 00 00 00 00 ff ff ff ff 00 " +
//                "00 00 00 01 91 a2 1b 8f 3b 00 " +
//
//
//
//                "      00 00 00 00 15 00 00 00 00 00 00 13 36 67 " +
//                "47 00 00 00 00 13 36 67 47 00 00 00 00 00 00 00 " +
//                "00 00 ff ff ff ff 01 00 00 00 ";


        StringBuilder sb = new StringBuilder();
        char[] charArray = hexString.toCharArray();
        for (char c : charArray) {
            if (c != ' ') {
                sb.append(c);
            }
        }
        hexString = sb.toString();
        byte[] byteArray = DatatypeConverter.parseHexBinary(hexString);
        ByteBuffer byteBuffer = ByteBuffer.wrap(byteArray);
        System.out.println("len is : " + byteBuffer.array().length);
        byteBuffer.get(new byte[66]);
        byteBuffer.getInt();


        ResponseHeader responseHeader = ResponseHeader.parse(byteBuffer, (short) 0);
        System.out.println("responseHeader is " + responseHeader);
        FetchResponse<MemoryRecords> fetchResponse = FetchResponse.parse(byteBuffer, (short) 11);
        System.out.println(fetchResponse);
        LinkedHashMap<TopicPartition, FetchResponse.PartitionData<MemoryRecords>> map = fetchResponse.responseData();
        System.out.println("map size is : " + map.size());
        System.out.println("map is : " + map);
        for (Map.Entry<TopicPartition, FetchResponse.PartitionData<MemoryRecords>> entry : map.entrySet()) {
            System.out.println();
            System.out.println();
            System.out.println();
            System.out.println();
            System.out.println("TP is : " + entry.getKey());
            FetchResponse.PartitionData<MemoryRecords> value = entry.getValue();
            MemoryRecords records = value.records();
            records.batches().forEach(batch -> {
                System.out.println("isValid: " + batch.isValid());
                System.out.println("crc : " + batch.checksum());
                System.out.println("baseOffset : " + batch.baseOffset());
            });
        }
    }
}

其中關鍵的部分是檢視2個CRC的邏輯：

  • 一塊是從協議體中獲取到的，即Broker計算的CRC內容，這個對比傳輸前後均一致
  • 一塊是根據訊息內容動態計算的，訊息傳輸前，動態計算的CRC內容能與自身儲存的對齊，但訊息接收後，動態計算的CRC便發生了偏差

下圖是真實生產業務日誌中爆出的異常

一場 Kafka CRC 異常引發的血案

其中發現計算出來的CRC是2481280076。而後將我們dump下來的二進位制進行協議解碼，執行上述程式碼後發現結果與生產環境的一致

一場 Kafka CRC 異常引發的血案

四、磁碟排查

後續我們對傳送出去的內容與磁碟的內容做了對比，內容一致，因此bug不是因磁碟導致

五、結論

由於出現問題的訊息在TCP傳送前後出現了diff，而正常收到的訊息，在TCP傳送前後均一致，因此

定位為網路出現了問題

網路的同學也認為這個現象不符合預期，已經開始介入了排查

總結：其實根據這些年處理Kafka異常的經驗，這個bug第一時間拿到的時候，就感覺不像是Kafka自己的問題，關鍵是異常報錯在Kafka的Broker端，我們需要不斷提升自證清白的能力

相關文章