共计 7844 个字符，预计需要花费 20 分钟才能阅读完成。
本篇为 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，用户能够在控制台看到降级揭示并不便的进行一键降级。
心愿本篇文章对您有帮忙，谢谢观看！
【腾讯云原生】云说新品、云研新术、云游新活、云赏资讯，扫码关注同名公众号，及时获取更多干货！！
