【Pod Terminating缘由追踪系列之三】让docker事件处理罢工的cancel状态码

时间  2020-09-14 标签 pod terminating 缘由 追踪 系列 之三 docker 事件 处理 罢工 cancel 状态

本篇为Pod Terminating缘由追踪系列的第三篇，前两篇分别介绍了两种可能致使Pod Terminating的缘由。在处理现网问题时，Pod Terminating属于比较常见的问题，而本系列的初衷即是记录致使Pod Terminating问题的缘由，但愿可以帮助你们在遇到此类问题时，开拓排查思路。git

本篇将再介绍一种形成Pod Terminating的缘由，即处理事件流的方法异常退出致使的Pod Terminating，当docker版本在19如下且containerd进程因为各类缘由（好比OOM）频繁重启时，会有几率致使此问题产生。对于本文中提到的问题，在docker19中已经获得解决，但因为docker18没法直接升级到docker19，且dockerd19修复的改动较大，难以cherry-pick到docker18，所以本文在结尾参考docker19的实现给出了一种简单的解决方案。github

Pod Terminating

前一阵有客户反馈使用docker18版本的节点上Pod一直处在Terminating状态，客户经过查看kubelet日志怀疑是Volume卸载失败致使的。现象以下图：docker

Jul 31 09:53:52 VM_90_48_centos kubelet: E0731 09:53:52.860699     702 plugin_watcher.go:120] error could not find plugin for deleted file /var/lib/kubelet/plugins/kubernetes.io/qcloud-cbs/mounts/disk-o3yxvywa/WTEST.TMP when handling delete event: "/var/lib/kubelet/plugins/kubernetes.io/qcloud-cbs/mounts/disk-o3yxvywa/WTEST.TMP": REMOVE
Jul 31 09:53:52 VM_90_48_centos kubelet: E0731 09:53:52.860717     702 plugin_watcher.go:115] error stat file /var/lib/kubelet/plugins/kubernetes.io/qcloud-cbs/mounts/disk-o3yxvywa/WTEST.TMP failed: stat /var/lib/kubelet/plugins/kubernetes.io/qcloud-cbs/mounts/disk-o3yxvywa/WTEST.TMP: no such file or directory when handling create event: "/var/lib/kubelet/plugins/kubernetes.io/qcloud-cbs/mounts/disk-o3yxvywa/WTEST.TMP": CREATE

经过查看客户Pod的部署状况，发现客户同时使用了in-tree和out-tree的方式挂载cbs，kubelet中的报错是由于在in-tree中检测到了来自out-tree的旁路信息而报错，本质上并不会形成Pod Terminating不掉的问题，看来形成Pod Terminating的缘由并不是这么简单。centos

分析日志及源码

在排除了cbs卸载的问题后，咱们首先想到会不会仍是dockerd和containerd状态不一致的问题呢？经过下面两个指令查看了一下容器和task的状态，发现容器的状态是up而task的状态为STOPPED，果真又是状态不一致致使的问题。按照前两篇的经验来看应该是来自containerd的事件在dockerd中没有获得处理或处理的过程阻塞了。api

#查看容器状态，看到容器状态为up
docker ps | grep <container-id>
#查看task状态，显示task的状态为STOPPED
docker-container-ctr --namespace moby --address var/run/docker/containerd/docker-containerd.sock task ls | grep <container-id>

这里提供一种简单验证方法来验证是否为task事件没有获得处理形成的Pod Terminating，随便起一个容器（例如CentOS），并经过exec进入容器并退出，这时去查看docker的堆栈（发送SIGUSR1信号给dockerd），若是发现以下有一条堆栈信息：bash

goroutine 10717529 [select, 16 minutes]:
github.com/docker/docker/daemon.(*Daemon).ContainerExecStart(0xc4202b2000, 0x25df8e0, 0xc42010e040, 0xc4347904f1, 0x40, 0x7f7ea8250648, 0xc43240a5c0, 0x7f7ea82505e0, 0xc43240a5c0, 0x0, ...)
    /go/src/github.com/docker/docker/daemon/exec.go:264 +0xcb6
github.com/docker/docker/api/server/router/container.(*containerRouter).postContainerExecStart(0xc421069b00, 0x25df960, 0xc464e089f0, 0x25dde20, 0xc446f3a1c0, 0xc42b704000, 0xc464e08960, 0x0, 0x0)
    /go/src/github.com/docker/docker/api/server/router/container/exec.go:125 +0x34b

