案例详见之CLOSE_WAIT问题排查实战

现象

应用出现告警。

观察程序日志出现大量org.apache.http.conn.ConnectionPoolTimeoutException: Timeout waiting for connection from pool

初步判断是 httpclient 连接池满了导致无法获取新连接。

问题排查

初探

httpclient 连接池满了,首先想到的是某些连接请求时间比较长,并且没有设置合理的超时时间,导致被占满,如果假设成立,则集群中的其它机器也应该会出现这种错误,但是从监控和其它机器的日志看,并没有出现连接池被占满的情况。

换个思路

既然是单台机器的问题,直接登录到机器上观察网络连接,发现大量的连接停留在 CLOSE_WAIT 上,并且网络对端是集群中各个机器,包括这台机器本身,端口是 8080 ,而且数量正好是 200 ,跟代码中 httpclient 配置的连接池最大数量相符,截止到目前,可以断定是由于这些未关闭的连接占满了连接池,所以后续的请求都无法获取连接了。

还有一个点需要注意,每一个 CLOSE_WAIT 的连接中都有 1 个字节的数据未被接收,这一点后续会有说明。 

那 CLOSE_WAIT 什么情况下会产生呢?这就要说到 TCP 的连接和断开,贴个经典的图:

这张图我修改了一下,在断开连接的时候,更符合文章中说的这个 case ,remote 和 local 角色交换了一下,为什么会是这样,我们后面说。

从上图中我们可以看到,CLOSE_WAIT 状态产生的时机,在服务端发送了 FIN 包之后,客户端返回 ACK ,这时候客户端的 TCP 连接就处于 CLOSE_WAIT 状态。然后是这样,那就说明客户端没有发送 FIN 包,也就是没有主动关闭连接。

柳暗花明

既然是代码问题,从监控中找出问题机器产生 CLOSE_WAIT 的时间点,扒一下应用在那个时间点的发布记录,比较幸运,应用的那次发布并没有改动太多,很容易就定位到了问题代码,贴一部分代码:

  1. public void keep(String url) {
  2. log.info("url {}", url);
  3. try {
  4. HttpPost httpPost = new HttpPost(url);
  5. final CloseableHttpResponse response = httpClient.execute(httpPost);
  6. log.info("result:{}", response);
  7. } catch (Exception e) {
  8. log.warn("error", e);
  9. }
  10. }

可以看到代码很简单,就是一个普通的 HTTP 访问,对端返回的是空响应体,状态码是 200 ,看起来一切都很正常。为了验证是否为这段代码引起的,在测试环境手工触发了这段代码,果然会产生 CLOSE_WAIT ,现在可以断定,就是这段代码引起的。

究其原因

既然是客户端未发送 FIN 包,那就是 response 并没有关闭,可以看到,代码中直接打印了 response 后,并没有做任何操作。这也解释了为什么 CLOSE_WAIT 中都会有 1 个字节的数据未被接收,那一个字节的数据应该就是 EOF 。

修复!

既然知道了原因,那需要手动接收 response 中流数据,并将其关闭,代码如下:

  1. public void keep(String url) {
  2. log.info("url {}", url);
  3. try {
  4. HttpPost httpPost = new HttpPost(url);
  5. final CloseableHttpResponse response = httpClient.execute(httpPost);
  6. final HttpEntity entity = response.getEntity();
  7. String resBody = EntityUtils.toString(entity);
  8. log.info("result:{}", resBody);
  9. } catch (Exception e) {
  10. log.warn("error", e);
  11. }
  12. }

这里有一点需要注意,必须要调用 EntityUtils.toString() 方法将 HttpEntity 对象转成字符串,因为关闭流的方法在这里面。贴出来相关的代码:

  1. public static String toString(HttpEntity entity, Charset defaultCharset) throws IOException, ParseException {
  2. Args.notNull(entity, "Entity");
  3. // 获取entity中的流
  4. InputStream instream = entity.getContent();
  5. if (instream == null) {
  6. return null;
  7. } else {
  8. // 此处省略一些代码
  9. Reader reader = new InputStreamReader(instream, charset);
  10. CharArrayBuffer buffer = new CharArrayBuffer(i);
  11. char[] tmp = new char[1024];
  12. int l;
  13. while((l = reader.read(tmp)) != -1) {
  14. buffer.append(tmp, 0, l);
  15. }
  16. String var9 = buffer.toString();
  17. return var9;
  18. } finally {
  19. // 关闭流
  20. instream.close();
  21. }
  22. }
  23. }

