单条日志过长引发的 CLOSE-WAIT 问题

标签: 日志 close wait | 发表时间:2020-06-23 01:22 | 作者:玻璃樽
出处:http://weekly.dockone.io

背景

部分租户称他们的某个业务部署在 Kubernetes 容器平台后经常会重启,部分租户称另一个业务在运行一段时间时会产生大量的 CLOSE-WAIT,还有的就是业务跑着就会 hang 住。

其实这三个问题,经过我们排查后,都是同一个问题引起,这也是我今天要分享的主题内容。

分析过程

大家都知道,重启我们不好查,因为原因太多了,比如:容器分配的内存不够会重启,运行中程序内存泄漏到将内存耗尽会重启;在 Kubernetes 中配置了容器运行时健康检查时,如果条件未达到会重启等等;总之不好排查。

那如果这三个问题有关联的话,那么会不会是服务 hang 住了触发了其他两个?即 hang 住了,服务自然没法响应客户端的关闭连接,此时就会产生 CLOSE-WAIT;另外,如果 hang 住了,而业务在 Kubernetes 平台又配置了 live probe 保活机制,那么就会触发容器自动重启。这么看来,我们首要解决的就是 CLOSE-WAIT 问题,也是我们比较好入手的地方。

当然,也可能由于 CLOSE-WAIT 过多,耗尽了分配的端口或者文件句柄或者产生了过高的 CPU 消耗,导致业务作为服务端响应过慢,就像被 hang 住一样?这个好排查,只要看下当前的容器中句柄数使用量及总量或者查看一下容器日志是否会报端口被占用及相关异常信息,甚至查看容器过往及当前的 CPU、内存资源使用情况等等,就可以排除这种情况。

所以,我们先从 CLOSE-WAIT 这个问题着手。这个问题其实有一年左右的时间了,之前排查下来,一般是服务端在处理 TCP 四次挥手过程中不恰当引起,因此业务代码修改后,就可以解决。但现在我们这个租户反馈,同样的容器镜像在我们公司内部的另一个 Docker Swarm 平台不会出现,在 Kubernetes 平台却时有发生。这个信息很重要,说明可能不是代码本身的问题,所以我们决定深入排查这个问题。

CLOSE-WAIT 有很多原因引起,有可能是服务端代码处理 TCP 挥手不合理引起,比如忘记了 close 相应的 socket 连接,那么自然不会发出 FIN 包;还比如出现死循环之类的问题,导致 close 最后没有被调用执行;还有可能是服务端程序响应过慢,或者存在耗时逻辑,导致 close 延后;也可能是 accept 的 backlog 设置的太大,导致服务端来不及消费的情况,引起多余的请求还在队列里就被对方关闭了。还有可能是内核参数配置没有做优化处理,比如调整 tcp_keepalive_time / tcp_keepalive_intvl / tcp_keepalive_probes 等, (这种情况治标不治本)。林林总总,但我们这里的情况都不是。

开始复现

在和租户一起复现的过程中,我们注意到一个问题,就是在 Kubernetes 平台的该业务容器对应的控制台看不到业务日志输出了,这个信息很关键。这时执行 ss -ant 查看发现 CLOSE-WAIT 在不断的增加,而此前在日志正常输出时,只会产生少量 CLOSE-WAIT,所以我们断定是业务挂了引起了 CLOSE-WAIT 的增加。

构造测试程序

由于是租户的业务并在生产环境,所以为了证实这个问题,我们还编写了 Java 测试程序来模拟这种情况,即不断的输出日志的同时暴露服务的某个可供客户端查询的 API 接口,这样可以在复现问题时,查看该接口是否还能正常响应。结果确实没有响应了,因此证明了是服务挂死引起了 CLOSE-WAIT

