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。^_^