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