关于腾讯云:Pod-Terminating原因追踪系列之二exec连接未关闭导致的事件阻塞

7次阅读

共计 6124 个字符，预计需要花费 16 分钟才能阅读完成。

前一阵有客户 docker18.06.3 集群中呈现 Pod 卡在 terminating 状态的问题，通过排查发现是 containerd 和 dockerd 之间事件流阻塞，导致后续事件得不到解决造成的。

定位问题的过程极其艰巨，其中不乏大量工具的应用和大量的源码浏览。本文将梳理排查此问题的过程，并总结残缺的 dockerd 和 contaienrd 之间事件传递流程，一步一步找到问题产生的起因，特写本文记录分享，心愿大家在有相似问题产生时，可能迅速定位、解决。

对于本文中提到的问题，在 docker19 中曾经失去解决，但 docker18 无奈间接降级到 docker19，因而本文在结尾参考 docker19 给出了一种简略的解决方案。

置信大家在解决现网问题时，常常会遇到 Pod 卡在 terminating 不动的状况，产生这种状况的起因有很多，比方《Pod Terminating 起因追踪系列之一》中提到的 containerd 没有正确处理错误信息，当然更常见的比方 umount 失败、dockerd 卡死等等。

遇到此类问题时，通常通过 kubelet 或 dockerd 日志、容器和 Pod 状态、堆栈信息等伎俩来排查问题。本问题也不例外，首先登录到 Pod 所在节点，应用以下两条指令查看容器状态：

# 查看容器状态，看到容器状态为 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>

能够看到在 dockerd 中容器状态为 up，但在 containerd 中 task 状态为 STOPPED，两者信息产生了不统一，也就是说因为某种原因 containerd 中的状态信息没有同步到 dockerd 中，为了探索为什么两者状态产生了不统一，首先须要理解从 dockerd 到 containerd 的整体调用链：

当启动 dockerd 时，会通过 NewClient 办法创立一个 client，该 client 保护一条到 containerd 的 gRPC 连贯，同时起一个协程 processEventStream 订阅（subscribe）来自 containerd 的 task 事件，当某个容器的状态发生变化产生了事件，containerd 会返回事件到 client 的 eventQ 队列中，并通过 ProcessEvent 办法进行解决，processEventStream 协程在除优雅退出以外永远不会退出（但在有些状况下还是会退出，在后续会推出一篇文章，恰好是这种状况，敬请期待~）。

当容器过程退出时，containerd 会通过上述 gRPC 连贯返回一个 exit 的 task 事件给 client，client 接管到来自 containerd 的 exit 事件之后由 ProcessEvent 调用 DeleteTask 接口删除对应 task，至此实现了一个容器的删除。

因为 containerd 始终处于 STOPPED 状态，因而通过下面的调用链猜想会不会是 task exit 事件因为某种原因而阻塞掉了？产生的后果就是在 containerd 侧因为发送了 exit 事件而进入 STOPPED 状态，但因为没有调用 DeleteTask 接口，因而本 task 还存在。

通过发送 task exit 事件给一个卡住的 Pod，来模仿容器完结的状况：

/tasks/exit {"container_id":"23bd0b1118238852e9dec069f8a89c80e212c3d039ba030cfd33eb751fdac5a7","id":"23bd0b1118238852e9dec069f8a89c80e212c3d039ba030cfd33eb751fdac5a7","pid":17415,"exit_status":127,"exited_at":"2020-07-17T12:38:01.970418Z"}

咱们能够手动将上述事件 publish 到 containerd 中，然而须要留神的一点的是，在 publish 之前须要将上述内容进行一下编码（参考 containerd/cmd/containerd-shim/main_unix.go Publish 办法）。失去的后果如下图，能够看到事件胜利的被 publish，也被 dockerd 捕捉到，但容器的状态依然没有变动。

# 将 file 文件中的事件发送到 containerd
docker-containerd --address var/run/docker/containerd/docker-containerd.sock publish --namespace moby --topic /tasks/exit < ~/file

当咱们查看 docker 堆栈日志（向 dockerd 过程发送 SIGUSR1 信号），发现有大量的 Goroutine 卡在 append 办法，每次 publish 新的 exit 事件都会减少一个 append 办法的堆栈信息：

