一、背景

最近在預發布環境上遇到一個特別詭異的問題，事情大概是這樣的：

設備在生產時需要走一個注冊的過程，里面涉及到和服務端進行 TCP 通信獲取配置文件、發送密鑰等操作，但是生產進度會卡在70%。

流程如下圖所示。

大家不用細看里面的原理，只用看 D4 階段和 D5 階段即可。

數據通信方式：TCP。

圖片

配置文件長這樣，key=value 形式存儲。

name=rabbit
B2=asdf21
...

當配置文件中的 name 字段為 rabbit 時，設備正常生產，當配置文件中的 name 字段為 rabbit-TD 時，設備就無法生產成功，生產進度會卡在 70%。

從現象來看，不確定是設備端沒有執行 D5 階段，還是服務端沒有處理成功處理 D5 階段。

二、排查過程

2.1、檢查代碼

檢查下設備端和服務端的代碼，有沒有對 name 這個字段的長度做一些限制。

結論：設備端和服務端并沒有對配置文件的字段長度做限制。

2.2、查看服務端日志

排查下服務端的日志，發現只有 D4 階段的業務日志打印，D5 階段的日志沒有。

初步結論：設備端沒有發送 D5 階段的數據包。

2.3、服務端抓包

思路：抓個包看下服務端有沒有收到 D5 階段的數據包。

在服務端通過 microsoft network monitor 抓包工具抓包，然后將抓包文件放到 wireshark 中排查。

下圖是設備端和服務端的 TCP 通信數據。

圖片

可以看到設備向服務端發送了配置文件（D4階段），服務端發送了一個 ACK 響應。

在TCP（傳輸控制協議）通信中，當客戶端發送一條TCP消息給服務端時，服務端通常會發送一個ACK（確認）響應來表明它已經成功接收到了這條消息。這是基于TCP的可靠傳輸機制，確保數據能夠正確無誤地從發送方傳輸到接收方。

TCP使用序列號和確認號來實現可靠傳輸。發送方會為每個發送的字節分配一個序列號，接收方在收到數據后會發送一個ACK確認，確認號表示接收方期望接收的下一個字節的序列號。如果發送方在一定時間內沒有收到ACK確認，它會重新發送數據。（來自 AI）

初步結論：服務端發送了 D4 階段的 ACK 響應。設備端沒有發送 D5 階段的數據包

注意：這個結論在后面的排查過程中被推翻。

2.4、設備端抓包

思路：抓個包看下服務端有沒有發送 D5 階段的數據包。通過如下命令在設備端抓個包：

#tcpdump -i fetho host 192.168.1.253

抓到的數據包如下所示：

圖片

通過上圖的抓包結果可以看到最后一個階段是 D4 和 D5，它倆其實是將數據包合并在一起發送的（這個是我后來才發現的，也是 1024 卡 Bug 產生的源頭）

也就是說 D4 和 D5 其實是一個階段，并沒有分開發。

然后設備端一直在等待服務端返回配置文件（P6 階段）。

初步結論：設備端執行了 D5 階段，服務端沒有執行 P6 階段，服務端有問題。

2.5、再查服務端的數據包

這就尷尬了，設備端明明執行了 D5 階段，但是服務端看起來沒有收到 D5 的數據包。

重新再看下最后一條數據包，報文內容如下圖所示：

圖片

打開 D4 階段的數據報文，可以看到數據里面是包含有 D4 階段的配置文件內容以及D5階段的文件內容，當時我看到這個報文是懵的：

我看之前的接口文檔上寫的是 D4 和 D5 階段分開發送數據？怎么又合在一起發了？

原因：設備端將 D4和D5 的數據包連續寫到 socket 中的。

初步結論：服務端沒有正確處理 D4 和 D5 合體的數據包。

那怎么辦？只能在服務端多加點日志打印看看 D5 的數據包為什么沒有正確處理呢。

2.6、分析數據包

3.6.1 name=rabbit 時的報文（可正常生產）

每個階段發送一次報文都是按照這樣的格式進行發送：0x1234abcd, length, type, data。

• 0x1234abcd : 起始數據
• lenght: 業務數據長度
• type: 請求類型
• data：業務數據

當配置文件中的 name 字段為 rabbit 時，報文D4 和 D5 合體后的報文內容如下：

圖片

說明：

