一、背景

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

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

流程如下圖所示。

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

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

圖片

配置文件長(zhǎng)這樣，key=value 形式存儲(chǔ)。

name=rabbit
B2=asdf21
...

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

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

二、排查過(guò)程

2.1、檢查代碼

檢查下設(shè)備端和服務(wù)端的代碼，有沒(méi)有對(duì) name 這個(gè)字段的長(zhǎng)度做一些限制。

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

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

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

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

2.3、服務(wù)端抓包

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

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

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

圖片

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

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

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

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

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

2.4、設(shè)備端抓包

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

#tcpdump -i fetho host 192.168.1.253

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

圖片

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

也就是說(shuō) D4 和 D5 其實(shí)是一個(gè)階段，并沒(méi)有分開(kāi)發(fā)。

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

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

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

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

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

圖片

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

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

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

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

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

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

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

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

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

當(dāng)配置文件中的 name 字段為 rabbit 時(shí)，報(bào)文D4 和 D5 合體后的報(bào)文內(nèi)容如下：

圖片

說(shuō)明：

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

圖片

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

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

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

圖片

說(shuō)明：

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

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

圖片

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

圖片

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

圖片

• 結(jié)合上面的說(shuō)明，來(lái)一張完整的報(bào)文數(shù)據(jù)圖：

2.7、真相大白

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

三、解決方案

3.1、方案一

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

3.2、方案二

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

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

如下圖所示：

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

圖片

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

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

或

1024 字節(jié) = 1019（配置文件報(bào)文內(nèi)容） + 4（配置文件報(bào)文長(zhǎng)度） + 1（請(qǐng)求類型）= 1024 字節(jié)。

還有兩個(gè)疑問(wèn)：

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

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