新闻中心

洞察行业前沿技术,聚焦梯度科技动态

一次节点NotReady背后的Docker连接泄露分析
2020-09-30
文章来源:
作者:屈骏

屈骏,梯度科技核心研发工程师,负责日常集群节点和运行时相关的工作,以及containerd、docker、runc等运行时组件的定制开发和问题排查。



某一天客户反馈他们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的驱逐。

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


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的一个核心模块。

image003.png


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"的报错。

image005.png

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


$ ulimit -n
6553500


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

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

image007.png

可以看到这个数量还是蛮高的,而且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),这样可以避免僵尸进程的产生,给节点运行环境造成其他的影响。



智慧驱动,云领未来

0731-82253717