本篇为Pod Terminating起因追踪系列的第三篇，前两篇别离介绍了两种可能导致Pod Terminating的起因。在解决现网问题时，Pod Terminating属于比拟常见的问题，而本系列的初衷便是记录导致Pod Terminating问题的起因，心愿可能帮忙大家在遇到此类问题时，开辟排查思路。
本篇将再介绍一种造成Pod Terminating的起因，即处理事件流的办法异样退出导致的Pod Terminating，当docker版本在19以下且containerd过程因为各种起因（比方OOM）频繁重启时，会有概率导致此问题产生。对于本文中提到的问题，在docker19中曾经失去解决，但因为docker18无奈间接降级到docker19，且dockerd19修复的改变较大，难以cherry-pick到docker18，因而本文在结尾参考docker19的实现给出了一种简略的解决方案。
Pod Terminating
前一阵有客户反馈应用docker18版本的节点上Pod始终处在Terminating状态，客户通过查看kubelet日志狐疑是Volume卸载失败导致的。景象如下图：
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的起因并非这么简略。
剖析日志及源码
在排除了cbs卸载的问题后，咱们首先想到会不会还是dockerd和containerd状态不统一的问题呢？通过上面两个指令查看了一下容器和task的状态，发现容器的状态是up而task的状态为STOPPED，果然又是状态不统一导致的问题。依照前两篇的教训来看应该是来自containerd的事件在dockerd中没有失去解决或解决的过程阻塞了。
#查看容器状态，看到容器状态为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），如果发现如下有一条堆栈信息：
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事件。
在有了之前的排查教训后，咱们很快猜到会不会是处理事件流的办法processEventStream在解决exit事件的时候产生了阻塞？验证办法很简略，只须要查看堆栈有没有goroutine卡在StreamConfig.Wait()即可，通过搜寻processEventStream堆栈信息发现并没有goroutine卡在Wait办法上，甚至连processEventStream这个处理事件流的办法在堆栈都中也没有找到，阐明事件处理的办法曾经return了！天然也就无奈解决来自containerd的所有事件了。
那么造成processEventStream办法return的具体起因是什么呢？通过查看源码发现，processEventStream中只有在一种状况下会return，即当gRPC连贯返回的谬误可能被解析（ok为true）且返回cancel状态码的时候proceEventStream会return，否则会另起协程递归调用proceEventStream：
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状态码呢？
在查看客户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/…）
解决办法也很简略，在每次递归调用之前sleep 1秒即可，该改变也曾经合进了docker19的代码中。
在后续咱们将推出产品化运行时版本升级修复本篇中提到的bug，用户能够在控制台看到降级揭示并不便的进行一键降级。
心愿本篇文章对您有帮忙，谢谢观看！
【腾讯云原生】云说新品、云研新术、云游新活、云赏资讯，扫码关注同名公众号，及时获取更多干货！！
发表回复