[[347677]]

 前言

筆者很熱衷于解決Bug,同時(shí)比較擅長(zhǎng)(網(wǎng)絡(luò)/協(xié)議)部分，所以經(jīng)常被喚去解決一些網(wǎng)絡(luò)IO方面的Bug?，F(xiàn)在就挑一個(gè)案例出來(lái)，寫出分析思路，以饗讀者，希望讀者在以后的工作中能夠少踩點(diǎn)坑。

關(guān)于TCP流

TCP是流的概念，解釋如下

• TCP窗口的大小取決于當(dāng)前的網(wǎng)絡(luò)狀況、對(duì)端的緩沖大小等等因素，
• TCP將這些都從底層屏蔽。開(kāi)發(fā)者無(wú)法從應(yīng)用層獲取這些信息。
• 這就意味著，當(dāng)你在接收TCP數(shù)據(jù)流的時(shí)候無(wú)法知道當(dāng)前接收了
• 有多少數(shù)據(jù)流，數(shù)據(jù)可能在任意一個(gè)比特位(seq)上。

Bug現(xiàn)場(chǎng)

出Bug的系統(tǒng)是做與外部系統(tǒng)進(jìn)行對(duì)接之用。這兩者并不通過(guò)http協(xié)議進(jìn)行交互，而是在通過(guò)TCP協(xié)議之上封裝一層自己的報(bào)文進(jìn)行通訊。如下圖示:

通過(guò)監(jiān)控還發(fā)現(xiàn)，此系統(tǒng)的業(yè)務(wù)量出現(xiàn)了不正常的飆升，大概有4倍的增長(zhǎng)。而且在監(jiān)控看來(lái)，這些業(yè)務(wù)還是成功的。

第一反應(yīng)，當(dāng)然是祭出重啟大法，第一時(shí)間重啟了機(jī)器。此后一切正常，交易量也回歸正常，仿佛剛才的Bug從來(lái)沒(méi)有發(fā)生過(guò)。在此之前，此系統(tǒng)已經(jīng)穩(wěn)定運(yùn)行了好幾個(gè)月，從來(lái)沒(méi)出現(xiàn)過(guò)錯(cuò)誤。

但是，這事不能就這么過(guò)去了，下次又出這種Bug怎么辦,繼續(xù)重啟么?由于筆者對(duì)分析這種網(wǎng)絡(luò)協(xié)議比較在行，于是Bug就拋到了筆者這。

錯(cuò)誤日志

線上系統(tǒng)用的框架為Mina,不停的Dump出其一堆以16進(jìn)制表示的二進(jìn)制字節(jié)流。

,并拋出異常

首先定位異常拋出點(diǎn)

以下代碼僅為筆者描述Bug之用，和當(dāng)時(shí)代碼有較大差別。

private boolean handeMessage(IoBuffer in,ProtocolDecoderOutput out){ 
 int lenDes = 4; 
 byte[] data = new byte[lenDes]; 
 in.mark(); 
 in.get(data,0,lenDes); 
 int messageLen = decodeLength(data); 
 if(in.remaining() < messageLen){ 
  logger.warn("未接收完畢"); 
  in.reset(); 
  return false; 
 }else{ 
  ...... 
 } 
  
} 

筆者本身經(jīng)常寫這種拆包代碼，第一眼就發(fā)現(xiàn)有問(wèn)題。讓我們?cè)倏匆谎蹐?bào)文結(jié)構(gòu):

上面的代碼首先從報(bào)文前4個(gè)字節(jié)中獲取到報(bào)文長(zhǎng)度，同時(shí)檢測(cè)在buffer中的存留數(shù)據(jù)是否夠報(bào)文長(zhǎng)度。

if(in.remaining() < messageLen) 

為何沒(méi)有在一開(kāi)始檢測(cè)buffer中是否有足夠的4byte字節(jié)呢。此處有蹊蹺。直覺(jué)上就覺(jué)的是這導(dǎo)致了后來(lái)的種種現(xiàn)象。

