問(wèn)題一直在發(fā)生
1. I'm NotReady
阿里云有自己的 Kube.NETes 容器集群產(chǎn)品。隨著 Kubernetes 集群出貨量的劇增，線上用戶零星的發(fā)現(xiàn)，集群會(huì)非常低概率地出現(xiàn)節(jié)點(diǎn) NotReady 情況。
據(jù)我們觀察，這個(gè)問(wèn)題差不多每個(gè)月就會(huì)有一到兩個(gè)客戶遇到。在節(jié)點(diǎn) NotReady 之后，集群 Master 沒(méi)有辦法對(duì)這個(gè)節(jié)點(diǎn)做任何控制，比如下發(fā)新的 Pod，再比如抓取節(jié)點(diǎn)上正在運(yùn)行 Pod 的實(shí)時(shí)信息。
2. 需要知道的 Kubernetes 知識(shí)
這里我稍微補(bǔ)充一點(diǎn) Kubernetes 集群的基本知識(shí)。Kubernetes 集群的“硬件基礎(chǔ)”，是以單機(jī)形態(tài)存在的集群節(jié)點(diǎn)。這些節(jié)點(diǎn)可以是物理機(jī)，也可以是虛擬機(jī)。集群節(jié)點(diǎn)分為 Master 和 Worker 節(jié)點(diǎn)。
- Master 節(jié)點(diǎn)主要用來(lái)負(fù)載集群管控組件，比如調(diào)度器和控制器;
- 而 Worker 節(jié)點(diǎn)主要用來(lái)跑業(yè)務(wù)。Kubelet 是跑在各個(gè)節(jié)點(diǎn)上的代理，它負(fù)責(zé)與管控組件溝通，并按照管控組件的指示，直接管理 Worker 節(jié)點(diǎn)。
當(dāng)集群節(jié)點(diǎn)進(jìn)入 NotReady 狀態(tài)的時(shí)候，我們需要做的第一件事情，肯定是檢查運(yùn)行在節(jié)點(diǎn)上的 kubelet 是否正常。在這個(gè)問(wèn)題出現(xiàn)的時(shí)候，使用 systemctl 命令查看 kubelet 狀態(tài)，發(fā)現(xiàn)它作為 systemd 管理的一個(gè) daemon，是運(yùn)行正常的。當(dāng)我們用 journalctl 查看 kubelet 日志的時(shí)候，發(fā)現(xiàn)了下邊的錯(cuò)誤。
3. 什么是 PLEG
這個(gè)報(bào)錯(cuò)很清楚的告訴我們，容器 runtime 是不工作的，且 PLEG 是不健康的。這里容器 runtime 指的就是 Docker daemon，Kubelet 通過(guò)直接操作 docker daemon 來(lái)控制容器的生命周期。
而這里的 PLEG，指的是 pod lifecycle event generator。
PLEG 是 kubelet 用來(lái)檢查容器 runtime 的健康檢查機(jī)制。這件事情本來(lái)可以由 kubelet 使用 polling 的方式來(lái)做。但是 polling 有其成本上的缺陷，所以 PLEG 應(yīng)用而生。PLEG 嘗試以一種“中斷”的形式，來(lái)實(shí)現(xiàn)對(duì)容器 runtime 的健康檢查，雖然它實(shí)際上同時(shí)用了 polling 和“中斷”兩種機(jī)制。
基本上看到上邊的報(bào)錯(cuò)，我們可以確認(rèn)，容器 runtime 出了問(wèn)題。在有問(wèn)題的節(jié)點(diǎn)上，通過(guò) docker 命令嘗試運(yùn)行新的容器，命令會(huì)沒(méi)有響應(yīng)。這說(shuō)明上邊的報(bào)錯(cuò)是準(zhǔn)確的。
容器 runtime
1. Docker Daemon 調(diào)用棧分析
Docker 作為阿里云 Kubernetes 集群使用的容器 runtime，在 1.11 之后，被拆分成了多個(gè)組件以適應(yīng) OCI 標(biāo)準(zhǔn)。
拆分之后，其包括 docker daemon，contAInerd，containerd-shim 以及 runC。組件 containerd 負(fù)責(zé)集群節(jié)點(diǎn)上容器的生命周期管理，并向上為 docker daemon 提供 gRPC 接口。
在這個(gè)問(wèn)題中，既然 PLEG 認(rèn)為容器運(yùn)行是出了問(wèn)題，我們需要先從 docker daemon 進(jìn)程看起。我們可以使用 kill -USR1 命令發(fā)送 USR1 信號(hào)給 docker daemon，而 docker daemon 收到信號(hào)之后，會(huì)把其所有線程調(diào)用棧輸出到文件 /var/run/docker 文件夾里。
Docker daemon 進(jìn)程的調(diào)用棧相對(duì)是比較容易分析的。稍微留意，我們會(huì)發(fā)現(xiàn)大多數(shù)的調(diào)用棧都類似下圖中的樣子。
通過(guò)觀察棧上每個(gè)函數(shù)的名字，以及函數(shù)所在的文件(模塊)名稱，我們可以看到，這個(gè)調(diào)用棧下半部分，是進(jìn)程接到 http 請(qǐng)求，做請(qǐng)求路由的過(guò)程;而上半部分則進(jìn)入實(shí)際的處理函數(shù)。最終處理函數(shù)進(jìn)入等待狀態(tài)，等待的是一個(gè) mutex 實(shí)例。
到這里，我們需要稍微看一下 ContainerInspectCurrent 這個(gè)函數(shù)的實(shí)現(xiàn)，而最重要的是，我們能搞明白這個(gè)函數(shù)的第一個(gè)參數(shù)，就是 mutex 的指針。使用這個(gè)指針?biāo)阉髡麄€(gè)調(diào)用棧文件，我們會(huì)找出，所有等在這個(gè) mutex 上邊的線程。
同時(shí)，我們可以看到下邊這個(gè)線程。
這個(gè)線程上，函數(shù) ContainerExecStart 也是在處理具體請(qǐng)求的時(shí)候，收到了 mutex 這個(gè)參數(shù)。但不同的是，ContainerExecStart 并沒(méi)有在等待 mutex，而是已經(jīng)拿到了 mutex 的所有權(quán)，并把執(zhí)行邏輯轉(zhuǎn)向了 containerd 調(diào)用。關(guān)于這一點(diǎn)，我們可以使用代碼來(lái)驗(yàn)證。
前邊我們提到過(guò)，containerd 向上通過(guò) gRPC 對(duì) docker daemon 提供接口。此調(diào)用棧上半部分內(nèi)容，正是 docker daemon 在通過(guò) gRPC 請(qǐng)求來(lái)呼叫 containerd。
2. Containerd 調(diào)用棧分析
與輸出 docker daemon 的調(diào)用棧類似，我們可以通過(guò) kill -SIGUSR1 命令來(lái)輸出 containerd 的調(diào)用棧。不同的是，這次調(diào)用棧會(huì)直接輸出到 messages 日志。
Containerd 作為一個(gè) gRPC 的服務(wù)器，它會(huì)在接到 docker daemon 的遠(yuǎn)程請(qǐng)求之后，新建一個(gè)線程去處理這次請(qǐng)求。關(guān)于 gRPC 的細(xì)節(jié)，我們這里其實(shí)不用關(guān)注太多。
在這次請(qǐng)求的客戶端調(diào)用棧上，可以看到這次調(diào)用的核心函數(shù)是 Start 一個(gè)進(jìn)程。我們?cè)?containerd 的調(diào)用棧里搜索 Start，Process 以及 process.go 等字段，很容易發(fā)現(xiàn)下邊這個(gè)線程。
這個(gè)線程的核心任務(wù)，就是依靠 runC 去創(chuàng)建容器進(jìn)程。而在容器啟動(dòng)之后，runC 進(jìn)程會(huì)退出。所以下一步，我們自然而然會(huì)想到，runC 是不是有順利完成自己的任務(wù)。
查看進(jìn)程列表，我們會(huì)發(fā)現(xiàn)，系統(tǒng)中有個(gè)別 runC 進(jìn)程，還在執(zhí)行，這不是預(yù)期內(nèi)的行為。容器的啟動(dòng)跟進(jìn)程的啟動(dòng)，耗時(shí)應(yīng)該是差不對(duì)的，系統(tǒng)里有正在運(yùn)行的 runC 進(jìn)程，則說(shuō)明 runC 不能正常啟動(dòng)容器。
什么是 Dbus
1. RunC 請(qǐng)求 Dbus
容器 runtime 的 runC 命令，是 libcontainer 的一個(gè)簡(jiǎn)單的封裝。這個(gè)工具可以用來(lái)管理單個(gè)容器，比如容器創(chuàng)建，或者容器刪除。在上節(jié)的最后，我們發(fā)現(xiàn) runC 不能完成創(chuàng)建容器的任務(wù)。
我們可以把對(duì)應(yīng)的進(jìn)程殺掉，然后在命令行用同樣的命令嘗試啟動(dòng)容器，同時(shí)用 strace 追蹤整個(gè)過(guò)程。
分析發(fā)現(xiàn)，runC 停在了向帶有 org.free 字段的 dbus 寫數(shù)據(jù)的地方。那什么是 dbus 呢?在 linux 上，dbus 是一種進(jìn)程間進(jìn)行消息通信的機(jī)制。
2. 原因并不在 Dbus
我們可以使用 busctl 命令列出系統(tǒng)現(xiàn)有的所有 bus。如下圖，在問(wèn)題發(fā)生的時(shí)候，我看到客戶集群節(jié)點(diǎn) Name 的編號(hào)非常大。所以我傾向于認(rèn)為，dbus 某些相關(guān)的數(shù)據(jù)結(jié)構(gòu)，比如 Name 耗盡了引起了這個(gè)問(wèn)題。
Dbus 機(jī)制的實(shí)現(xiàn)，依賴于一個(gè)組件叫做 dbus-daemon。如果真的是 dbus 相關(guān)數(shù)據(jù)結(jié)構(gòu)耗盡，那么重啟這個(gè) daemon，應(yīng)該是可以解決這個(gè)問(wèn)題。但不幸的是，問(wèn)題并沒(méi)有這么直接。重啟 dbus-daemon 之后，問(wèn)題依然存在。
在上邊用 strace 追蹤 runC 的截圖中，我提到了，runC 卡在向帶有 org.free 字段的 bus 寫數(shù)據(jù)的地方。在 busctl 輸出的 bus 列表里，顯然帶有這個(gè)字段的 bus，都在被 systemd 使用。這時(shí)，我們用 systemctl daemon-reexec 來(lái)重啟 systemd，問(wèn)題消失了。
所以基本上我們可以判斷一個(gè)方向：?jiǎn)栴}可能跟 systemd 有關(guān)系。
Systemd 是硬骨頭
Systemd 是相當(dāng)復(fù)雜的一個(gè)組件，尤其對(duì)沒(méi)有做過(guò)相關(guān)開(kāi)發(fā)工作的同學(xué)來(lái)說(shuō)，比如我自己。基本上，排查 systemd 的問(wèn)題，我用到了四個(gè)方法：
- (調(diào)試級(jí)別)日志
- core dump
- 代碼分析
- 以及 live debugging
其中第一個(gè)、第三個(gè)和第四個(gè)結(jié)合起來(lái)使用，讓我在經(jīng)過(guò)幾天的鏖戰(zhàn)之后，找到了問(wèn)題的原因。但是這里我們先從“沒(méi)用”的 core dump 說(shuō)起。
1. 沒(méi)用的 Core Dump
因?yàn)橹貑?systemd 解決了問(wèn)題，而這個(gè)問(wèn)題本身，是 runC 在使用 dbus 和 systemd 通信的時(shí)候沒(méi)有了響應(yīng)，所以我們需要驗(yàn)證的第一件事情，就是 systemd 不是有關(guān)鍵線程被鎖住了。
查看 core dump 里所有線程，只有以下一個(gè)線程并沒(méi)有被鎖住，它在等待 dbus 事件，以便做出響應(yīng)。
2. 零散的信息
因?yàn)闊o(wú)計(jì)可施，所以只能做各種測(cè)試、嘗試。使用 busctl tree 命令，可以輸出所有 bus 上對(duì)外暴露的接口。從輸出結(jié)果看來(lái)，org.freedesktop.systemd1 這個(gè) bus 是不能響應(yīng)接口查詢請(qǐng)求的。
使用下邊的命令，觀察 org.freedesktop.systemd1 上接受到的所有請(qǐng)求，可以看到，在正常系統(tǒng)里，有大量 Unit 創(chuàng)建刪除的消息，但是有問(wèn)題的系統(tǒng)里，這個(gè) bus 上完全沒(méi)有任何消息。
gdbus monitor --system --dest org.freedesktop.systemd1 --object-path /org/freedesktop/systemd1
- 1.
分析問(wèn)題發(fā)生前后的系統(tǒng)日志，runC 在重復(fù)地跑一個(gè) libcontainer_%d_systemd_test_default.slice 測(cè)試，這個(gè)測(cè)試非常頻繁，但是當(dāng)問(wèn)題發(fā)生的時(shí)候，這個(gè)測(cè)試就停止了。
所以直覺(jué)告訴我，這個(gè)問(wèn)題可能和這個(gè)測(cè)試有很大的關(guān)系。
另外，我使用 systemd-analyze 命令，打開(kāi)了 systemd 的調(diào)試日志，發(fā)現(xiàn) systemd 有 Operation not supported 的報(bào)錯(cuò)。
根據(jù)以上零散的知識(shí)，只能做出一個(gè)大概的結(jié)論：org.freedesktop.systemd1 這個(gè) bus 在經(jīng)過(guò)大量 Unit 創(chuàng)建刪除之后，沒(méi)有了響應(yīng)。
而這些頻繁的 Unit 創(chuàng)建刪除測(cè)試，是 runC 某一個(gè) checkin 改寫了 UseSystemd 這個(gè)函數(shù)，而這個(gè)函數(shù)被用來(lái)測(cè)試 systemd 的某些功能是否可用。UseSystemd 這個(gè)函數(shù)在很多地方被調(diào)用，比如創(chuàng)建容器、查看容器性能等操作。
3. 代碼分析
這個(gè)問(wèn)題在線上所有 Kubernetes 集群中，發(fā)生的頻率大概是一個(gè)月兩例。問(wèn)題一直在發(fā)生，且只能在問(wèn)題發(fā)生之后，通過(guò)重啟 systemd 來(lái)處理，這風(fēng)險(xiǎn)極大。
我們分別給 systemd 和 runC 社區(qū)提交了 bug，但是一個(gè)很現(xiàn)實(shí)的問(wèn)題是，他們并沒(méi)有像阿里云這樣的線上環(huán)境，他們重現(xiàn)這個(gè)問(wèn)題的概率幾乎是零，所以這個(gè)問(wèn)題沒(méi)有辦法指望社區(qū)來(lái)解決。硬骨頭還得我們自己啃。
在上一節(jié)最后，我們看到了問(wèn)題出現(xiàn)的時(shí)候，systemd 會(huì)輸出一些 Operation not supported 報(bào)錯(cuò)。這個(gè)報(bào)錯(cuò)看起來(lái)和問(wèn)題本身風(fēng)馬牛不相及，但是直覺(jué)告訴我，這或許是離問(wèn)題最近的一個(gè)地方，所以我決定，先搞清楚這個(gè)報(bào)錯(cuò)因何而來(lái)。
Systemd 代碼量比較大，而報(bào)這個(gè)錯(cuò)誤的地方也比較多。通過(guò)大量的代碼分析(這里略去一千字)，我發(fā)現(xiàn)有幾處比較可疑地方，有了這些可疑的地方，接下來(lái)需要做的事情，就是等待。在等待了三周以后，終于有線上集群再次重現(xiàn)了這個(gè)問(wèn)題。
4. Live Debugging
在征求客戶同意之后，下載 systemd 調(diào)試符號(hào)，掛載 gdb 到 systemd 上，在可疑的函數(shù)下斷點(diǎn)，continue 繼續(xù)執(zhí)行。經(jīng)過(guò)多次驗(yàn)證，發(fā)現(xiàn) systemd 最終踩到了 sd_bus_message_seal 這個(gè)函數(shù)里的 EOPNOTSUPP 報(bào)錯(cuò)。
這個(gè)報(bào)錯(cuò)背后的道理是，systemd 使用了一個(gè)變量 cookie，來(lái)追蹤自己處理的所有 dbus message。每次在加封一個(gè)新消息的時(shí)候，systemd 都會(huì)先把 cookie 這個(gè)值加一，然后再把這個(gè) cookie 值復(fù)制給這個(gè)新的 message。
我們使用 gdb 打印出 dbus->cookie 這個(gè)值，可以很清楚看到，這個(gè)值超過(guò)了 0xffffffff。所以看起來(lái)，這個(gè)問(wèn)題是 systemd 在加封過(guò)大量 message 之后，cookie 這個(gè)值 32 位溢出，新的消息不能被加封導(dǎo)致的。
另外，在一個(gè)正常的系統(tǒng)上，使用 gdb 把 bus->cookie 這個(gè)值改到接近 0xffffffff，然后觀察到，問(wèn)題在 cookie 溢出的時(shí)候立刻出現(xiàn)，則證明了我們的結(jié)論。
5. 怎么判斷集群節(jié)點(diǎn) NotReady 是這個(gè)問(wèn)題導(dǎo)致的
首先我們需要在有問(wèn)題的節(jié)點(diǎn)上安裝 gdb 和 systemd debuginfo，然后用命令 gdb / usr/lib / systemd / systemd 1 把 gdb attach 到 systemd，在函數(shù) sd_bus_send 設(shè)置斷點(diǎn)，之后繼續(xù)執(zhí)行。
等 systemd 踩到斷點(diǎn)之后，用 p /x bus->cookie 查看對(duì)應(yīng)的 cookie 值，如果此值超過(guò)了 0xffffffff，那么 cookie 就溢出了，則必然導(dǎo)致節(jié)點(diǎn) NotReady 的問(wèn)題。確認(rèn)完之后，可以使用 quit 來(lái) detach 調(diào)試器。
問(wèn)題修復(fù)
這個(gè)問(wèn)題的修復(fù)，并沒(méi)有那么直截了當(dāng)。原因之一是 systemd 使用了同一個(gè) cookie 變量來(lái)兼容 dbus1 和 dbus2。
對(duì)于 dbus1 來(lái)說(shuō)，cookie 是 32 位的，這個(gè)值在經(jīng)過(guò) systemd 三五個(gè)月頻繁創(chuàng)建刪除 Unit 之后，是肯定會(huì)溢出的;
而 dbus2 的 cookie 是 64 位的，可能到了時(shí)間的盡頭它也不會(huì)溢出。
另外一個(gè)原因是，我們并不能簡(jiǎn)單的讓 cookie 折返，來(lái)解決溢出問(wèn)題。因?yàn)檫@有可能導(dǎo)致 systemd 使用同一個(gè) cookie 來(lái)加封不同的消息，這樣的結(jié)果將是災(zāi)難性的。
最終的修復(fù)方法是，使用 32 位 cookie 來(lái)同樣處理 dbus1 和 dbus2 兩種情形。同時(shí)在 cookie 達(dá)到 0xfffffff 之后的下一個(gè) cookie 返回 0x80000000，用最高位來(lái)標(biāo)記 cookie 已經(jīng)處于溢出狀態(tài)。檢查到 cookie 處于這種狀態(tài)時(shí)，我們需要檢查是否下一個(gè) cookie 正在被其他 message 使用，來(lái)避免 cookie 沖突。
后記
這個(gè)問(wèn)題根本原因肯定在 systemd，但是 runC 的函數(shù) UseSystemd 使用不那么美麗的方法，去測(cè)試 systemd 的功能，這個(gè)函數(shù)在整個(gè)容器生命周期管理過(guò)程中，被頻繁地觸發(fā)，讓這個(gè)低概率問(wèn)題的發(fā)生成為了可能。
systemd 的修復(fù)已經(jīng)被紅帽接受，預(yù)期不久的將來(lái)，我們可以通過(guò)升級(jí) systemd，從根本上解決這個(gè)問(wèn)題。