改动的代码上线后,问题顺利解决。

扩展阅读

为什么服务端主动关闭连接?

理论上来说,都是客户端主动关闭连接,如果不关闭的话,应该保持 ESTABLISH 状态,为什么 tomcat 会主动断开连接呢?

我们知道 http 协议是无状态的,在 http1.0 的时候,客户端和服务端的连接每次在服务端传输完数据之后就会被关闭,但是看了一下 tomcat 的 server.xml 配置,是 http1.1 协议的,那既然是这样,应该默认是支持长连接,除非客户端在请求头中的 Connection 字段指定了 close ,但是在代码中并没有发现显式的指定。

为了测试,在本地用 Spring boot 创建了一个很简单的 demo ,启动之后,用 http client 客户端访问,依然是模拟出现问题的代码,就是不关闭 response ,发现 TCP 连接一直是 establish 的状态,访问测试服务器上的应用,却可以复现 CLOSE_WAIT ,那问题可能是出现在 tomcat 的配置上,于是乎,仔细翻看 tomcat 的各项配置,终于在 server.xml 里面找到了可疑点。

  1. <Connector port="8080" protocol="HTTP/1.1"
  2. maxThreads="200" connectionTimeout="20000"
  3. enableLookups="false" compression="on"
  4. redirectPort="8443"
  5. URIEncoding="UTF-8"
  6. compressableMimeType="text/csv,text/html,text/xml,text/css,text/plain,text/javascript,application/javascript,application/x-javascript,application/json,application/xml"
  7. />

从 tomcat 的官方文档中可以找到两条配置的说明:

 

因为服务器并没有设置 keepAliveTimeout ,所以采用的就是 connectionTimeout 的配置,也就是 20 秒如果没有请求就会关闭连接,于是乎,把本地创建的 demo 中的 tomcat 设置为 5 秒关闭,再次请求本地的测试代码,不出意外,出现了 CLOSE_WAIT 的连接。

为什么服务端不会有大量FIN_WAIT2的连接?

再回过去看 TCP 的那张图,可以发现,如果客户端在 CLOSE_WAIT 状态,那服务端应该是在 FINWAIT2 状态,从上面的本地 demo 也可以证明这一点,那为什么服务端并没有积压很多这种连接呢?

从服务器的连接历史监控数据可以看到,其它服务端确实会出现 FINWAIT2 状态的 TCP 连接,但是都不会积压很久,系统会回收掉,其实这种 FIN 状态的连接,是通过 Linux 的 TCP 参数配置来设置超时时间的,超过了配置的超时时间,就会被系统回收掉,只需要通过 sysctl 命令设置 net.ipv4.tcpfin_timeout 参数来设置超时回收时间即可,单位是秒,服务端设置的是 30 秒,所以这些 FIN 状态的 TCP 连接会存在最多 30 秒就被系统回收了。

总结

至此,所有问题和疑点都已经解决,通过这次 CLOSE_WAIT 的问题排查,可以总结出来一些套路,大家遇到相关问题的时候,可以按照套路排查问题。

1.CLOSE_WAIT 根本的原因是应用端未关闭一个已经被对端关闭的连接导致,所以我们可以翻看代码中发起 HTTP 请求的地方,如果请求的系统比较多,可以通过 netstat 等相关命令查看 tcp 的对端地址和端口,来辅助查找。

