壮美广西经济社会云

一次节点NotReady背后的Docker连接泄露分析

时间：2020-11-04

某一天客户反馈他们Kubernetes集群中的一个节点显示为NotReady状态，运行在该节点的应用实例也发生了漂移。节点NotReady在Kubernetes中是比较常见的一个场景，也是CKA(Certified Kubernetes Administrator)考试中的必考题，对于这个问题的排查需要我们对Kuberntes的节点管理有一定的了解。

如下图所示Kubernetes是一个Master-Slave架构，从节点通过自身的Kublet服务向Master节点的kube-apiserver定时发送心跳，来更新kube-apiserver中node lease或者node status数据，然后Master节点的kube-controller-manager会监听这些数据的变化，如果一个节点的心跳数据长时间没有更新，那么该节点就会被设置为NotReady，并且触发Pod的驱逐。

Kubelet的PLEG

由上可知节点的状态更新涉及多个组件，其中节点的异常、网络异常、ETCD数据库异常、控制组件kube-apiserver与kube-controller-manager异常都可能导致节点NotReady发生。首先，我们从心跳发送的源头，从节点的kubelet服务来开始排查，登录到对应节点，执行top命令查看主机负载，发现CPU负载并不高，内存空余也较多，因此可以判断并不是因为主机的负载高而导致消息发送失败。然后，查看kubelet的日志，发现kubelet服务虽然处于Running状态，但是日志中有PLEG相关的报错。

PLEG is not healthy: pleg was last seen active 4h3m5.30015447s ago;

kubelet报PLEG的状态为"not healthy"，看上去与我们节点的NotReady有很强的相关性，实际也确实如此，PLEG全称是"Pod Lifecycle Event Generator”，如下图kubelet设计图所示，此模块用于从容器运行时(CRI)接口获取运行中的容器信息，记录调度在本机上POD所运行的状态，并生成事件发送给kubelet的SyncLoop，Kubelet利用这些信息与Apiserver中POD的期望状态相对比，来控制节点上的容器创建与删除，是kubelet的一个核心模块。

kubelet会定时执行PLEG，一旦执行失败并且超过了PLEG执行超时时间后，kubelet则会认为PLEG not healthy，从而节点也变成NotReady状态。

Kubelet的容器运行时

由上可知节点的问题是出在PLEG的执行上，PLEG的执行是调用的容器运行时接口(CRI)，因此问题的分析需要继续深入到容器运行时，kubelet支持多种容器运行时，如Docker、Containerd、CRI-O、coreOS Rkt，由于客户的这套环境上线较早已经持续运行多年，kubelet配置的容器运行时是默认的Docker17版本，对于以Docker为CRI的PLEG异常场景，我们以往也处理过多次，通常可能是docker服务卡住或者系统负载太高docker服务响应慢导致PLEG不能及时完成，我们可以用一条命令模拟PLEG的调用来快速判断docker服务是否出现了异常。

time docker ps -a  | grep -v CONTAINER |  awk '{print $1}' | xargs docker inspect

当然也可以先查看docker的日志，通过jounalctl -u docker -f,我们看到了日志正在刷大量的"too many open files"的报错。

从日志中可以看到docker服务的确出现了问题，其所监听unix socket端口在新的客户端连接进来时，已经无法创建新的文件描述符，这也意味着docker基本无法对外提供服务了。为什么出现"too many open files"的报错呢，我们都知道linux系统中的ulimits可以限制某个用户的最大文件打开数，那么是有人误设置这个参数吗，执行ulimit -n命令可以确认此值的大小。

$ ulimit -n 6553500

可以看到系统的文件打开数并没有设置过低，反而相比默认的65535设置已经调高两个数量级。

那么到底打开了多少个docker.socket文件呢，可以先使用lsof命令来获取:

可以看到这个数量还是蛮高的，而且socket文件描述符用于客户端与dockerd服务建立连接时创建，客户端执行完成后，这个连接释放后也会随之关闭才对，因此可以推断是docker.sock文件描述符发生了泄露。

文件描述符的泄露通常对应着协程的泄露，Golang已经提供一个很好的工具go tool pprof,可以查看当前Golang程序的CPU时间片、内存堆、协程栈的使用情况，Docker在很早的版本就加入了pprof的支持，考虑到在用户环境，且我们需要一个更加详细的堆栈输出，我们采取了另外一个更快的方式来获取dockerd进程当前的协程堆栈，即发送一个SIGUSR1信号给dockerd进程，获得一个当前dockerd进程的goroutines堆栈文件。

$ kill -10 $(pidof dockerd)  $ journalctl -u docker -f  level=info msg="goroutine stacks written to /var/run/docker/goroutine-stacks-2020-xx-xxTxxxxxxxx+0800.log"

Dockerd的异常协程

在拿到dockerd进程的协程堆栈文件后，我们可以做一个简单的分析,输出当前正执行同一函数的堆栈数量，此时我们可以看到有个正在执行container.wait的协程数量非常的多，十分可疑:

