推薦幾個我近期排查線上http接口偶發415時用到的工具

導讀：近期有一個業務部門的同學反饋說他負責的C工程在小概率情況下SpringMvc會返回415，通過輸出的日志可以確定是SpringMvc找不到content-type這個頭了，具體為什么找不到了呢？請聽我娓娓道來。

 

關鍵詞：http 415，SpringMvc，nginx，lua，wireshark，jmeter

問題現象：

近期接到一個同學的反饋說，他負責的C工程在小概率的情況下SpringMvc會返回415，通過輸出的日志發現請求頭里面並沒有content-type了，所以才導致SpringMvc返回415，他猜測可能是我在nginx這邊加的lua腳本給影響了（我們用lua腳本做了一些灰度跳轉的邏輯），雖然我心里很清楚lua這塊並沒有修改請求頭的邏輯，但是沒辦法，嘴上說說並不能服眾，我需要拿出證據自證清白。

第一把斧亮相：

既然是說lua把請求頭給改了，那把content-type輸出來看看不就完事了。很簡單，直接修改nginx access日志的log_format即可，在原有的基礎上增加$http_content_type。就這樣很快加完了，那就開始守株待兔吧，運氣還不錯，幾分鍾以后就命中一個415的請求，查看access日志里記錄的content-type值，一點問題沒有，就是我們熟悉的那個“application/json”，這一刻心里竊喜“不是哥的問題，回郵件該干啥干啥了”。

第二把斧亮相：

半天過后負責Resin（一種web服務器，和Tomcat差不多）的同學找到了我，猜測可能是請求頭里面有某些特殊字符導致請求頭的解析發生了問題，所以請求頭亂了，請看下面這張圖，仔細找找其實是能找到content-type的。

 

 

 

 

 話到這里我已經知道他要干什么了，給我幾分鍾我想想辦法，既然懷疑是特殊字符導致那我就將所有的頭信息都打印出來，查了一下lua-nginx-module的使用手冊，有一個聲明叫log-by-lua可以使用一下，它類似於一個過濾器一樣，如果配置了，nginx會在特定的階段觸發它，更具體的說nginx會在log階段且在記錄access log之前觸發。所以我的大概思路是這樣“如果請求后端服務器返回415那就輸出請求頭信息到日志中”，具體的腳本寫出來就是這樣（我當時想是不是可以用在服務的監控上）：

location  ~ \.do$ {

        proxy_pass http://$backend;

         log_by_lua_block {

          if tonumber(ngx.var.status) == 415 then

                ngx.log(ngx.ERR,"upstream reponse status is 415,please notice it,here are request headers:")

                local h, err = ngx.req.get_headers(100,true)

 

               if err == "truncated" then

                    ngx.log(ngx.ERR,"request headers beyond 100,will not return")

                else

                   local cjson = require("cjson")

                   ngx.log(ngx.ERR,cjson.encode(h))

              end

          end

        }

   }

和之前一樣，繼續開始守株待兔，運氣不錯，幾分鍾過后就出現了415，立馬將請求頭信息發給負責Resin的那個大哥，感覺馬上要水落石出了，下樓抽根煙放松放松。

 

第三把斧亮相：

第二天剛到工位我就詢問負責Resin那個大哥是否復現了問題，結果讓人很意外，拿着我給的請求頭信息居然沒有復現問題，這太不科學了，大家在群里你一言我一嘴，感覺有些黔驢技窮，有人說要review Resin的源代碼（線上出了問題，review我覺得真的是一種解決問題的下策），有人在那里抱怨說早應該把Resin替換掉的（事后諸葛亮），最后我提了一個土辦法，應該可以復現問題，要是還不能復現真的就不科學了。兄台，tcpdump+wireshark了解一下，分幾步來說：

        1.在服務器上使用tcpdump抓一段時間的包，因為不確定什么時候會出現，所以暫定10分鍾；

        2.將第一步中產生的抓包文件使用wireshark打開，過濾http狀態為415的請求，http.response.code==415；

        

 

 

        3.選擇其中一條報文，右鍵“追蹤流-tcp流”；

        4.復制第三步產生的tcp報文；

        

      5.將第四步復制的tcp報文直接貼到jmeter里面進行測試（我為什么選擇jmeter，因為可以直接模擬發送tcp報文，不會像postman增加一些自己的頭）；

      6.成功復現結果；

      7.導出jmeter腳本給負責Resin的同學修改bug；

 

問題原因分析：

最終確定是Resin出了問題，但這里有個前提是我們公司自己改造過的Resin，官方的Resin並沒有這個問題，至於為什么我們改造過的Resin會出問題，這里就不多說了，只是一些內部的技術債罷了，說了可能也不會明白，明白了可能也不會碰上。

工具串講：

首先我使用nginx的log_format直接輸出請求頭里面的content_type，但是如果想輸出所有的請求頭時這種方式就行不通了，所以我借助了lua-nginx-module中的log-by-lua在反向代理請求結束時輸出了請求頭，最后為了完完全全找到問題發生的場景，我使用tcpdump來抓取網絡包，並且借助wireshark來找到發生了415的tcp報文，拿着tcp報文直接使用jmeter成功復現問題。

 

總結：

十一長假的第五天，此刻剛把孩子哄睡着，在床邊小心翼翼的打開電腦整理一下上次排查問題的過程，上面提到的幾個工具是我想推薦給大家使用的，這里拿自己經歷過的真實場景做一個拋轉引用，至於更深層次的使用網絡上不乏鋪天蓋地的介紹，我這里就不啰嗦了，如果覺得有用，請大家點個推薦。最后，祝大家假期愉快。

參考資料：

https://github.com/openresty/lua-nginx-module#log_by_lua

http://jmeter.apache.org/usermanual/index.html

https://www.wireshark.org/docs/