【Pod Terminating緣由追蹤系列之三】讓docker事件處理罷工的cancel狀態碼

本篇爲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/pull/39513）

解決辦法也很簡單，在每次遞歸調用以前sleep 1秒便可，該改動也已經合進了docker19的代碼中。

在後續咱們將推出產品化運行時版本升級修復本篇中提到的bug，用戶能夠在控制檯看到升級提醒並方便的進行一鍵升級。

但願本篇文章對您有幫助，謝謝觀看！

【騰訊雲原生】雲說新品、雲研新術、雲遊新活、雲賞資訊，掃碼關注同名公衆號，及時獲取更多幹貨！！