以后可使用《Pod Terminating缘由追踪系列之二》中介绍的方法，确认一下该条堆栈信息是不是刚刚建立的CentOS容器产生的，固然从堆栈的时间上来看很容易看出来，也能够经过gdb判断ContainerExecStart参数（第二个参数的地址）中的execID是否和CentOS容器的execID相等的方式来确认，经过返回结果发现exexID相等，说明虽然咱们的exec退出了，可是dockerd却没有正确处理来自containerd的exit事件。socket

在有了以前的排查经验后，咱们很快猜到会不会是处理事件流的方法processEventStream在处理exit事件的时候发生了阻塞？验证方法很简单，只须要查看堆栈有没有goroutine卡在StreamConfig.Wait()便可，经过搜索processEventStream堆栈信息发现并无goroutine卡在Wait方法上，甚至连processEventStream这个处理事件流的方法在堆栈都中也没有找到，说明事件处理的方法已经return了！天然也就没法处理来自containerd的全部事件了。post

那么形成processEventStream方法return的具体缘由是什么呢？经过查看源码发现，processEventStream中只有在一种状况下会return，即当gRPC链接返回的错误可以被解析（ok为true）且返回cancel状态码的时候proceEventStream会return，不然会另起协程递归调用proceEventStream：spa

case err = <-errC:
    if err != nil {
        errStatus, ok := status.FromError(err)
        if !ok || errStatus.Code() != codes.Canceled {
            c.logger.WithError(err).Error("failed to get event")
            go c.processEventStream(ctx)
        } else {
            c.logger.WithError(ctx.Err()).Info("stopping event stream following graceful shutdown")
        }
    }
    return

那么为何gRPC链接会返回cancel状态码呢？3d

在查看客户docker日志时发现containerd在以前不断的被kill并重启，持续了大概11分钟左右：

#日志省略了部份内容
Jul 29 19:23:09 VM_90_48_centos dockerd[11182]: time="2020-07-29T19:23:09.037480352+08:00" level=error msg="containerd did not exit successfully" error="signal: killed" module=libcontainerd
Jul 29 19:24:06 VM_90_48_centos dockerd[11182]: time="2020-07-29T19:24:06.972243079+08:00" level=info msg="starting containerd" revision=e6b3f5632f50dbc4e9cb6288d911bf4f5e95b18e version=v1.2.4
Jul 29 19:24:52 VM_90_48_centos dockerd[11182]: time="2020-07-29T19:24:52.643738767+08:00" level=error msg="containerd did not exit successfully" error="signal: killed" module=libcontainerd
Jul 29 19:25:02 VM_90_48_centos dockerd[11182]: time="2020-07-29T19:25:02.116798771+08:00" level=info msg="starting containerd" revision=e6b3f5632f50dbc4e9cb6288d911bf4f5e95b18e version=v1.2.4

查看系统日志文件（/var/log/messages）看下为何containerd会被不断地重启：

#日志省略了部份内容
Jul 29 19:23:09 VM_90_48_centos kernel: Memory cgroup out of memory: Kill process 15069 (docker-containe) score 0 or sacrifice child
Jul 29 19:23:09 VM_90_48_centos kernel: Killed process 15069 (docker-containe) total-vm:51688kB, anon-rss:10068kB, file-rss:324kB
Jul 29 19:24:52 VM_90_48_centos kernel: Memory cgroup out of memory: Kill process 12411 (docker-containe) score 0 or sacrifice child
Jul 29 19:24:52 VM_90_48_centos kernel: Killed process 5836 (docker-containe) total-vm:1971688kB, anon-rss:22376kB, file-rss:0kB

能够发现containerd被kill是因为OOM致使的，那么会不会是由于containerd的不断重启致使gRPC返回cancel的状态码呢。先查看一下重启containerd这部分的逻辑：

在启动dockerd时，会建立一个独立的到containerd的gRPC链接，并启动一个monitor协程基于该gRPC链接对containerd的服务作健康检查，monitor每隔500ms会对到containerd的grpc链接作健康检查并记录失败的次数，若是发现gRPC链接返回状态码为UNKNOWN或者NOT_SERVING时对失败次数加一，当失败次数大于域值（域值为3）而且containerd进程已经down掉（经过向进程发送信号进行判断），则会重启containerd进程，并执行reconnect重置dockerd和containerd之间的gRPC链接，在reconnect的逻辑中，会先close旧的gRPC链接，以后新建一条新的gRPC链接：

// containerd/containerd/client.go
func (c *Client) Reconnect() error {
    ....
    // close掉旧的链接
    c.conn.Close()
    // 创建新的链接
    conn, err := c.connector()
    ....
    c.conn = conn
    return nil
}
connector := func() (*grpc.ClientConn, error) {
    ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second)
    defer cancel()
    conn, err := grpc.DialContext(ctx, dialer.DialAddress(address), gopts...)
    if err != nil {
        return nil, errors.Wrapf(err, "failed to dial %q", address)
    }
    return conn, nil
}

