万分之一错误率问题的分析及定位

Posted 2020-08-28 hetaohappy

本文主要描述网关上线的一次异常排查，分析排查问题的思路及过程。 通过本文，可以较好的了解网络，netty及http协议。

1问题背景

1 网关上线后有二万分之一的请求报500的错误。

2 升级了几个网关的业务域，但是只有一个业务域报错，其他业务域正常。

2基础知识

2.1 netty的worker模型

 

Netty的线程模型主要为Boss线程组和worker线程组。 Boss线程负责接收连接，在tcp连接创建好后，会通过一定策略将连接(channel)绑定到worker线程上面。

Worker线程主要做三件事情：IO处理，执行定时任务，执行任务队列。

IO处理：主要为接收数据包，对数据包进行解析。

执行定时任务：处理绑定在worker上面的定时任务。

执行任务队列：处理绑定在worker上面的任务。

Netty处理channel有一个准则：当前执行线程(worker2)不是对应channel绑定的线程（worker1），便会封装一个task，放到channel绑定线程(worker1)的队列里面。 具体这么设计的原因，这里暂时不做讨论。

2.2 tcp拆包

如果发送的tcp包大于MSS（Max segment size）会进行拆包，MSS大小的计算一般为：MSS=MTU-sizeof(IP Header)-sizeof(TCP Header)=1500-20-20=1460。

如果发送的一个请求大于1460，一般便会拆成多个segment进行发送。比如一次http请求包的大小为2000，会拆成两个tcp segment。

上图描述，web服务端接收到第一个segment1会构造部分line和header的对象，接收第二个segment，会构造剩下的header和boby的对象。

具体http协议的解析可以参考：netty对http协议解析原理  http://blog.csdn.net/hetaohappy/article/details/52008120

2.3 连接关闭策略

上图未罗列详尽，主要描述了一些后面需要关注的点。连接的关闭来源主要分为外部触发和内部触发。

外部触发：主要为客户端端关闭连接(FIN)或者强制关闭(RST)。内部触发：主要为空闲超时关闭连接，http协议出错关闭连接，网络异常关闭连接等。

网关如果收到关闭连接的信号，会去检查http协议解析的状态。

2.4 FIN和RST区别

FIN和RST都是用于关闭网络连接。 FIN主要用于标准的四次挥手的关闭方式。而RST表示复位，强制关闭，用于异常的关闭连接。

发送RST包关闭连接时，不必等缓冲区的包都发出去，直接就丢弃缓存区的包发送RST包。而接收端收到RST包后，也不必发送ACK包来确认。

RST的好处是解决了麻烦的TIME_WAIT等状态的连接。

两者是通过tcp.flags.fin或者tcp.flags.reset 来标识当前的包是哪种关闭方式。

在java里面如果设置SO_LINGER=0 ，调用channel.close的时候，发送的就是RST包，如果SO_LINGER != 0 ，调用channel.close，则会走tcp的四次挥手的流程。

RST的出现大概场景：

1 服务端口未打开

2 已经关闭连接，又收到请求的包

3 重试达到一定的次数

3 初步分析定位

1 通过异常栈分析：http协议解析了一半，然后对channel进行close导致的错误，可以确定是http协议解析的问题。

2 怀疑是header存在非法字符解析报错导致。之前版本header解析出错是414， 统计最近几天的414的错误。标红的是上线后的时间点统计。确实有可能414错误变成500错误了。 But why?

时间	414个数	500个数
1/10:17--1/11:10	2,420	0
1/11:17--1/12:10	900	0
1/12:17--1/13:10	40	3940

3 新功能升级有一个点是netty版本从4.0.33升级到了4.0.41版本。在老的版本中是没有堆栈描述的Exception，Exception对象是在新版本中添加的，问题出现的原因可能是netty版本升级导致。

4 升级了几个业务域，但是只有一个业务域报错，更加确定是协议解析的错误。

4 问题分析定位上半场 

4.1 异常原理分析

网关的http协议解析是基于netty实现的，通过异常描述，可以确定如下信息

1 异常的错误是一个异步task执行导致。

2 可以看到触发的是invokeChannelInactive任务，这里可以确定是某个地方触发了channel的close方法。

3 在decodeLast处报错，可以确定是http协议解析了一半，然后连接被关闭掉，导致的上述异常。

通过该调用栈分析发现，异步在提高性能的同时，但是对于问题的排查难度非常大，因为调用链不够完整，不清楚是哪个地方触发的异步任务。

这里主要有两个疑问：

1 调用关闭连接的源头在哪个地方？

2 为什么在关闭连接的时候，去检查http协议解析状态，http协议解析了一半?(http协议解析一半，在关闭连接就会抛出异常)

一直怀疑是header里面存在非法字符导致协议解析一半，导致关闭的连接。 但是通过推演代码逻辑是不可能发生这种情况，并且在线下均未复现。（如果对该逻辑感兴趣，可查看netty-4.0.41的HttpObjectDecoder 这个类）

4.2 异常行为分析

在通过分析代码及线下复现均未果的情况下，尝试分析所有的错误是否有什么共性。

错误的分布

发现请求量大的时候，错误便会增多。便怀疑是在并发较高的情况下，可能触发了某个异常机制。便线下做性能测试，但是并未复现该问题。

线上线下行为分析

怀疑线上行为和线下行为可能表现不一致，比如部署结构或者代码编译问题。访问线上来构造各种可能出现该异常的请求，但是也未复现。

访问的accesslog分析

通过access log分析，发现出错请求的access log的部分header并没有打印出来，这里更加判定是http协议解析出错导致http协议解析了一半。但是分析的各种场景并不能复现该异常。

在各种分析都未果的情况下，便启动了排查问题的一大利器：抓包。

