一、背景

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

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

二、分析过程

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

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

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

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

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

三、开始复现

在和租户一起复现的过程中，我们注意到一个问题，就是在 K8S 平台的该业务容器对应的控制台看不到业务日志输出了，这个信息很关键。这时执行 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，这个主要是在 docker 写日志到日志驱动中时，开启了 tty，而 tty 是通过 signalRead() 及 signalWrite() 函数来通知 tty console 当前是否可以读写。在这个过程中，由于都需要等待 Signal 信号来判断是否可读写（通过调用 Signal() 函数来获取），我们不难看出 Signal 已经成为了一个竞争资源，有经验的开发者马上能看出这里有问题了，没错！需要提前加锁以防资源竞争产生。

所以，是由于我们在部署容器时开启了 tty，长条日志触发了该 bug。我们都知道，tty 默认是关闭的。这时我们对比了公司内部的 Docker Swarm 平台，发现在该平台上也是关闭 tty 的，所以解释了为什么在 K8S 平台出现 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 时才临时分配一个用于交互。

欢迎关注我的微信公众号