本篇為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，用戶可以在控制臺看到升級提醒并方便的進行一鍵升級，
希望本篇文章對您有幫助，謝謝觀看！
【騰訊云原生】云說新品、云研新術、云游新活、云賞資訊，掃碼關注同名公眾號，及時獲取更多干貨！！
轉載請註明出處，本文鏈接：https://www.uj5u.com/qita/692.html
標籤：其他