推荐几个我近期排查线上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/

 

来我的公众号与我交流