通过查看 append 办法的源码发现，append 办法负责将收到的 containerd 事件放入 eventQ，并执行回调函数，对收到的不同类型事件进行解决：

func (q *queue) append(id string, f func()) {q.Lock()
    defer q.Unlock()
    if q.fns == nil {q.fns = make(map[string]chan struct{})
    }
    done := make(chan struct{})
    fn, ok := q.fns[id]
    q.fns[id] = done
    go func() {
        if ok {<-fn}
        f()
        close(done)
        q.Lock()
        if q.fns[id] == done {delete(q.fns, id)
        }
        q.Unlock()}()}

形参中的 id 为 container 的 id，因而对于同一个 container 它的事件是串行解决的，只有前一个事件处理完结才会解决下一个事件，且没有超时机制。

因而只有 eventQ 中有一个事件产生了阻塞，那么在它前面所有的事件都会被阻塞住。这也就解释了为什么每次 publish 新的对于同一个 container 的 exit 事件，都会在堆栈中减少一条 append 的堆栈信息，因为它们都被之前的一个事件阻塞住了。

为了找到阻塞的起因，咱们找到阻塞的第一个 exit 事件 append 的堆栈信息再具体的看一下：

通过堆栈能够发现代码卡在了 docker/daemon/monitor.go 文件的 123 行（省略了不重要的代码）：

func (daemon *Daemon) ProcessEvent(id string, e libcontainerd.EventType, ei libcontainerd.EventInfo) error {
    ......
    case libcontainerd.EventExit:
        ......
        if execConfig := c.ExecCommands.Get(ei.ProcessID); execConfig != nil {
            ......
123 行        execConfig.StreamConfig.Wait()
            if err := execConfig.CloseStreams(); err != nil {logrus.Errorf("failed to cleanup exec %s streams: %s", c.ID, err)
            }
            ......
        } else {......}
    ......
    return nil
}

能够看到收到的事件为 exit 事件，并在第 123 行 streamConfig 在期待一个 wg，这里的 streamconfig 为一个内存队列，负责收集来自 containerd 的输入返回给客户端，具体是如何解决 io 的在前面会细讲，这里先顺藤摸瓜查一下 wg 在什么时候 add 的：

func (c *Config) CopyToPipe(iop *cio.DirectIO) {copyFunc := func(w io.Writer, r io.ReadCloser) {c.Add(1)
        go func() {if _, err := pools.Copy(w, r); err != nil {logrus.Errorf("stream copy error: %v", err)
            }
            r.Close()
            c.Done()}()}
    if iop.Stdout != nil {copyFunc(c.Stdout(), iop.Stdout)
    }
    if iop.Stderr != nil {copyFunc(c.Stderr(), iop.Stderr)
    }
    .....
}

CopyToPipe 是用来将 containerd 返回的输入 copy 到 streamconfig 的办法，能够看到当来自 containerd 的 io 流不为空，则会对 wg add1，并开启协程进行 copy，copy 完结后才会 done，因而一旦阻塞在 copy，则对 exit 事件的解决会始终期待 copy 完结。咱们再回到 docker 堆栈中进行查找，发现的确有一个 IO wait，并阻塞在 polls.Copy 函数上：

至此造成 dockerd 和 containerd 状态不统一的起因曾经找到了！咱们来梳理一下。

首先通过查看 dockerd 和 containerd 状态，发现两者状态不统一。因为 containerd 处于 STOPPED 状态因而判断在 containerd 发送 task exit 事件时可能产生阻塞，因而咱们结构了 task exit 事件并 publish 到 containerd，并查看 docker 堆栈发现有大量阻塞在 append 的堆栈信息，证实了咱们的猜测。

最初咱们通过剖析代码和堆栈信息，最终定位在 ProcessEvent 因为 pools.Copy 的阻塞，也会被阻塞，直到 copy 完结，而事件又是串行解决的，因而只有有一个事件处理被阻塞，那么前面所有的事件都会被阻塞，最终体现出的景象就是 dockerd 和 containerd 状态不统一。

