http连接池未设置获取连接超时时间导致服务死机

缺乏、安全感 2023-06-27 08:44 16阅读 0赞

## 一、故障过程回顾 ##

2020年1月3日早上7：30收到pay-xx服务连接超时告警，发现问题后马上进行排查，根据链路日志发现，我们请求有通过http发送给第三方，将请求日志发给第三方，但第三方反馈未收到该请求。瞬间懵逼了， 我们有发送请求，但第三方没有收到，请求中途掉包了 ？网络出现了问题？但是我们部分请求是可以送达第三方的，开始怀疑是第三方对我们出口的ip做了白名单限制 ？ 7：50 左右我们一个服务节点开始出现波测告警，该告警的意思是一个服务节点已经死机。于是赶快联系运维重新部署，pay-xx服务。 8：30重新部署服务后，整个请求恢复正常。  
为了排查问题，我们然运维保留了死机节点，并导出了jvm堆栈。

## 二、问题排查 ##

1）我将出问题的节点出口ip给第三方排查是否由于网关ip白名单访问限制导致问题，第三运维反馈ip白名单正常。  
2）我开始找出问题时候http访问的状态，发现在服务告警前，http请求第三方返回了很多504以后， 我们服务开始出现异常；  
![在这里插入图片描述][20200105163721531.png]  
3）第三方排查确实7：29至7：30 一段时间没有收到我们的请求，那这个http 504状态表示的超时，是什么地方返回的呢？看第三方网关监控7：30分他们可以正常收到请求，但为什么我们的一个节点会出现死机呢？  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70]  
4）第三方用的是阿里云cdn加速，进过与阿里一起排查发现7：29至7：30，我们收到的504状态码，是阿里网关内部超时返回的  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70 1]  
5）第三方优化了cdn 中tcp 超时时间  
![在这里插入图片描述][20200105164343355.png]  
6）问题的根源算是找到了，是由于阿里网关内部超时导致，我们服务7：29至7：30大量请求超时。  
7）问题起因算是找到了， 但我们的服务为什么没有，没有对连接做超时断开呢 ？于是我开始看项目代码。

public Map<String, String> send(HttpRequest request) throws ClientException, BusinessException { 
            Stopwatch stopwatch = Stopwatch.createStarted();
            logger.info("Start send http request...");
    
            //设置超时时间，如果request没设置超时时间，取profile里的
            int socketTimeout = request.getSocketTimeout() > 0 ? request.getSocketTimeout() :10000;
            int connectTimeout = request.getConnectTimeout() > 0 ? request.getConnectTimeout() : 10000;
            RequestConfig config = RequestConfig.custom().setSocketTimeout(socketTimeout).setConnectTimeout(connectTimeout)
                    .build();
    
            logger.info("Http request params: uri={}, headers={}, params={} ", request.getUri(),
                    JSONArray.toJSONString(request.getHeaders()), SensitiveUtils.toJson(request.getParamsMap()));
    
            if (logger.isDebugEnabled() && Strings.nullToEmpty(request.getBodyText()).length() > 0) { 
                logger.debug("Http request body is {}", request.getBodyText());
            }
            //请求调用
            CloseableHttpResponse httpResponse;
            if (request.getMethodType() == MethodType.GET) { 
                httpResponse = sendGet(request, config);
            } else if (request.getMethodType() == MethodType.POST) { 
                httpResponse = sendPost(request, config);
            } else { 
                throw new ClientException(ClientErrorCode.METHOD_TYPE_NOT_SUPPORT);
            }
            //校验http状态码
            checkHttpStatus(httpResponse);
            Map<String, String> response = new HashMap<>();
         
            } catch (Exception e) { 
                logger.error("Close the response inputStream error, error={}", e);
                throw new ServerException(ClientErrorCode.CLOSE_RESPONSE_CONTENT_ERROR);
            } finally { 
                try { 
                    httpResponse.close();
                } catch (IOException e) { 
                    logger.error("Close the response error, error={}", e);
                }
                logger.info("Http request response: uri={}, response={}, time={} ", request.getUri(),
                        SensitiveUtils.toJson(response), stopwatch.elapsed(TimeUnit.MILLISECONDS));
            }
    
            return response;
        }

从上面代码看来都有设置SocketTimeout、ConnectTimeout的超时时间，按理我们请求第三方如果超时，就会出现超时。在代码里面我们有打印error日志，但是我在日志系统中查了并无明显的error日志。那说明我们http请求是没有出现异常。  
![在这里插入图片描述][20200105170416206.png]  
8）开始排查为什么我们服务没有异常的原因，我们在日志中看到一直在发请求，但一直没有http返回  
![在这里插入图片描述][20200105170530473.png]  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70 2]

9） 让运维查看了故障节点日志， 也未发现异常，我们用的是docker容器，如果宿主机出现问题，其它服务器也会有异常告警， 说明容器是没有问题的。  
10）通过故障节点堆栈信息分析，http请求导致Tomcat线程池出现了问题。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70 3]  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70 4]  
11）上分析已经明显知道，是由于http请求堆积太多导致，服务线程池飙升，导致节点死机。那问题又回到为为什么大量http请求，堆积后没有超时失败呢 ？然后开始google 发现 apache httpclient 4.5 用连接池技术，新增了一个超时时间设置，默认设置的是-1 ；  
*setConnectionRequestTimeout：设置从connect Manager获取Connection 超时时间，单位毫秒。这个属性是新加的属性，因为目前版本是可以共享连接池的。*  
紧接去看httpclient的源码发现了坑。 获取Connection有判断ConnectionRequestTimeout时间，默认值-1会被设置为0 ，0表示永久不失效。