2.找到对应的代码之后,可以看代码的处理逻辑,如果是判断响应码为 200 再进行业务处理的情况,观察如果响应码不为 200 的话,是否有主动关闭流,可以使用 httpRequest.abort() 来关闭,这里可以通过被调用方的 access 日志来辅助判断,如下是一个符合这条 case 的 demo ,首先我们需要一个很简单的 web 服务,只需要返回非 200 的状态码即可,然后模拟未关闭流的情况。

  1. public class HttpClientTest {
  2. private static final CloseableHttpClient HTTP_CLIENT = HttpClientBuilder.create().build();
  3. public static void main(String[] args) throws IOException, InterruptedException {
  4. HttpPost post = new HttpPost("http://localhost:8080/hello/nobody");
  5. if (res.getStatusLine().getStatusCode() == HttpStatus.SC_OK) {
  6. // 进行业务处理...
  7. String result = EntityUtils.toString(res.getEntity());
  8. System.out.println(result);
  9. }
  10. // !!!未对非200的响应做出处理
  11. Thread.sleep(30 * 60 * 1000L);
  12. System.exit(0);
  13. }
  14. }

执行完上述代码,如果 tomcat 设置的 keepAlive 时间比较短的话,就可以从本机看到 CLOSE_WAIT 状态的 TCP 连接了,同样,如果服务端只是返回了 200 的状态码,但是未返回内容,在本机业务处理的时候没有把 Entity 转为 String 的话,即跟本文章中的 case 一样,也会出现 CLOSE_WAIT 状态的 TCP 连接,所以遇到这种情况,需要对非 200 的状态码进行单独的关闭。

3.如果响应码是 200 ,再看业务代码是否处理出现异常,这里的异常包括各种 Exception ,或者多线程导致的各种问题,如未使用线程安全类导致的死循环等,在异常出现的时候,是否有捕获并关闭流,对于线程安全问题导致的死循环,很明显的一个特征就是某个 CPU 核心的使用率是 100% ,可以通过 mpstat 或 top 命令查看出现问题的线程栈。

4.还有一种情况,业务处理和 IO 处理在同一个线程,要注意在处理 IO 的过程中,是否会产生各种异常,或者多线程导致的问题,如未使用线程安全类导致的死循环等,对于异常,可以使用 finally 来关闭流,对于死循环这种问题,明显的一个特征就是某个 CPU 核心的使用率是 100% ,可以通过 mpstat 或 top 命令查看出现问题的线程栈,下面是模拟一个死循环导致未关闭流的情况:

  1. public class HttpClientTest {
  2. private static final CloseableHttpClient HTTP_CLIENT = HttpClientBuilder.create().build();
  3. public static void main(String[] args) throws IOException, InterruptedException {
  4. HttpPost httpPost = new HttpPost("http://localhost:8080/hello/nobody");
  5. CloseableHttpResponse res = HTTP_CLIENT.execute(httpPost);
  6. if (res.getStatusLine().getStatusCode() == HttpStatus.SC_OK) {
  7. // 进行IO处理
  8. InputStream inputStream = res.getEntity().getContent();
  9. Reader reader = new InputStreamReader(inputStream);
  10. CharArrayBuffer buffer = new CharArrayBuffer((int) res.getEntity().getContentLength());
  11. char[] tmp = new char[1024];
  12. int l;
  13. // 这里模拟一个死循环
  14. for (l = reader.read(tmp); l != -1; ) {
  15. buffer.append(tmp, 0, l);
  16. // 这里单纯是为了死循环不要OOM
  17. buffer.clear();
  18. }
  19. // 进行业务处理...
  20. String result = buffer.toString();
  21. System.out.println(result);
  22. }
  23. Thread.sleep(30 * 60 * 1000L);
  24. System.exit(0);
  25. }
  26. }

这段代码是故意模拟的一个死循环,实际代码中有可能是由于非线程安全类导致,由于在处理 IO 过程中产生了死循环,所以没有关闭流,导致系统里面产生了 CLOSE_WAIT 的 TCP 连接,同时,使用 top 观察 cpu 使用情况,可以看到其中一个线程 CPU 使用率 100% ,因为测试代码是单线程,所以直接看到 main 线程是 100% 。

另外,还可以从一些蛛丝马迹中来帮助我们定位问题,比如文章中的这个 case ,所有 CLOSE_WAIT 的未接收数据都是 1 字节,大概率是未主动关闭流导致,如果是不相等的字节数,可能是应用处理到某处出现问题,比如上面提到的异常或死循环等。

未经允许不得转载:大自然的搬运工 » 案例详见之CLOSE_WAIT问题排查实战

赞 (0)

评论 0

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址