• 指定的業務數據的長度的值必須和后面的業務數據報文的長度相等（比如D4階段的配置文件的數據，D5 階段的密鑰數據的長度），否則會執行報錯，這也是導致 D5 階段未正確執行的根本原因。
• D4 階段的配置文件的數據的長度為 0x00 0x00 0x03 0xF4 ，轉成十進制就是 1011。
• 服務端在讀取 D4 階段報文時，先讀取 4 字節的配置文件數據長度length。然后讀取1 字節的請求類型type，最后再只讀取 1011 字節的數據data，如果業務數據的長度不等于 1011 就會報錯！
• D4階段總共讀取了 1016 字節數據。然后執行 D4 階段的邏輯。
• 接著讀取 D5 階段的 4字節的報文起始數據，然后是 4 字節的業務數據的長度（十六進制 0x00 0x00 0x01 0x00 轉成十進制是 256），這里總共讀取了 1024 字節的數據，剛剛達到了服務端讀取數據的最大長度1024，就會分成下一次讀取。如下圖所示，完整讀取了業務數據的長度。

圖片

• 然后讀取 1字節的請求類型數據，最后是 256 字節的密鑰數據。

3.6.2 name=rabbit-TD 時的報文（不能正常生產）

當配置文件中的 name 字段為 rabbit-TD 時，報文 D4 和 D5 合體后的報文內容如下：

圖片

說明：

• D4 階段的配置文件的數據的長度lenth為 0x00 0x00 0x03 0xF6 ，轉成十進制就是 1014。
• 服務端在讀取 D4 階段報文時，先讀取 4 字節的配置文件數據長度，然后讀取1 字節的請求類型，最后再只讀取 1014 字節的數據，這里總共讀取了 1019 字節數據。然后執行 D4 階段的邏輯。這前面的步驟都沒有問題。
• 接著讀取 D5 階段的 4字節的報文起始數據，已經讀取了 1023 字節的數據。
• 再讀業務數據的長度 lenth，先讀取了 1字節，剛好達到服務端讀取數據的最大長度 1024，分成下一次讀取。問題就出現在這里，業務數據的長度被分開了！

日志的內容如下：

圖片

• 下一次讀取時，會直接讀 4 個字節的數據，作為讀取業務數據的長度，這里產生了錯位，因業務數據的長度length已經被讀取了一個字節，就只能往后讀取 4 個字節。
• 如下圖所示：本來 D5 階段的業務數據的長度應該是 256 字節，但是因為錯位往后讀取了一位，把請求類型type的 1 個字節讀取了，最后就是 0x00,0x01,0x00,0x02，轉成十進制就是 65538，但是 D5 階段的業務數據只有 256 字節。這就導致傳的業務數據的長度和傳的業務數據報文長度不一致，所以服務端解析的 D5 的數據報文有問題。如下圖所示：

圖片

日志內容如下：

圖片

• 結合上面的說明，來一張完整的報文數據圖：

2.7、真相大白

因讀取的數據報文達到1024 字節時，將業務數據的長度這四個字節做了切割，前面1024字節包含長度字段的第一個字節，長度字段的后面3個字節和請求類型的 1個字節組成了長度字段的 4 個字節，也就是錯位多讀取了后面一個字節的內容，最后算出來長度的值為 65538，不等于后面的業務數據的 256 字節，導致服務端的程序報錯，所以后續代碼就沒有執行了。

三、解決方案

3.1、方案一

原因就是前面讀取的 length 的 1 個字節沒有和后續讀取的 length 的三個字節合成長度字段 length 的值，那么只要保證第二次讀取長度字段length的時候把之前的 1 個字節拿到即可。

3.2、方案二

還有一個卡 Bug 的方案：將 D4 階段的配置文件增加一點內容，保證配置文件的內容 = 1014 + 1 =1015 即可，或大于等于 1014+5 = 1019，目的就是把長度字段完整的四個字節卡到 1024 后面，或者把起始數據的四個字節也卡在 1024 后面。

驗證了兩種情況：name 為 Rabbit-TDDDDDDD 和 Rabbit-TDD 是正常生產的。下面是 Rabbit-TDD 的情況，正好將 D4 的數據 + D5 的起始數據卡滿了 1024 字節。

如下圖所示：

• 左邊是出 Rabbit-TD 的日志，系統報錯。1023-4-5=1024 或者這樣算 1014+5+5=1024。
• 右邊是 Rabbit-TDD的日志，右邊正常執行。1024-4+4=1024 或者這樣算 1015+5+4=1024。

圖片

再來給大家算一遍如何卡 Bug 的，系統能正常運行。

1024 字節 = 1015（配置文件報文內容） + 4（配置文件報文長度） + 1（請求類型） + 4（D5報文起始數據）。

或

1024 字節 = 1019（配置文件報文內容） + 4（配置文件報文長度） + 1（請求類型）= 1024 字節。

還有兩個疑問：

- D4 階段的起始數據為啥沒有算到 1024 字節中，這里我也沒弄懂 Socket的數據是怎么分開、合并發送的。

- 服務端為什么是讀取 1024 字節就會分成下次讀取？技術棧是 mina 框架，出問題的是 windows server 2003，而win10上沒重現這個問題。