事實(shí)上，在筆者解決各種Bug的過(guò)程中，經(jīng)常通過(guò)猜想等手段定位出Bug的原因。但是從現(xiàn)場(chǎng)取證，通過(guò)證據(jù)去解釋發(fā)生的現(xiàn)象，通過(guò)演繹去說(shuō)服同事，并對(duì)同事提出的種種問(wèn)題做出合理的解釋才是最困難的。

猜想總歸是猜想，必須要有實(shí)錘，沒(méi)有證據(jù)也說(shuō)服不了自己。

為何會(huì)拋出異常

這個(gè)異常由這句代碼拋出:

int messageLen = decodeLength(data); 

從上面的Mina框架Dump出的數(shù)據(jù)來(lái)看，是解析前四個(gè)字節(jié)出了問(wèn)題，前4個(gè)字節(jié)為30,31,2E,01(16進(jìn)制)

最前面的包長(zhǎng)度是通過(guò)字符串來(lái)表示的，翻譯成十進(jìn)制就是48、49、46、1，再翻譯為字符串就是('0','1', 非數(shù)字, 非數(shù)字)

30, 31,    2E,   01  (16進(jìn)制) 
48, 49,    46,   1   (10進(jìn)制) 
'0','1',非數(shù)字, 非數(shù)字 (字符串) 

很明顯，解析字符串的時(shí)候遇到前兩個(gè)byte,0和1可以解析出來(lái)，但是遇到后面兩個(gè)byte就報(bào)錯(cuò)了。至于為什么是For input String,'01',而不是2E,是由于傳輸用的是小端序。

為何報(bào)文會(huì)出現(xiàn)非數(shù)字的字符串

鑒于上面的錯(cuò)誤代碼，筆者立馬意識(shí)到，應(yīng)該是TCP流處理不當(dāng)了。這時(shí)候就應(yīng)該去找發(fā)生Bug的最初時(shí)間點(diǎn)的日志，去分析為何那個(gè)時(shí)間會(huì)gg。

由于最初那個(gè)錯(cuò)誤日志Dump數(shù)來(lái)的數(shù)據(jù)過(guò)于長(zhǎng)，在此就不貼出來(lái)了，以下示意圖是筆者當(dāng)時(shí)人肉decode的結(jié)果:

拋出的異常為:

這個(gè)異常拋出點(diǎn)恰恰就在筆者懷疑的

in.get(data,0,lenDes); 

這里。至此，筆者就幾乎已經(jīng)確定是這個(gè)Bug導(dǎo)致的。

演繹

Mina框架在Buffer中解幀，前5幀正常。但是到第六幀的時(shí)候，只有兩個(gè)字節(jié)，無(wú)法組成報(bào)文的4byte長(zhǎng)度頭,而代碼沒(méi)有針對(duì)此種情況做處理,于是報(bào)錯(cuò)。為何會(huì)出現(xiàn)這種情況:

• TCP窗口的大小取決于當(dāng)前的網(wǎng)絡(luò)狀況、對(duì)端的緩沖大小等等因素，
• TCP將這些都從底層屏蔽。開(kāi)發(fā)者無(wú)法從應(yīng)用層獲取這些信息。
• 這就意味著，當(dāng)你在接收TCP數(shù)據(jù)流的時(shí)候無(wú)法知道當(dāng)前接收了
• 有多少數(shù)據(jù)流，數(shù)據(jù)可能在任意一個(gè)比特位(seq)上。

第六幀的頭兩個(gè)字節(jié)是30,32正好和后面dump出來(lái)的30 31 2e 01中的30、31組成報(bào)文長(zhǎng)度

• 30,32,30,31 (16進(jìn)制)
• 48,50,48,49 (10進(jìn)制)
• 0, 2, 0, 1 (字符串)
• 2, 0, 1, 0 (整理成大端序)