$ grep '^goroutine' -A 1 docker-goroutines.log |grep docker |awk -F ',' '{print $1","$2","$3}' |sort | uniq -i -c
1 github.com/docker/docker/api/server.(*Server).serveAPI(0xc420092840, 0x5, 0x7)
1 github.com/docker/docker/container.wait(0xc4201db8c0, 0x77359400, 0x2427ca0
32753 github.com/docker/docker/container.wait(0xc4201db8c0, 0xffffffffc4653600, 0x162f9e0
1 github.com/docker/docker/container.wait(0xc420238300, 0x77359400, 0x2427ca0
32756 github.com/docker/docker/container.wait(0xc420238300, 0xffffffffc4653600, 0x162f9e0
1 github.com/docker/docker/daemon.(*Daemon).execCommandGC(0xc420442c00),,
1 github.com/docker/docker/daemon.(*statsCollector).run(0xc420285b80),,
1 github.com/docker/docker/libcontainerd.(*remote).handleConnectionChange(0xc4203b88f0),,
1 github.com/docker/docker/pkg/signal.DumpStacks(0x18fb82e, 0xf, 0x0
1 github.com/docker/docker/pkg/signal.Trap.func1(0xc4202ec780, 0xc42043ebc0),
1 github.com/docker/docker/vendor/github.com/docker/libnetwork.(*controller).watchLoop(0xc42029a000),,
1 github.com/docker/docker/vendor/github.com/docker/libnetwork/osl.removeUnusedPaths(),,
1 github.com/docker/docker/vendor/github.com/tonistiigi/fifo.(*fifo).Read(0xc420476f00, 0xc420556000, 0x8000
1 github.com/docker/docker/vendor/github.com/tonistiigi/fifo.(*fifo).Read(0xc420477080, 0xc42054e000, 0x8000
2 github.com/docker/docker/vendor/github.com/tonistiigi/fifo.OpenFifo.func1(0x0, 0x2441520, 0xc4202851c0
1 github.com/docker/docker/vendor/google.golang.org/grpc.(*addrConn).resetTransport(0xc4200b4840, 0xc4202ec300, 0x0
1 github.com/docker/docker/vendor/google.golang.org/grpc.(*addrConn).wait(0xc4200b4840, 0x24415e0, 0xc49a4bad80

从上面的协程堆栈可以看出来，这是在给某一个容器发送Stop请求，且Stop执行失败，然后转到Kill请求，最终停留在wait函数上。我们首先看wait函数的代码，停留在等待管道的位置，该管道waitChan是由调用函数传入:

// docker/docker/container/state.go:165 func wait(waitChan <-chan struct{}, timeout time.Duration) error { if timeout < 0 { // 卡在此处，等待一个管道 <-waitChan return nil }

然后追踪调用wait的函数，可以发现waitChan是来自容器的State属性中，通过查看代码中的相关调用，我们可以得知，这个管道的是通过收到containerd的容器已停止或重启的消息后会被close掉:

// docker/docker/container/state.go:188
func (s *State) WaitStop(timeout time.Duration) (int, error) {
s.Lock()
if !s.Running {
exitCode := s.ExitCodeValue
s.Unlock()
return exitCode, nil
}
waitChan := s.waitChan
s.Unlock()
if err := wait(waitChan, timeout); err != nil {
return -1, err
}

而此时卡在此处的协程数这么多，可以推断容器的的停止消息并没有返回过来，此时问题会是出现在containerd那边吗？有这种可能，但我们可以先继续分析为何容器stop失败然后执行kill的流程。

// docker/docker/daemon/stop.go:75
func (daemon *Daemon) containerStop(container *container.Container, seconds int) error {　　
// 判断容器是否还在运行
if !container.IsRunning() {
return nil
}
daemon.stopHealthchecks(container)
stopSignal := container.StopSignal()
// 1. Send a stop signal
// 发送一个15信号给容器进程
if err := daemon.killPossiblyDeadProcess(container, stopSignal); err != nil {
......
// 如果容器进程在接收15信号的过程中出现了报错，则等待两秒，看容器是否会变成停止状态，
// 如果容器还是没有停止，则继续发送9信号，强行杀死。
if _, err := container.WaitStop(2 * time.Second); err != nil {
logrus.Infof("Container failed to stop after sending signal %d to the process, force killing", stopSignal)
if err := daemon.killPossiblyDeadProcess(container, 9); err != nil {
return err
}
}
}
// 2. Wait for the process to exit on its own
// 如果上面流程执行完，在此处等待15秒，如果15秒后容器还未停止，则打印容器退出超时,
// 准备强制杀死。
if _, err := container.WaitStop(time.Duration(seconds) * time.Second); err != nil {
logrus.Infof("Container %v failed to exit within %d seconds of signal %d - using the force", container.ID, seconds, stopSignal)
// 3. If it doesn't, then send SIGKILL
// 在此处执行了Kill容器的调用
if err := daemon.Kill(container); err != nil {
container.WaitStop(-1 * time.Second)
logrus.Warn(err)
// Don't return error because we only care that container is stopped, not what function stopped it
}
}
// Kill函数
// daemon/kill.go:147
func (daemon *Daemon) Kill(container *container.Container) error {　　
// 判断容器是否还在运行
if !container.IsRunning() {
return errNotRunning{container.ID}
}
// 1. Send SIGKILL
// 直接对容器进程发送Kill信号
if err := daemon.killPossiblyDeadProcess(container, int(syscall.SIGKILL)); err != nil {
......
// 判断是否kill命令是否返回进程号不存在的错误，此时返回的错误为nil
if isErrNoSuchProcess(err) {
return nil
}
// 如果kill返回的是其他错误，则等待两秒，如果两秒后容器状态还是没变成已停止，则返回超时错误。
if _, err2 := container.WaitStop(2 * time.Second); err2 != nil {
return err
}
}
// 2. Wait for the process to die, in last resort, try to kill the process directly
if err := killProcessDirectly(container); err != nil {
if isErrNoSuchProcess(err) {
return nil
}
return err
}
// 最终协程卡在此处，-1表示无限等待容器的退出状态更新。
container.WaitStop(-1 * time.Second)
return nil
}

那么Stop失败就是此次docker.sock文件描述符的泄露原因吗，我们可以做一个简单的复现测试，在daemon.Stop发送信号之前就将协程挂起，重新编译后在本地的环境中执行docker stop，然后对比连接数和socket文件描述符的增长情况。

# 对一个容器执行700停止命令
$ for i in `seq 700 `; do timeout 1 docker stop bb6fb175f7ef; done
# 检查docker.sock的连接数
$ ss |grep docker.sock |wc -l
704
# 检查docker.sock的文件描述符数量
$ lsof 2>/dev/null |grep /var/run/docker.sock |wc -l
21150
# 再执行一次停止命令，检查连接数和文件描述符的变化
$ docker stop bb6fb175f7ef
$ ss |grep docker.sock |wc -l
705
$ lsof 2>/dev/null |grep /var/run/docker.sock |wc -l
21180

可以看到一个连接数对应着三十个文件描述符，此时统计异常节点的docker服务中强行杀死容器的日志条数，发现与现场的情况基本符合。

$ grep -rn 'trying direct SIGKIL' 54.36-syslog |wc -l 126650

显然，节点的NotReady原因到此逐渐明朗，dockerd进程的socket文件泄露达到最大文件打开数限制导致docker服务异常，最终导致了kubelet执行PLEG失败。但是从上面的代码分析，可以看到社区在停止容这块的逻辑考虑的比较多，加入了各种超时，进程号不存在的情况，以及多次发送15或者9信号来停止容器进程，这主要是考虑到从docker客户端发送停止命令到容器停止以及消息返回中间经过了containerd、containerd-shim、runc等组件，整个流程比较长，会有较多的干扰因素，然而一个容器经过了层层的stop和kill信号，却依然没有停止且容器的PID还一直存在，这显然是不符合常理的。

此时我们想到确实存在给进程发送停止信号成功，返回码为0，其进程号却依然存在的场景，如该进程为内核进程以及处于Z（僵尸进程）或D(不可中断)状态。于是我们再次联系用户，连上异常节点，发现其日志中一直正在停止的容器所对应的PID已经处于了僵尸进程状态。

反思与总结

问题分析到此也解决也比较简单，即在killProcessDirectly函数中加入进程是否为僵尸进程的判断后将socket连接释放即可。

// In case there were some exceptions(e.g., state of zombie and D)
 if system.IsProcessAlive(pid) {

 // Since we can not kill a zombie pid, add zombie check here
 isZombie, err := system.IsProcessZombie(pid)
 if err != nil {
 logrus.Warnf("Container %s state is invalid", stringid.TruncateID(cntr.ID))
 return err
 }
 if isZombie {
 return errdefs.System(errors.Errorf("container %s PID %d is zombie and can not be killed. Use the --init option when creating containers to run an init inside the container that forwards signals and reaps processes", stringid.TruncateID(cntr.ID), pid))
 }
 }

考虑到此问题一直存在于社区中(https://github.com/moby/moby/issues/39407)，并在此issue中引起许多人的讨论(https://github.com/moby/moby/issues/35910)，因此我们也给社区提了一个PR(https://github.com/moby/moby/pull/40749)并合入了Master分支中。当然僵尸进程出现之后也确实难以处理，我们可以考虑使用一些较为稳定的守护进程来管理容器里的进程，比如社区所推荐的tini(https://github.com/krallin/tini)，这样可以避免僵尸进程的产生，给节点运行环境造成其他的影响。