【Pod Terminating緣由追蹤系列之二】exec鏈接未關閉致使的事件阻塞

前一陣有客戶docker18.06.3集羣中出現Pod卡在terminating狀態的問題，通過排查發現是containerd和dockerd之間事件流阻塞，致使後續事件得不處處理形成的。

定位問題的過程極其艱難，其中不乏大量工具的使用和大量的源碼閱讀。本文將梳理排查此問題的過程，並總結完整的dockerd和contaienrd之間事件傳遞流程，一步一步找到問題產生的緣由，特寫本文記錄分享，但願你們在有相似問題發生時，可以迅速定位、解決。

對於本文中提到的問題，在docker19中已經獲得解決，但docker18沒法直接升級到docker19，所以本文在結尾參考docker19給出了一種簡單的解決方案。

刪除不掉Pod

相信你們在解決現網問題時，常常會遇到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事件

經過發送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問題已經解決，後續也將推出小版本修復此問題，雖然修復起來比較簡單，但問題分析的過程卻無比艱辛，但願本篇文章可以對你們從此的問題定位打開思路，謝謝觀看~
【騰訊雲原生】雲說新品、雲研新術、雲遊新活、雲賞資訊，掃碼關注同名公衆號，及時獲取更多幹貨！！