這四個(gè)字節(jié)組合起來(lái)才是正常的報(bào)文頭，再經(jīng)過(guò)運(yùn)算得到整個(gè)Body的長(zhǎng)度。

第一次Mina解析的時(shí)候，后面的兩個(gè)30,31尚未放到buffer中，于是出錯(cuò):

public ByteBuffer get(byte[] dst, int offset, int length) { 
    checkBounds(offset, length, dst.length); 
    // 此處拋出異常 
    if (length > remaining()) 
        throw new BufferUnderflowException(); 
    int end = offset + length; 
    for (int i = offset; i < end; i++) 
        dst[i] = get(); 
    return this; 
} 

為何流量會(huì)飆升

解釋這個(gè)問(wèn)題前，我們先看一段Mina源碼:

// if there is any data left that cannot be decoded, we store 
        // it in a buffer in the session and next time this decoder is 
        // invoked the session buffer gets appended to 
        if (buf.hasRemaining()) { 
            if (usingSessionBuffer && buf.isAutoExpand()) { 
                buf.compact(); 
            } else { 
                storeRemainingInSession(buf, session); 
            } 
        } else { 
            if (usingSessionBuffer) { 
                removeSessionBuffer(session); 
            } 
        } 

Mina框架為了解決這種問(wèn)題，會(huì)將這種尚未接收完全的包放到sessionBuffer里面，待解析完畢后把這份Buffer刪除。

如果代碼正確，對(duì)報(bào)文頭做了校驗(yàn)，那么前5個(gè)報(bào)文的buffer將經(jīng)由這幾句代碼刪除，只留下最后兩個(gè)沒(méi)有被decode的兩字節(jié)。

if (usingSessionBuffer && buf.isAutoExpand()) { 
    buf.compact(); 
} else { 
    storeRemainingInSession(buf, session); 
} 

但是，由于decode的時(shí)候拋出了異常，沒(méi)有走到這段邏輯，所以前5個(gè)包還留在sessionBuffer中，下一次解包的時(shí)候，又會(huì)把這5個(gè)包給解析出來(lái)，發(fā)送給后面的系統(tǒng)。

這也很好的解釋了為什么業(yè)務(wù)量激增，因?yàn)橄到y(tǒng)不停的發(fā)相同的5幀給后面系統(tǒng)，導(dǎo)致監(jiān)控認(rèn)為業(yè)務(wù)量飆升。后查詢另一個(gè)系統(tǒng)的日志，發(fā)現(xiàn)一直同樣的5個(gè)序列號(hào)坐實(shí)了這個(gè)猜想。

完結(jié)了么?

NO,整個(gè)演繹還有第二段日志的推演

就是系統(tǒng)后來(lái)不停dump出的日志，再貼一次:

這個(gè)buffer應(yīng)該是Mina繼續(xù)接收外部系統(tǒng)的數(shù)據(jù)到buffer中導(dǎo)致，

Mina框架不停的接收數(shù)據(jù)，直到buffer區(qū)滿，然后整個(gè)框架不停的解析出前5幀，到第6幀的時(shí)候，出錯(cuò)，然后dump出其尚未被解幀的數(shù)據(jù)。這就是第二段日志。

最后的高潮

到現(xiàn)在推理似乎很完美了，但是我突然覺(jué)得不對(duì)(另一位同事也提出了相同的疑問(wèn)):

如果說(shuō)Mina接收到新的數(shù)據(jù)放到buffer中的話，第6幀的前兩個(gè)字節(jié)和后來(lái)發(fā)過(guò)來(lái)的若干字節(jié)不是又拼成了完整的一幀了么，那么后來(lái)為什么會(huì)一直出錯(cuò)了呢。如下圖所示:

丟失的兩字節(jié)

按照前面的推理，幀6的前兩個(gè)字節(jié)30、32肯定是丟了，那么怎么丟的呢?推理又陷入了困境，怎么辦?日志已經(jīng)幫不了筆者了，畢竟日志的表現(xiàn)都已解釋清楚。翻源碼吧:

