Kubernetes集群Node间歇性NotReady，查到最后竟然是这个原因

被这个问题困扰一段时间了，先后进行了各种假设，然后又一一推翻，最后找到的原因让人很意外。

这里简单记录一下问题的排查过程，然后直接抛答案，如果想了解详细的调查过程、调查过程中的所思所想和走过的弯路，点击「阅读原文」。

出现问题的集群规模不大，总共 200 多个 Node，最早是从 Kubernetes 的事件中发现这个问题的，同事反馈时不时地监听到 NodeNotReady 事件，但是登陆集群查看时 Node 的状态都是  Ready。

一开始忙其它的事情没太在意，后来这种「幽灵式」的 NodeNotReady 越来越频繁，并且持续的时间越来越长，不但触发了报警系统，而且 Node 上的 Pod 也被漂移了，开始着手调查。

线索非常少，检查 kube-controller-manager 的日志，只看到一条 NodeNotReady 的事件日志，在 kubelet 的日志里也翻不到有价值的信息。调整日志级别后，只从 kube-controller-manager 的日志里得知一个事实：

Node 的状态长时间没有得到更新，超过 gracePeriod，被认定为 NotReady。

关键是为什么会延迟？开始胡思乱想，是不是网络不好，会不会 etcd 状态不对，要么是 docker 又 hang 了，还是 Go 的定时器有问题？乱想一气，乱查一通，没啥结论，还是老老实实地捋代码吧。

Kubelet 默认上报频率是 10s 一次，kube-controller-manager 的 gracePeriod 默认是 40s，调整这两个参数只能延缓、掩盖问题，不能解决问题，如果你遇到同样的问题，不要在这些参数上耽误功夫了。

Kubelet 的版本是 1.9.11，这个版本的 kubelet 在向 kbue-apiserver 提交状态信息时，不会打印日志。把添加了几行日志代码的 kubelet 推送到问题集群中，然后把 kube-apiserver 的日志级别调整为 2。这样就有足够的信息来界定问题区间了。

「幽灵式」的 NodeNotReady 非常频繁，早晚不歇，一天好多次，这对调查过程非常有帮助！让我们有足够的案例用来分析，如果是个把月出现一次，那就抓瞎了。

很快从新的案例中收集到足够的信息，把几处日志综合起来看，确定 kubelet 到 kube-apiserver  的通信没有问题，更新请求实时送达了 kube-apiserver，kube-apiserver 收到请求的时间与 kube-controller-manager 中记录的时间也完全匹配。

问题在 kubelet 自身，上一次更新提交完成后，下一次更新很准时地在 10s 后启动（证明 go 的定时器工作正常），但是这次更新却莫名其妙地卡住了！

Github 上有一个 issue，当 kubelet 的 heartBeatClient 建立的连接被对方中断后，kubelet 会 hang。看到这个 issue 时以为找到了答案，出于谨慎，添加了更多的调试日志，再次推送到问题集群，试图拿到更有力的证据。

结果很意外，本来满心认为是 kubelet 通过 heartBeatClient 获取信息或者向 kube-apiserver 提交更新的时候发生了延迟。事实却是，一个 if 判断和两行赋值语句，就耗费了足足了 26s ！匪夷所思：

感觉无法理解，于是又开始瞎想了，难道是 Go 的 gc 有问题？赋值语句耗时如此之长，实在没别的地方可想，翻了翻 Go 的内存模型，内存回收延迟都是毫秒级的，不可能是 gc 的问题。

突然想到之前遇到一个 kubelet 进程被长时间挂起，最后被 kernel 杀死的场景，会不会是 node 的系统有问题给 kubelet 进程按下了暂停键？

用 top 观察 kubelet 进程的状态，发现  wa 时间占比有时候会突然升高到 20%，然后用 iostat 发现根分区磁盘和数据盘的 util 都是 100%，处于过饱和状态，await 时间一度升到 20 多秒！

然后用 pidstat 找到了正在频繁进行 IO 操作的 java 进程，通过向上找父进程的方法找到了它所在的容器。这个容器正在疯狂地吐日志，容器内进程不停地向标准输出写入日志，日志被收集到 container 目录中。

但没有非常直接地证据证明就是这个原因，把运行有这批容器的 node 找出来与发生过 「幽灵」Not Ready 的 node  对比，发现恰好是对应的，所有发生了「幽灵」Not Ready 的 node 上都运行有正在疯狂吐日志的容器，没有运行该容器的 node 没有发生 Not Ready。

联系相关方将写入到标准输出的日志停止，node 磁盘设备的 util 从 100% 降低到接近于 0，「幽灵」Not Ready 也不出现了。

问题的根源其实还没有彻底挖出来，在用 pidstat 查看 io 情况的时候，发现容器狂刷日志时 dockerd 的写操作也很高，是不是两者相互作用才引发的问题？

最近业务回暖，调用量增加日志随之增多，再联想到 docker ps 无响应的事情已经遇到了不止一次两次了，这里估计有戏，找机会再挖一挖。

另外联系业务方调整日志输出也不治本，只不过都是内部系统，规模也不大，比较好协调罢了，需要找一个业务无感知的限制方法。

调查这些问题真是耗时间，其它工作的进度又又又延后了......

这里只是大概叙述一下，完整调查过程见「阅读原文」。

上一篇：以Go的map是否并发安全为例，介绍最权威的Go语言资料的使用方法

关注后加作者微信