因为reconnect会先close旧链接，那么会不会是close形成的gRPC返回cancel呢？能够写一个简单的demo验证一下，服务端和客户端之间经过unix socket链接，客户端订阅服务端的消息，服务端不断地publish消息给客户端，客户端每隔一段时间close一次gRPC链接，获得的结果以下：

从结果中发如今unix socket下客户端close链接是有几率致使grpc返回cancel状态码的，那么具体什么状况下会产生cancel状态码呢？经过查看gRPC源码发现，当服务端在发送事件过程当中，客户端close了链接则会使服务端返回cancel状态码，若此时服务端没有发送事件，则会返回图中的transport is closing错误，至此，问题已经基本定位了，颇有多是客户端close了gRPC链接致使服务端返回了cancel状态码，使processEventStream方法return，致使来自containerd的事件流没法获得处理，最终致使dockerd和containerd的状态不一致。但因为客户的日志级别较高，咱们无法从中得到问题产生时的具体时序，所以但愿经过调低日志级别复现问题来定位具体在什么状况下会产生这个问题。

问题复现

这个问题复现起来比较简单，只须要模仿客户产生问题时的状况，不断重启containerd进程便可。在docker18.06.3-ce版本集群下建立一个Pod，咱们经过下面的脚本不断kill containerd进程：

#!/bin/bash  
for i in $(seq 1 1000)
do
process=`ps -elf | grep  "docker-containerd --config /var/run/docker/containerd/containerd.toml"| grep -v "grep"|awk '{print $4}'`
if [ ! -n "$process" ]; then
  echo "containerd not running"  
else
  echo $process;
  kill -9 $process;
fi
sleep 1;
done

运行上面的脚本便有概率复现该问题，以后删除Pod并查看Pod状态，发现Pod会一直卡在Terminating状态。

查看容器状态和task状态，发现和客户问题的现象彻底一致：

因为咱们调低了日志级别，查看日志发现下面这样一条日志，而这条日志只有processEventStream方法return时才会打印，且打印日志后processEventStream方法当即return，所以能够肯定问题的根本缘由就是processEventStream收到了gRPC返回的cancel状态码致使方法return，以后的来自containerd的事件没法获得处理，最终出现dockerd和containerd状态不一致的问题。

Aug 13 15:23:16 VM_1_6_centos dockerd[25650]: time="2020-08-13T15:23:16.686289836+08:00" level=info msg="stopping event stream following graceful shutdown" error="<nil>" module=libcontainerd namespace=moby

问题定位

经过分析docker日志，能够了解到docker18具体在什么状况下会产生processEventStream return的问题，下图是会致使processEventStream return的时序图：

经过该时序图可以看出问题所在，首先当containerd进程被kill后，monitor经过健康检查，发现containerd进程已经中止，便会经过cmd从新启动containerd进程，并从新链接到contaienrd，若是processEventStream在reconnect以前使用旧的gRPC链接成功，订阅到containerd的事件，那么在reconnect时会close这条旧链接，而若是刚好在这时containerd在传输事件，那么该gRPC链接就会返回一个cancel的状态码给processEventStream方法，致使processEventStream方法return。

修复与反思

此问题产生的根本缘由在于reconnect的逻辑，在重启时没法保证reconnect必定在processEventStream的subscribe以前发生。因为processEventStream会递归调用自动重连，所以实际上并不须要reconnect，在docker19中也已经修复了这个问题，且没有reconnect，可是docker19这部分改动较大，没法cherry-pick到docker18，所以咱们能够参考docker19的实现修改docker18代码，只须要将reconnect的逻辑去除便可。

另外在修复时顺便修复了processEventStream方法不断递归致使瞬间产生大量日志的问题，因为subscribe失败之后会不断地启动协程递归调用，所以会在瞬间产生大量日志，在社区也有人已经提交过PR解决这个问题。（https://github.com/moby/moby/pull/39513）

解决办法也很简单，在每次递归调用以前sleep 1秒便可，该改动也已经合进了docker19的代码中。

在后续咱们将推出产品化运行时版本升级修复本篇中提到的bug，用户能够在控制台看到升级提醒并方便的进行一键升级。

但愿本篇文章对您有帮助，谢谢观看！

【腾讯云原生】云说新品、云研新术、云游新活、云赏资讯，扫码关注同名公众号，及时获取更多干货！！

联系我们 沪ICP备13005482号-10