一、背景

最近在預(yù)發(fā)布環(huán)境上遇到一個特別詭異的問題，事情大概是這樣的：

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

流程如下圖所示。

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

數(shù)據(jù)通信方式：TCP。

圖片

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

name=rabbit
B2=asdf21
...

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

從現(xiàn)象來看，不確定是設(shè)備端沒有執(zhí)行 D5 階段，還是服務(wù)端沒有處理成功處理 D5 階段。

二、排查過程

2.1、檢查代碼

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

結(jié)論：設(shè)備端和服務(wù)端并沒有對配置文件的字段長度做限制。

2.2、查看服務(wù)端日志

排查下服務(wù)端的日志，發(fā)現(xiàn)只有 D4 階段的業(yè)務(wù)日志打印，D5 階段的日志沒有。

初步結(jié)論：設(shè)備端沒有發(fā)送 D5 階段的數(shù)據(jù)包。

2.3、服務(wù)端抓包

思路：抓個包看下服務(wù)端有沒有收到 D5 階段的數(shù)據(jù)包。

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

下圖是設(shè)備端和服務(wù)端的 TCP 通信數(shù)據(jù)。

圖片

可以看到設(shè)備向服務(wù)端發(fā)送了配置文件（D4階段），服務(wù)端發(fā)送了一個 ACK 響應(yīng)。

在TCP（傳輸控制協(xié)議）通信中，當客戶端發(fā)送一條TCP消息給服務(wù)端時，服務(wù)端通常會發(fā)送一個ACK（確認）響應(yīng)來表明它已經(jīng)成功接收到了這條消息。這是基于TCP的可靠傳輸機制，確保數(shù)據(jù)能夠正確無誤地從發(fā)送方傳輸?shù)浇邮辗健?/p>

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

初步結(jié)論：服務(wù)端發(fā)送了 D4 階段的 ACK 響應(yīng)。設(shè)備端沒有發(fā)送 D5 階段的數(shù)據(jù)包

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

2.4、設(shè)備端抓包

思路：抓個包看下服務(wù)端有沒有發(fā)送 D5 階段的數(shù)據(jù)包。通過如下命令在設(shè)備端抓個包：

#tcpdump -i fetho host 192.168.1.253

抓到的數(shù)據(jù)包如下所示：

圖片

通過上圖的抓包結(jié)果可以看到最后一個階段是 D4 和 D5，它倆其實是將數(shù)據(jù)包合并在一起發(fā)送的（這個是我后來才發(fā)現(xiàn)的，也是 1024 卡 Bug 產(chǎn)生的源頭）

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

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

初步結(jié)論：設(shè)備端執(zhí)行了 D5 階段，服務(wù)端沒有執(zhí)行 P6 階段，服務(wù)端有問題。

2.5、再查服務(wù)端的數(shù)據(jù)包

這就尷尬了，設(shè)備端明明執(zhí)行了 D5 階段，但是服務(wù)端看起來沒有收到 D5 的數(shù)據(jù)包。

重新再看下最后一條數(shù)據(jù)包，報文內(nèi)容如下圖所示：

圖片

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

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

原因：設(shè)備端將 D4和D5 的數(shù)據(jù)包連續(xù)寫到 socket 中的。

初步結(jié)論：服務(wù)端沒有正確處理 D4 和 D5 合體的數(shù)據(jù)包。

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

2.6、分析數(shù)據(jù)包

3.6.1 name=rabbit 時的報文（可正常生產(chǎn)）

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

• 0x1234abcd : 起始數(shù)據(jù)
• lenght: 業(yè)務(wù)數(shù)據(jù)長度
• type: 請求類型
• data：業(yè)務(wù)數(shù)據(jù)

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

圖片

說明：

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

圖片

• 然后讀取 1字節(jié)的請求類型數(shù)據(jù)，最后是 256 字節(jié)的密鑰數(shù)據(jù)。

3.6.2 name=rabbit-TD 時的報文（不能正常生產(chǎn)）

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

圖片

說明：

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

日志的內(nèi)容如下：

圖片

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

圖片

日志內(nèi)容如下：

圖片

• 結(jié)合上面的說明，來一張完整的報文數(shù)據(jù)圖：

2.7、真相大白

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

三、解決方案

3.1、方案一

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

3.2、方案二

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

驗證了兩種情況：name 為 Rabbit-TDDDDDDD 和 Rabbit-TDD 是正常生產(chǎn)的。下面是 Rabbit-TDD 的情況，正好將 D4 的數(shù)據(jù) + D5 的起始數(shù)據(jù)卡滿了 1024 字節(jié)。

如下圖所示：

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

圖片

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

1024 字節(jié) = 1015（配置文件報文內(nèi)容） + 4（配置文件報文長度） + 1（請求類型） + 4（D5報文起始數(shù)據(jù)）。

或

1024 字節(jié) = 1019（配置文件報文內(nèi)容） + 4（配置文件報文長度） + 1（請求類型）= 1024 字節(jié)。

還有兩個疑問：

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

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