openresty記錄響應body亂碼問題

問題背景

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

排查過程

　　一、在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校驗，也會發現有問題。

　　二、嘗試調用該接口，發現返回的是正常內容，可是記錄的確是亂碼，因此肯定應該是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

　　三、想經過在測試環境加一些日誌，而後調用線上的接口進行排查問題，因爲線上的接口作了IP限制，測試環境調不通，此方法做罷。

　　四、讓接口方把線上的數據拷貝至測試環境，而後調用此接口，可是日誌記錄也是正常的，沒有出現亂碼。

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

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

                         

經過我標紅的地方能夠很清楚的看到，響應數據是經過gzip壓縮的，而咱們日誌記錄中沒有任何解壓縮的處理，因此日誌記錄的時候就會出現上述的狀況。

問題總結

　　最後解決方式是若是響應body若是進行了壓縮，咱們默認不記錄響應body。

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

　　　　一、必定要千方百計的重現問題，否則不少時候你可能就無從下手。

　　　　二、網絡這一門技術確實過重要了，若是此次不進行抓包分析，可能還得絞盡腦汁想別的方法。記得上一次nginx的問題也是經過抓包分析問題的，因此這一利器必定要掌握。

　　寫這篇文章的主要目的是記錄一下本身的排查過程（不少細節可能描述的不是很清楚），經過這種方式讓本身不斷優化本身解決問題的思路，讓之後的日子裏沒有難解的bug。^_^