另外,我们也注意到一个非常关键的信息,就是业务的单条日志太长了,目测单行有上万个字符(当然租户日志在生产中输出这么 多日志,本身就很不科学,正是这种不科学,才给了我们排查这个问题的机会!),所以我们让租户把日志输出关闭后,重新压测两天后,并没有产生 CLOSE-WAIT,到这里我们基本断定了和日志输出有关了。

接下来,我们构造测试日志,一种是不断的输出日志,但单条长度限制在 1 万个字符内。另外一种是不断的在前一行基础上追加一个字符,并输出每行字符总数,为的是想知道单条字符在超过多少时才会 hang 死,这个测试脚本如下:
docker run -t busybox /bin/sh -c 's="a"; while true; do echo $s | wc -c; echo $s; s="a$s"; done'  

测试结果分析

经过测试发现,大概单条日志在 2 万 ~ 3 万 的时候就会出现日志不输出的情况,也就是业务挂死了。至此,我们就把方向缩小到了单条日志长度问题上了。这时再通过 Google 就容易找到有效信息了,发现 Docker 社区也报了这个问题 Logging long lines breaks container,从其中的描述来看,完全和我们产线中遇到的一样。

至此,问题我们定位出来了。root cause 是 tty 的一个 bug,目前只在 docker-ce.18.06 这个版本中得到了修复,详见 console_linux: Fix race: lock Cond before Signal. #27,这个主要是在 Docker 写日志到日志驱动中时,开启了 tty,而 tty 是通过 signalRead() 及 signalWrite() 函数来通知 tty console 当前是否可以读写。在这个过程中,由于都需要等待 Signal 信号来判断是否可读写(通过调用 Signal() 函数来获取),我们不难看出 Signal 已经成为了一个竞争资源,有经验的开发者马上能看出这里有问题了,没错!需要提前加锁以防资源竞争产生。

所以,是由于我们在部署容器时开启了 tty,长条日志触发了该 bug。我们都知道,tty 默认是关闭的。这时我们对比了公司内部的 Docker Swarm 平台,发现在该平台上也是关闭 tty 的,所以解释了为什么在 Kubernetes 平台出现 CLOSE-WAIT 的原因了。

最后,我们可以通过升级 docker-ce 的版本到特定的 docker-ce.18.06 版本(其他版本还没有 cherry-pick 过来,比如 docker-ce 19.x 后的版本该bug依旧存在),或者关闭 tty,即在创建容器时,tty=false 就可以了。具体可以在用 deployment 部署了业务后,通过 docker inspect | grep Tty 来查看该业务容器是否开启。

后记

在容器部署的时候 tty 的开启是没有必要的,也就是不需要分配 tty 资源给容器,因为我们不需要交互。只有在我们需要交互的使用场景,比如向控制台输入某些命令,需要容器给我们输出时,才加上 -t 即可,比如 docker exec -it xxxx sh 或者 kubectl exec -it xxx -- sh 时才临时分配一个用于交互。

相关 [日志 close wait] 推荐:

单条日志过长引发的 CLOSE-WAIT 问题

- - DockOne.io
部分租户称他们的某个业务部署在 Kubernetes 容器平台后经常会重启,部分租户称另一个业务在运行一段时间时会产生大量的 CLOSE-WAIT,还有的就是业务跑着就会 hang 住. 其实这三个问题,经过我们排查后,都是同一个问题引起,这也是我今天要分享的主题内容. 大家都知道,重启我们不好查,因为原因太多了,比如:容器分配的内存不够会重启,运行中程序内存泄漏到将内存耗尽会重启;在 Kubernetes 中配置了容器运行时健康检查时,如果条件未达到会重启等等;总之不好排查.

wait、sleep、yield区别

- - CSDN博客推荐文章
1、属于Object的本地方法. 2、暂停当前线程,并释放锁. 3、调用notify()或notifyAll()方法唤醒线程. 1、Thread类的静态方法. 2、当前线程休眠,但不释放锁. 3、其他线程可以继续执行,无论该线程优先级高与否. 4、休眠一段时间后,自动执行. 1、Thread类的静态方法.

