问题备忘: httpclient连接池异常引发的惨案

深藏阁楼爱情的钟 2021-06-11 15:11 916阅读 0赞

## 1. 问题描述 ##

客户端A --> Ngnix --> 服务B  
Ngnix做服务B的负载，客户端访问服务B时，客户端偶尔会有抛出TimeoutException异常。

举个例子：如A在09:59:48访问B，则服务B在09:59:53收到请求，并成功执行业务并返回。但是A会在10:00:05左右抛出TimeoutException。此时客户端A认为本次调用失败，然后走失败的业务逻辑。但是查找服务端的日志，发现实际业务在服务B上正常执行了，并正常返回。这样出现客户端和服务端两边数据不一致的问题。

这个问题是难点：

1.  两边是通过公网调用，公网网络的复杂性会导致问题更复杂
2.  无法直接定位是服务端还是客户端的问题
3.  两边的程序不是同一个所写，由不同人维护。自己维护服务端代码，客户端代码是其它人维护
4.  需要理解TCP/IP的通信协议
5.  需要理解httplclent和ngnix的超时配置相关的知识

下面我按照以下顺序一一排查问题：

1.  网络问题
2.  超时配置参数的问题
3.  GC的问题
4.  使用tcpdump抓包，分析网络包
5.  修正代码问题
6.  上线验证

## 2. 问题分析处理的过程 ##

### 2.1. 网络问题 ###

由于客户端A和服务B是使用公网访问，最开始认为是网络抖动引起，并没有马上处理。但是运行一段时间后且这段时间服务器的流量不是很大，这个问题仍然每天不定时出现，所以猜测可能不是网络的问题。

### 2.2. 超时配置参数的问题 ###

又猜测可能是超时参数配置的问题。整理服务端和客户端配置如下：  
**客户端httpclient**  
客户端httpclient的关于连接的配置相关的参数和意义如下：

*  SocketTimeout 是 5s
    
     *  连接建立后，数据传输过程中数据包之间间隔的最大时间
 *  ConnectTimeout 是 3s
    
     *  连接建立时间，即三次握手完成时间
 *  ConnectionRequestTimeout 是默认值
    
     *  httpclient使用连接池来管理连接，这个时间就是从连接池获取连接的超时时间

这3个属性的关系如下：下图来自网络  
![这里写图片描述][SouthEast]  
虽然报文(“abc”)返回总共用了6秒，如果SocketTimeout设置成5秒，实际程序执行的时候是不会抛出java.net.SocketTimeoutException: Read timed out异常的。  
因为SocketTimeout的值表示的是“a”、”b”、”c”这三个报文，每两个相邻的报文的间隔时间没有能超过SocketTimeout。

**ngnix端**  
ngnix端的超时相关的配置如下

1.  keepalive\_timeout 10;
2.  send\_timeout 60;

经过对以上配置参数的深入理解，再加上即使异常的请求服务端也有收到请求并正常执行业务，且每个请求处理完毕的时间都在100ms左右。总之即使以上的配置参数异常导致超时也跟这个问题的现象不同，所以初步排除配置异常的问题

### 2.3. GC的问题 ###

请教组内的同事，可能是GC的问题，可能是GC的关系使服务暂停运行没有及时处理业务  
在服务端B执行如下命令，发现没有执行过FGC，YGC的时间也是在合理范围内  
jstat -gc pid 2000 20  
![这里写图片描述][SouthEast 1]

在客户端A执行如下命令，发现其频繁执行FCG，YGC  
jstat -gc pid 2000 20  
使用"jmap -heap pid" 查看客户端A的堆的分配情况，发现其内存分配非常小，老年期的已用空间在96%以上。  
综上，我们认为是在httpclient建立连接后，堆内存不足引发频繁的FGC，使得httpclient的无法在及时将数据发送请求到服务端，偶尔出现在5s临界点才发送数据到服务端成功  
修改堆内存后，GC的问题解决了，但是很遗憾，这个问题没有被修正。

### 2.4. 使用tcpdump抓包，分析网络包 ###

最后使出大招，在服务端172.23.4.33端使用tcpdump抓包，内容如下：  
![这里写图片描述][SouthEast 2]

**蓝色框的部分**：之前有一个正常的请求，通信完毕后10s，ngnix由于keep-alive=10s时间到了，发送请求通知关闭连接 close notify信令。但是这里有个问题，这里服务端发送FIN信令，而客户端没有发送FIN信令，不符合标准的TCP的四次挥手协议。即连接在服务端已经关闭，而客户端没有关闭。

这里的Alert (level warning description close notify)：表示发送方会关闭这个连接，不会在这个连接上发送任何数据

**红色框的部分**  
红色的部分和黄色的部分正好相隔5s：

红色的部分的包的时间，和我们定位的异常请求开始的时间相同，这里的操作可以理解为客户端和服务端相互关闭链接。加上这里的端口和上面蓝色部分的包的端口组相同，所有这两部分是对相同的连接执行操作，这里就比较奇怪。为什么数据传输完毕后，要经过19s才执行连接关闭推行。貌似这个关闭操作是由下一个请求触发的。

