openresty記錄響應body亂碼問題

問題背景

　　最近新上了一個功能，openresty通過syslog記錄請求日志，然后由logstash推送至ES。測試上線時未發現這個問題，在日常查看日志的過程中，發現logstash推送有錯誤日志，錯誤內容為：Error parsing json，導致此條請求日志丟失。

排查過程

　　1、在syslog中查找出現rror parsing json的日志，日志內容為：

{
    "request": {},
    "api": {},
    "upstream_uri": "",
    "response": {
        "body": "\b}Ϋٰȿ¢³HK>-¤ZŨwc¸±H½񨻴¥𼰮ѝ:h٥lQ¶܊𩥹\/𢦫A骩£𐵽I§HeƣJ¥ªy\bYHɬ晲̼.^¢~&Ԗ<Ŝu0004³Pv߯𜱽2򣹩9§𛳰004YRL0Üse񛳰018yׂ򉛵000fÿ D\b\\ì蛵0006ƞ󛳰018Ġ`OEѐ𶛵001d㐵y´§ꨜu0017~~И雿쮺]-¨򛛲LH󿶌klࢇcL\n{¦G~׮gyKeą±؜u0002L3\bG@¨#U¾:Ŧ,QL¹(=»{ӓ{mm¶[\/7!&c?ժłcHvxXLuǙ¹_ǃ̢򣹽g>U¶سL-Pò𤦡¾Мu001c2¸\f¿OnGŧ⠑矸I0k̾lЇ¶.龧d0븳q򶪰 K7d\t׬ō^­A±%ͨG¥J]a˜u0016ƹ�g擁E5®4[*-¨£\f傜u0012T©+̖៊8r¬iEiv<𿹕۽^ݿ�b׆YS»Ѭ.eל\𦪰P󅚣¸#󾵾ǽ¡D~d­8린²\t⃔ⅵѨ±ǣ}[1qE󄤉+Υ؜vЬBINµKª°¯]¸=R=>n\r»噠±ቃྊ;󳮰07¨;_n%",
        "headers": {
            "content-type": "text\/plain;charset=UTF-8",
            "date": "Wed, 02 Jan 2019 05:34:43 GMT",
            "connection": "close",
            "x-ratelimit-limit-second": "700",
            "vary": "Accept-Encoding",
            "content-encoding": "gzip",
            "via": "kong\/0.14.0",
            "x-kong-proxy-latency": "4",
            "x-ratelimit-remaining-second": "699",
            "transfer-encoding": "chunked",
            "x-kong-upstream-latency": "2",
            "x-kong-upstream-status": "200",
            "server": "nginx"
        },
        "status": 200,
        "size": "1012"
    },
    "started_at": 1546407283066
}

大家可以看到response.body是亂碼，response.body記錄的是請求相應的內容把這一段json進行json校驗，也會發現有問題。

　　2、嘗試調用該接口，發現返回的是正常內容，但是記錄的確是亂碼，所以確定應該是openresty記錄日志的時候出現了問題。目前我們是在openresty的log階段進行日志記錄，且針對chunked編碼進行了處理（如果body大於1k則不進行記錄）。日志記錄的代碼如下：

function body_filter()
  local headers = ngx.resp.get_headers()
  if headers['content-type'] and then
    if string.find(headers['content-type'], "application/json") or string.find(headers['content-type'], "text/plain") then
      local chunk = ngx.arg[1] or ""
      if string.len(ngx.ctx.response_temp or "") < max_body_size then
        ngx.ctx.response_temp = (ngx.ctx.response_temp or "").. chunk
        ngx.ctx.response_body = ngx.ctx.response_temp
      else
        ngx.ctx.response_body = ""
      end
    end
  end
end

　　3、想通過在測試環境加一些日志，然后調用線上的接口進行排查問題，由於線上的接口做了IP限制，測試環境調不通，此方法作罷。

　　4、讓接口方把線上的數據拷貝至測試環境，然后調用此接口，但是日志記錄也是正常的，沒有出現亂碼。

　　5、由於不能重現問題，在測試環境排查很難繼續下去。最后沒辦法，只能獻出終極武器，抓包。

　　6、通過tcpdump -Xvvenn -iany -w /tmp/20181228.pcap net [ip] and net [ip] and port [port]在線上服務器上抓包，然后下載pcap文件用wireshark進行分析，找到出問題的請求，如下圖： 

                         

通過我標紅的地方可以很清楚的看到，響應數據是通過gzip壓縮的，而我們日志記錄中沒有任何解壓縮的處理，所以日志記錄的時候就會出現上述的情況。

問題總結

　　最后解決方式是如果響應body如果進行了壓縮，我們默認不記錄響應body。

　　這個問題從出現到最終解決前前后后經歷了兩三天，解決完了會發現這個問題其實很簡單，從最早的日志里其實也有蛛絲馬跡（如第一個代碼片段中標紅的地方），但你其實想不到。所以也給了我很深的感悟：

　　　　1、一定要想方設法的重現問題，不然很多時候你可能就無從下手。

　　　　2、網絡這一門技術確實太重要了，如果這次不進行抓包分析，可能還得絞盡腦汁想別的方法。記得上一次nginx的問題也是通過抓包分析問題的，所以這一利器一定要掌握。

　　寫這篇文章的主要目的是記錄一下自己的排查過程（很多細節可能描述的不是很清楚），通過這種方式讓自己不斷優化自己解決問題的思路，讓以后的日子里沒有難解的bug。^_^