咱们曾经晓得了阻塞的起因，然而到底是什么操作阻塞了事件的解决？其实很简略，此 exit 事件是由 exec 退出产生的，咱们通过查看堆栈信息，发现在堆栈有为数不多的 ContainerExecStart 办法，阐明有 exec 正在执行，揣测是客户行为：

ContainerExecStart 办法中第二个参数为 exec 的 id 值，因而能够应用 gdb 查找对应地址内容，查看其参数中的 execId 和 terminating Pod 中的容器的 exexId（docker inspect 能够查看 execId，每个 exec 操作对应一个 execId）是否统一，后果发现 execId 雷同！因而能够判定是因为 exec 退出，产生的 exit 事件阻塞了 ProcessEvent 的解决逻辑，通过浏览源码总结出 exec 的解决逻辑：

那么为什么 exec 的 exit 会导致 Write 阻塞呢？咱们须要梳理一下 exec 的 io 解决流程看看到底 Write 到了哪里。下图为 io 流的处理过程：

首先在 exec 开始时会将 socket 的输入流 attach 到一个内存队列，并启动了⼀个 goroutine 用来把内存队列中的内容输入到 socket 中，除了内存队列外还有一个 FIFO 队列，通过 CopyToPipe 开启协程 copy 到内存队列。FIFO 队列用来接管 containerd-shim 的输入，之后由内存队列写入 socket，以 response 的形式返回给客户端。但咱们的问题还没有解决，还是不分明为什么 Write 会阻塞住。不过能够通过 gdb 来定位到 Write 函数关上的 fd，查看一下 socket 的状态：

n, err := syscall.Write(fd.Sysfd, p[nn:max])
type FD struct {
    // Lock sysfd and serialize access to Read and Write methods.
    fdmu fdMutex
    // System file descriptor. Immutable until Close.
    Sysfd int
    ......
}

Write 为零碎调用，其参数中第一位即关上的 fd 号，但须要留神，Sysfd 并非 FD 构造体的第一个参数，因而须要加上偏移量 16 字节（fdMutex 占 16 字节）

发现该 fd 为一个 socket 连贯，应用 ss 查看一下 socket 的另一端是谁：

发现该 fd 为来自 kubelet 的一个 socket 连贯，且没有被敞开，因而能够判断 Write 阻塞的起因正是客户端 exec 退出当前，该 socket 没有失常的敞开，使 Write 一直地向 socket 中写数据，直到写满阻塞造成的。

通过询问客户是否应用过 exec，发现客户本人写了一个客户端并通过 kubelet exec 来拜访 Pod，与上述排查后果相符，因而反馈客户能够排查下客户端代码，是否正确敞开了 exec 的 socket 连贯。

其实 docker 的这个事件处理逻辑设计并不优雅，客户端的行为不应该影响到服务端的解决，更不应该造成服务端的阻塞，因而本打算提交 pr 修复此问题，发现在 docker19 中曾经修复了此问题，而 docker18 的集群无奈间接降级到 docker19，因为 docker 会长久化数据到硬盘上，而 docker19 不反对 docker18 的长久化数据。

尽管不能间接降级到 docker19，不过咱们能够参考 docker19 的实现，在 docker19 中通过增加事件处理超时的逻辑防止事件始终阻塞，在 docker18 中同样能够增加一个超时的逻辑！

对 exit 事件增加超时解决：

#/docker/daemon/monitor.go
ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second)
execConfig.StreamConfig.WaitWithTimeout(ctx)
cancel()

#/docker/container/stream/streams.go
func (c *Config) WaitWithTimeout(ctx context.Context) {done := make(chan struct{}, 1)
    go func() {c.Wait()
        close(done)
    }()
    select {
    case <-done:
    case <-ctx.Done():
        if c.dio != nil {c.dio.Cancel()
            c.dio.Wait()
            c.dio.Close()}
    }
}

这里增加了一个 2s 超时工夫，超时则优雅敞开来自 containerd 的事件流。

至此一个辣手的 Pod terminating 问题曾经解决，后续也将推出小版本修复此问题，尽管修复起来比较简单，但问题剖析的过程却无比艰苦，心愿本篇文章可能对大家今后的问题定位关上思路，谢谢观看~
【腾讯云原生】云说新品、云研新术、云游新活、云赏资讯，扫码关注同名公众号，及时获取更多干货！！

正文完