4.3 网络抓包

运维帮忙抓线上返回是500错误的包，通过抓包分析来定位问题。

1 通过查询抓的数据包，未发现有500异常日志输出的这段时间有500 的响应包。尝试通过二进制和文本方式抓包，均未发现500响应的包。

2 通过http.request.full_uri=="XXX" 也未过滤到500对应的url。

分析线上的包却发现了另外两种场景：1：对外流量还存在大量的http1.0协议的请求；2：服务端会收到大量的RST的请求。(之前对这两种情况的场景支持的比较少)

随着问题的排查，旧的问题还未找到答案，新的问题又来了(比如：抓不到返回的500的包及过滤不到对应的请求包)

有这么一个疑问，抛异常的时候，上下文的信息是什么，是不是可以从抛异常的上下文中找到一点蛛丝马迹？便启动了排查问题的第二大利器：Btrace

4.4  Btrace

上面为Btrace 代码，主要为执行到出异常的那一行，然后把当前上下文的对象信息输出出来。

通过Btrace 输出，确定http协议是解析了一半，连接被关闭了， 但是并没有定位到问题的根源。

下面为btrace的代码：https://github.com/billowshe/btraceTest/blob/master/src/main/java/test/btracetest/BTraceHttp.java

btrace的详情可了解江南白衣的文章：Btrace入门到熟练小工完全指南 http://calvin1978.blogcn.com/articles/btrace1.html 

4.5 推演分析

貌似能想到的排查手段都使用了，但是还是未找到错误的根源。貌似解决该问题的思路走到了一个死胡同。

便重新梳理所有关闭连接的可能情况，首先排除了程序内部关闭连接的可能，便怀疑是由外界触发。

灵光乍现：会不会有可能接收到一个拆包，然后客户端直接再发送FIN或者RST? 又找到排查问题的新方向。便重新去排查之前抓的包，看是否可以找到先发送一个拆包，再发送一个FIN或者RST的场景。

4.6 柳暗花明

首先过滤出来所有tcp.flags.reset == 1 的包，然后挨个查看对应的Follow Tcp Stream。突然发现下面这个图，一切都豁然开朗。

 

 

 可以看到客户端先发送了一个不完整的http请求的包(拆包)，正常情况应该还会发送剩下的http请求的包，但是这里却直接发送了RST的一个包，客户端强制把连接给关闭掉了。

这样前面所有的疑惑都能解释了。

1 http协议解析了一半，连接被RST关闭了， 导致500的异常。

2 抓包没有抓到返回的500包。因为channel已经被关闭了，其实仅仅是记录日志，并没有发送数据包。

3 通过http.request.full_uri=="XXX" 未过滤对应的500请求。因为http请求包被拆包，仅仅是发送了一个segment，导致按照request.full_uri是查询不到的。

4 线上一直存在该问题，只是新升级的版本把这个问题给暴露出来了。

5 只有一个业务域受影响？是由于其他的业务前面部署的有nginx等负载均衡设备，这种断包的请求在nginx等上面已经被处理掉了。而该业务前面没有负载均衡设备。

5 问题分析定位下半场

排查完500异常的原因后，还被下面问题困扰着

1 确定了RST导致500，是否还有其他场景导致500异常。为什么会出现发送了一半的包，接着就把连接给关闭掉的情况？

2 如何模拟这种错误的请求？

3 该问题是一个通用的问题， nginx等负载均衡设备对于这种场景是如何处理的？

5.1 500错误场景分析

 继续进行抓包，多分析一些场景

 1：连接空闲关闭

 

客户端先发送了http的一段segment，接着一直不再发送剩下的segment。 服务端连接空闲超时后，就会关闭该连接，导致500异常。

 2：FIN关闭

 

客户端先发送了http的一段segment，接着过了1s后，客户端发送FIN，进行连接的关闭。通过该抓包流程，可以看出服务端收到segment后，返回的ACK，客户端并没有收到。服务端回复ack的信息，客户端一直收不到，导致客户端发送了关闭连接的请求。

通过抓包的分析，产生500请求主要有如下场景

1 客户端发送一段segment，然后发送FIN（关闭连接）

2 客户端发送一段segment，然后发送RST(强制关闭连接)

3 客户端发送一段segment, 服务端超时，进行关闭连接

5.2 请求模拟

该请求就是发送一半http协议数据到服务端，然后再关闭连接。 刚开始一直定位于通过http客户端来做，由于没法在应用层来控制只发送一半的包，导致一直无法实现模拟请求。

尝试直接通过tcp的客户端来做，通过发送一段不完成的http协议数据，然后再关闭连接。选择了jmeter来模拟这种场景。

构造上述的请求，先点击发送，这个时候连接会被hold主，接着点击stop按钮，便能模拟该请求。 如果SO_LINGER设置为0，则关闭发送的是RST包，如果不是0，则关闭发送的为FIN包。

5.3 nginx排查

通过构造请求发送到nginx，发现nginx会产生400的错误。通过排查，发现nginx生产环境确实存在一些400的错误。

6 总结

至此所有的问题都排查清楚了，下面对排查问题的过程最一些简单的总结：

1 版本升级带来的500异常，是以前一直存在的问题，只是该版本给暴露出来了。

2 导致问题的根本原因可能是网络的抖动等导致的。 

3 排查偶发的异常问题，需要耐得住寂寞，仔细排查，如果实在没有思路，那就好好休息一下，整理思路，再继续排查。

福利来袭
中生代成立一周年了，为了答谢沪上的朋友，特举办年度大会，集结了唯品会，百度，阿里，华为，蘑菇街，拍拍贷，携程，盛派网，沪江网等公司大咖，共襄盛举。 3.11，等你来约！

报名链接：https://m.grouplus.com/UbrxIM