Bug的源頭:

如果有問(wèn)題，肯定出在將數(shù)據(jù)放在Buffer中的環(huán)節(jié)，于是筆者找到了這段代碼:

if (appended) { 
    buf.flip(); 
} else { 
    // Reallocate the buffer if append operation failed due to 
    // derivation or disabled auto-expansion. 
    buf.flip(); 
    ...... 
} 

問(wèn)題出在buf.flip()上面，這段代碼最后調(diào)用的代碼是Java的Nio的Buffer的flip,代碼如下:

public final Buffer flip() { 
  // 下面這一句導(dǎo)致了最終的Bug現(xiàn)象 
    limit = position; 
    position = 0; 
    mark = -1; 
    return this; 
} 

為什么呢?首先我們需要了解一下Nio Buffer的一些特點(diǎn):

同時(shí)當(dāng)Mina框架將數(shù)據(jù)(數(shù)據(jù)本身也是一個(gè)buffer)放到sessionBuffer的時(shí)候,也是將position到limit的數(shù)據(jù)放到新buffer中，

下面我們演繹一下第一次拋異常時(shí)候的flip前和flip后:

這樣就清楚了,在buf.flip()后,由于limit變成了原position的位置，這樣最后的兩個(gè)字節(jié)30,32就被無(wú)情的丟棄了。這樣整個(gè)sessionBuffer就變成:

為什么position在flip前沒(méi)有指向limit的位置，是由于在每次讀取前有一個(gè)checkBound的動(dòng)作，在檢查buffer數(shù)據(jù)不夠后，不會(huì)推進(jìn)position的位置，直接拋出異常:

static void checkBounds(int off, int len, int size) { // package-private 
    if ((off | len | (off + len) | (size - (off + len))) < 0) 
        throw new IndexOutOfBoundsException(); 
} 
這樣所有的都 

這樣所有的都說(shuō)的通了，也完美了解釋了所有的現(xiàn)象。

正確代碼

private boolean handeMessage(IoBuffer in,ProtocolDecoderOutput out){ 
 int lenDes = 4; 
 byte[] data = new byte[lenDes]; 
 in.mark(); 
    // 前4字節(jié)校驗(yàn)代碼 
 if(in.remaining() < lenDes){ 
  // 由于未消費(fèi)字節(jié)，無(wú)需reset 
  return false; 
 } 
 in.get(data,0,lenDes); 
 int messageLen = decodeLength(data); 
 if(in.remaining() < messageLen){ 
  logger.warn("未接收完畢"); 
  in.reset(); 
  return false; 
 }else{ 
  ...... 
 } 
  
} 

為什么線上一直穩(wěn)定

隨著網(wǎng)絡(luò)不斷發(fā)展的今天，一些短小的幀很難出現(xiàn)中間斷開(kāi)的現(xiàn)象。而在一個(gè)好幾百字節(jié)的包中，前4個(gè)字節(jié)正好出錯(cuò)的概率那更是微乎其微。這樣就導(dǎo)致Bug難復(fù)現(xiàn)，很難抓住。即使猜到是這里，也沒(méi)有足夠的證據(jù)來(lái)證明。

總結(jié)

Mina/Netty等各種網(wǎng)絡(luò)框架給我們處理TCP流問(wèn)題提供了非常好的解決方案。但是我們寫代碼的時(shí)候也不能掉以輕心，必須時(shí)刻以當(dāng)前可能讀不夠字節(jié)的心態(tài)去讀取buffer中的數(shù)據(jù)，不然就可能遭重。

在此感謝給力的各位同事們，是你們的各種反駁讓我能夠找到最終的源頭，也讓我對(duì)網(wǎng)絡(luò)框架有了更加深刻的理解。

本文轉(zhuǎn)載自微信公眾號(hào)「解Bug之路」，可以通過(guò)以下二維碼關(guān)注。轉(zhuǎn)載本文請(qǐng)聯(lián)系解Bug之路公眾號(hào)。