Java多线程之wait()和notify()

- - CSDN博客推荐文章
直接看测试代码吧,细节之处,详见注释.  * Java多线程之wait()和notify()的妙用 .  * @see 问题:同时启动两个线程和同时启动四个线程,控制台打印结果是不同的 .  * @see      同时启动两个线程时,控制台会很规律的输出1010101010101010 .  * @see      同时启动四个线程时,控制台起初会规律的输出10101010,一旦某一刻输出一个负数,那么后面的输出就会"一错再错" .

java多线程设计wait/notify机制

- - CSDN博客推荐文章
  当线程A获得了obj锁后,发现条件condition不满足,无法继续下一处理,于是线程A就wait() , 放弃对象锁..   之后在另一线程B中,如果B更改了某些条件,使得线程A的condition条件满足了,就可以唤醒线程A:.   # 调用obj的wait(), notify()方法前,必须获得obj锁,也就是必须写在synchronized(obj) {…} 代码段内.

Java多线程之wait和notify

- - ITeye博客
最近在看Java特种兵,看到多线程部分,对wait和notify不是很理解,于是写了代码来帮助理解.              wait方法通过参数可以指定等待的时长. 如果没有指定参数,默认一直等待直到被通知. notify方法是通知某个正在等待这个对象的控制权的线程可以继续运行. 调用wait方法时候,必须加上synchronized同步块,不然会抛出java.lang.IllegalMonitorStateException异常.

Java Sleep() 与 Wait()的机制原理与区别

- - CSDN博客推荐文章
Java中的多线程是一种抢占式的机制而不是分时机制. 线程主要有以下几种状态:可运行,运行,阻塞,死亡. 抢占式机制指的是有多个线程处于可运行状态,但是只有一个线程在运行.        当有多个线程访问共享数据的时候,就需要对线程进行同步.        Thread类的方法:sleep(),yield()等.

[转载]java之yield(),sleep(),wait()区别详解

- - 移动开发 - ITeye博客
使当前线程(即调用该方法的线程)暂停执行一段时间,让其他线程有机会继续执行,但它并不释放对象锁. 也就是说如果有synchronized同步快,其他线程仍然不能访问共享数据. 例如有两个线程同时执行(没有synchronized)一个线程优先级为MAX_PRIORITY,另一个为MIN_PRIORITY,如果没有Sleep()方法,只有高优先级的线程执行完毕后,低优先级的线程才能够执行;但是高优先级的线程sleep(500)后,低优先级就有机会执行了.

最简实例说明wait、notify、notifyAll的使用方法

- - Java - 编程语言 - ITeye博客
wait()、notify()、notifyAll()是三个定义在Object类里的方法,可以用来控制线程的状态. 这三个方法最终调用的都是jvm级的native方法. 随着jvm运行平台的不同可能有些许差异. •如果对象调用了wait方法就会使持有该对象的线程把该对象的控制权交出去,然后处于等待状态.

日志管理

- - CSDN博客系统运维推荐文章
#很关键 [root@client01 ~]# ls /var/log/ anaconda.ifcfg.log. tallylog #关键日志,大部分记录在里面 [root@client01 ~]# ls /var/log/messages /var/log/messages. [root@client01 ~]# ps -ef|grep log #系统日志服务 root.

日志优化

- - 互联网 - ITeye博客
在任何系统中,日志都是非常重要的组成部分,它是反映系统运行情况的重要依据,也是排查问题时的必要线索. 绝大多数人都认可日志的重要性,但是又有多少人仔细想过该怎么打日志,日志对性能的影响究竟有多大呢. 今天就让我们来聊聊Java日志性能那些事. 说到Java日志,大家肯定都会说要选择合理的日志级别、合理控制日志内容,但是这仅是万里长征第一步……哪怕一些 DEBUG级别的日志在生产环境中不会输出到文件中,也可能带来不小的开销.