final HttpClientConnection managedConn;
            try { 
                final int timeout = config.getConnectionRequestTimeout();
                managedConn = connRequest.get(timeout > 0 ? timeout : 0, TimeUnit.MILLISECONDS);
            } catch(final InterruptedException interrupted) { 
                Thread.currentThread().interrupt();
                throw new RequestAbortedException("Request aborted", interrupted);
      }

尴尬，永久不失效，代表的就是：如果没有获取到Connection，线程会一直等待，一直未发送到第三方。这就是我们看到为什么发送日志，是正常的但是，没有返回的Response并且第三方也没有收到请求。

## 三、优化方案 ##

1） 上面已经找到问题， 我开始验证，我的想法。 我先写了一个server端， 并且让所有请求都暂停1分钟，模拟第三方返回延迟 。

AtomicInteger count = new AtomicInteger();
        
        @RequestMapping(path = "/{id}", method = RequestMethod.GET)
        @ResponseBody
        public Coffee getById(@PathVariable Long id) { 
        
           int counts = count.incrementAndGet();
            log.info("counts {}:", counts);
            log.info("request {}:", id);
            try { 
                Thread.sleep(60000);
            }catch (Exception e){ 
                e.printStackTrace();
            }
            Coffee coffee = coffeeService.getCoffee(id);
            return coffee;
        }

2）我用故障服务代码写了一个http请求

public class HttpTimeOutCase { 
         // 用3000个线程模拟并发
        public static void main(String args[]) { 
            for (int i = 0; i < 3000; i++) { 
                try { 
                    R r = new R();
                    System.err.println(r.getName());
                    r.start();
                } catch (Exception e) { 
                    e.printStackTrace();
                }
            }
            System.err.println("finish");
        }
    
        protected static class R extends Thread { 
            @Override
            public void run() { 
                try { 
                    Map<String, String> map = new HashMap<>();
                    String url = "http://localhost:8080/coffee/" + 1;
                    HttpRequest request = new HttpRequest(url, MethodType.GET, map);
                    request.setParamType(ParamType.X_WWW_FORM_URLENCODED);
                    Map<String, String> rspData = HttpClientsInstance.INSTANCE.getInstance().send(request);
                } catch (Exception e) { 
                    e.printStackTrace();
                }
            }
        }
    }

3）我们先试一下没有设置ConnectionRequestTimeout的情况，没有获取到connection的线程一直等待中  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70 5]  
每个请求，都是一个线程，所以看到线程数量最高的时候是2200个，如果是生产环境节点，这个线程数容器肯定死机了。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70 6]  
最后我们消费端将3000个请求都消费掉  
![在这里插入图片描述][20200105183413877.png]  
4）我们试一下设置ConnectionRequestTimeout的情况，没有获取到connection的线程20s后超时  
![在这里插入图片描述][20200105193725578.png]  
处理了400个请求， 其它并发的2600线程在客户端已经超时，现在最大连接数是200，连接超时时间是10s，服务端延迟时间是10s，所以处理了 2\*200条请求。设置获取连接超时时间，可以避免服务死机，但可能导致部分请求失败。  
5）在我们容器中Tomcat线程数默认是1000，所以将ConnectionRequestTimeout设置为50s

## 四、总结 ##

1）整个故障排查的思路不够清晰，导致排查了很久  
2）如果现在重新来排查

1.  查看日志，是否有正常发送http请求
2.  联系第三方排查是否接收到请求
3.  故障节点出现死机的时候，应该联系运维马上重新发布一组服务，优先恢复业务
4.  应该在故障节点上ping /wget 第三方域名,检查网络
5.  用jps 和 jstack 命令查看线程情况
6.  用jmap 导出堆栈信息

[20200105163721531.png]: https://img-blog.csdnimg.cn/20200105163721531.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70]: https://img-blog.csdnimg.cn/20200105164003483.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5,size_16,color_FFFFFF,t_70
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70 1]: https://img-blog.csdnimg.cn/20200105164256600.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5,size_16,color_FFFFFF,t_70
[20200105164343355.png]: https://img-blog.csdnimg.cn/20200105164343355.png
[20200105170416206.png]: https://img-blog.csdnimg.cn/20200105170416206.png
[20200105170530473.png]: https://img-blog.csdnimg.cn/20200105170530473.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70 2]: https://img-blog.csdnimg.cn/20200105170715664.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5,size_16,color_FFFFFF,t_70
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70 3]: https://img-blog.csdnimg.cn/20200105171513767.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5,size_16,color_FFFFFF,t_70
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70 4]: https://img-blog.csdnimg.cn/20200105182650826.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5,size_16,color_FFFFFF,t_70
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70 5]: https://img-blog.csdnimg.cn/20200105180728596.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5,size_16,color_FFFFFF,t_70
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5_size_16_color_FFFFFF_t_70 6]: https://img-blog.csdnimg.cn/20200105181245819.png?x-oss-process=image/watermark,type_ZmFuZ3poZW5naGVpdGk,shadow_10,text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzM2OTE4MTQ5,size_16,color_FFFFFF,t_70
[20200105183413877.png]: https://img-blog.csdnimg.cn/20200105183413877.png
[20200105193725578.png]: https://img-blog.csdnimg.cn/20200105193725578.png