后面阅读httpclient的源码发现，httpclient连接池在执行新的请求，如果发现连接异常时，会调用releaseconnection操作，会先执行释放之前连接操作

**黄色框的部分**  
和红色框的部分正好相隔5s  
这里是通过3次握手建立连接，然后再执行https进行加密传输。对https的后面的Application Data的解密我们发现这个的确是客户端发送到服务端的数据。现象好像是第一次请求执行失败，httpclient重新发起新的请求

所以以上的包和异常现象正好吻合，我们猜测如下：  
客户端A在09:59:48想重用上一次使用的TCP连接，但是发现连接已经关闭。服务端发送RST信令，通话双方重置连接。但是不知道什么原因客户端没有马上重置连接，而在等待5s超时后，然后才向服务端重新建立新的连接，并发送数据，服务端收到数据并执行请求。但是此时客户端发现整个连接时间已经超过5s，抛出TimeoutException。

### 2.5. 检查代码问题 ###

查看客户端代码，发现有两个问题  
一是：httpclient设置（.setRetryHandler(new HttpRetryHandler(3))）重试3次，已知httpclient的connectiontime是最多是5s,但是future.get(5000, TimeUnit.MILLISECONDS)只等待5s，所有如果发生第一次请求失败，则这个肯定会失败。这里客户端的请求服务端的操作和处理返回结果是异步，整个完成请求最多需要20s，而对返回结果的处理是5s之内，如果5s内没有返回，则抛出TimeoutException。但是httpclient的请求并没有被中断，继续执行。这也解释了为什么请求在服务端正常执行，而客户端抛出TimeoutException异常。

// 定义httpClient 
    httpClient = HttpClients.custom().setConnectionManager(connectionManager)
        .setDefaultRequestConfig(defaultRequestConfig)
         // 设置重试3次
        .setRetryHandler(new HttpRetryHandler(3))
        .setMaxConnPerRoute(500).build();
    //利用future管理回调
    Future<Object> future = executorService.submit(new CmdTask(sId, manageCenter.getService(provide), cmd, command.entry, provide, manageCenter.queryProvide(provide)));
    //等待5秒超时
    Object resp = future.get(5000, TimeUnit.MILLISECONDS);
    Pair<Integer, String> pairResp = null;

二是：httpclient使用了PoolingHttpClientConnectionManager连接池，使用PoolingHttpClientConnectionManager需要注意，详细见[官方文档][Link 1]：简单地说PoolingHttpClientConnectionManager里存储的连接，如果连接被服务器端关闭了，客户端监测不到连接的状态变化。在httpclient中，当连接空闲超过10s后，服务端会关闭本端连接。但是客户端的连接一直保持连接，即使服务端关闭连接，客户端也不会关闭连接。所以下次使用连接，程序从连接中获取一个连接（即使这个连接已经被服务端），也需要进行确认，如果发现连接异常，则服务端会发送RST信令，双方重新建立新的连接。

为了解决这个问题HttpClient会在使用某个连接前，监测这个连接是否已经过时，如果服务器端关闭了连接，那么会重现建立一个连接。但是这种过时检查并不是100%有效。所以建立创建一个监控进程来专门回收由于长时间不活动而被判定为失效的连接：

Timer timer = new Timer();
        timer.schedule(new TimerTask() {
            @Override
            public void run() {
                System.out.println("=====closeIdleConnections===");
                connectionManager.closeExpiredConnections();
                connectionManager.closeIdleConnections(5, TimeUnit.SECONDS);
            }
        }, 0, 5 * 1000);

PoolingHttpClientConnectionManager里异常连接没有及时释放，这也解释了之前的抓包中为什么每次请求会先使用旧的连接，发现连接关闭后，又重新建立新的连接的现象。

修改代码：

1.  创建定时任务关闭PoolingHttpClientConnectionManager的异常连接，释放连接和连接相关的资源
2.  关闭重试操作

### 2.6 修改代码后上线验证 ###

修改代码，上线，观察4天，问题没有再出现，捕获新的包查看新的双交互包  
![这里写图片描述][SouthEast 3]

红框部分是：客户端和服务端有正常的请求  
黄框部分是：之前的连接使用后，服务端过10s释放连接，是因为ngnix的keepalive的时间是10s，172.23.4.43通知106.2.33.40关闭请求，106.2.33.40发送FIN,ACK信令到172.23.4.43，表示自己已经连接，并通知对方关闭连接. 172.23.4.43收到信令后，关闭连接，并发送FIN,ACK信令，  
以上是完整的连接断开四次挥手，整个会话连接完全关闭。

绿框部分：客户端和服务端发启新的请求，此时第一步是客户端和服务端是三次握手建立建立

[SouthEast]: /images/20210520/de3cf804a89c480aaae1f6720e3fb7bd.png
[SouthEast 1]: /images/20210520/daf4d19379764403b570c4b2a30e403d.png
[SouthEast 2]: /images/20210520/1e44fa80726040c5b74016bda2fd07b5.png
[Link 1]: https://hc.apache.org/httpcomponents-client-ga/tutorial/html/connmgmt.html
[SouthEast 3]: /images/20210520/870d1054f94643339565fd57a28ad580.png