K8S從懵圈到熟練：讀懂此文，集群節(jié)點(diǎn)不下線(xiàn)！
排查完全陌生的問(wèn)題、不熟悉的系統(tǒng)組件，對(duì)許多工程師來(lái)說(shuō)是***的工作樂(lè)趣，當(dāng)然也是一大挑戰(zhàn)。今天，阿里巴巴售后技術(shù)專(zhuān)家聲東跟大家分享一例 Kubernetes 集群上的問(wèn)題。這個(gè)問(wèn)題影響范圍較廣，或許某天你也會(huì)遇到。更重要的是，作者在問(wèn)題排查過(guò)程中的思路和方法，也會(huì)讓你有所啟發(fā)。
關(guān)于問(wèn)題
I am Not Ready
阿里云有自己的 Kubernetes 容器集群產(chǎn)品。隨著 Kubernetes 集群出貨量劇增，線(xiàn)上用戶(hù)零星地發(fā)現(xiàn)，集群會(huì)非常低概率地出現(xiàn)節(jié)點(diǎn) NotReady 情況。據(jù)我們觀察，這個(gè)問(wèn)題差不多每個(gè)月，都會(huì)有一兩個(gè)用戶(hù)遇到。在節(jié)點(diǎn) NotReady 之后，集群 Master 沒(méi)有辦法對(duì)這個(gè)節(jié)點(diǎn)做任何控制，比如下發(fā)新的 Pod，再比如抓取節(jié)點(diǎn)上正在運(yùn)行 Pod 的實(shí)時(shí)信息。
需要知道的Kubernetes知識(shí)
這里我稍微補(bǔ)充一點(diǎn) Kubernetes 集群的基本知識(shí)。Kubernetes 集群的“硬件基礎(chǔ)”，是以單機(jī)形態(tài)存在的集群節(jié)點(diǎn)。這些節(jié)點(diǎn)可以是物理機(jī)，也可以是虛擬機(jī)。集群節(jié)點(diǎn)分為 Master 節(jié)點(diǎn)和 Worker 節(jié)點(diǎn)。Master 節(jié)點(diǎn)主要用來(lái)承載集群管控組件，比如調(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)(kubelet 是 systemd 管理的一個(gè) daemon )發(fā)現(xiàn)它是正常運(yùn)行的。當(dāng)我們用 journalctl 查看 kubelet 日志的時(shí)候，發(fā)現(xiàn)以下錯(cuò)誤。
什么是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)確的。
Docker Stack
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)為容器 runtime 出了問(wèn)題，我們需要從 docker daemon 進(jìn)程看起。我們可以使用 kill -USR1
Docker daemon 進(jìn)程的調(diào)用棧是比較容易分析的。稍加留意，我們會(huì)發(fā)現(xiàn)大多數(shù)的調(diào)用棧都長(zhǎng)成下圖中的樣子。通過(guò)觀察棧上每個(gè)函數(shù)的名字，以及函數(shù)所在的文件(模塊)名稱(chēng)，我們可以了解到，這個(gè)調(diào)用棧的下半部分，是進(jìn)程接到 http 請(qǐng)求，做請(qǐng)求路由的過(guò)程;而上半部分則是具體的處理函數(shù)。最終處理函數(shù)進(jìn)入等待狀態(tài)，等待一個(gè)mutex實(shí)例。
到這里，我們需要稍微看一下 ContainerInspectCurrent 這個(gè)函數(shù)的實(shí)現(xiàn)。從實(shí)現(xiàn)可以看到，這個(gè)函數(shù)的***個(gè)參數(shù)，就是這個(gè)線(xiàn)程正在操作的容器名指針。使用這個(gè)指針?biāo)阉髡麄€(gè)調(diào)用棧文件，我們會(huì)找出所有等在這個(gè)容器上的線(xiàn)程。同時(shí)，我們可以看到下邊這個(gè)線(xiàn)程。
這個(gè)線(xiàn)程調(diào)用棧上的函數(shù) ContainerExecStart 也是在處理相同容器。但不同的是，ContainerExecStart 并沒(méi)有在等這個(gè)容器，而是已經(jīng)拿到了這個(gè)容器的操作權(quán)(mutex)，并把執(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。
Containerd調(diào)用棧分析
與 docker daemon 類(lèi)似，我們可以通過(guò) kill -SIGUSR1
Containerd 作為一個(gè) gRPC 的服務(wù)器，會(huì)在接到 docker daemon 的遠(yuǎn)程調(diào)用之后，新建一個(gè)線(xiàn)程去處理這次請(qǐng)求。關(guān)于 gRPC 的細(xì)節(jié)，我們這里其實(shí)不用太多關(guān)注。在這次請(qǐng)求的客戶(hù)端調(diào)用棧上，可以看到這次調(diào)用的核心函數(shù)在 Start 一個(gè)Process 。我們?cè)?containerd 的調(diào)用棧里搜索 Start，Process 以及 process.go 等字段，很容易發(fā)現(xiàn)下邊這個(gè)線(xiàn)程。
這個(gè)線(xiàn)程的核心任務(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ù)期的行為。容器的啟動(dòng)，跟進(jìn)程的啟動(dòng)，耗時(shí)應(yīng)該是差不多數(shù)量級(jí)的，系統(tǒng)里有正在運(yùn)行的 runC 進(jìn)程，則說(shuō)明 runC 不能正常啟動(dòng)容器。
什么是D-Bus?
RunC請(qǐng)求D-Bus
容器 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 socket 寫(xiě)數(shù)據(jù)的地方。那什么是 dbus 呢?在 Linux 上，dbus 是一種進(jìn)程間進(jìn)行消息通信的機(jī)制。
原因并不在 D-Bus
我們可以使用 busctl 命令列出系統(tǒng)現(xiàn)有的所有 bus 。如下圖，在問(wèn)題發(fā)生的時(shí)候，我看到問(wèn)題節(jié)點(diǎn) bus name 編號(hào)非常大。所以我傾向于認(rèn)為，dbus 某些相關(guān)的數(shù)據(jù)結(jié)構(gòu)，比如 name，耗盡了引起了這個(gè)問(wèn)題。
Dbus 機(jī)制的實(shí)現(xiàn)，依賴(lài)于一個(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 寫(xiě)數(shù)據(jù)的地方。在 busctl 輸出的 bus 列表里，顯然帶有這個(gè)字段的 bus，都在被 systemd使用。這時(shí)，我們用 systemctl daemon-reexec 來(lái)重啟 systemd，問(wèn)題消失了。所以基本上我們可以判斷一個(gè)方向，問(wè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ō)起。
“沒(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)鍵線(xiàn)程被鎖住了。查看 core dump 里所有線(xiàn)程，只有以下一個(gè)線(xiàn)程，此線(xiàn)程并沒(méi)有被鎖住，它在等待 dbus 事件，以便做出響應(yīng)。
零散的信息
因?yàn)闊o(wú)計(jì)可施，所以只能做各種測(cè)試、嘗試。使用 busctl tree 命令，可以輸出所有bus 上對(duì)外暴露的接口。從輸出結(jié)果看來(lái)，org.freedesktop.systemd1 這個(gè) bus 是不能響應(yīng)接口查詢(xún)請(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
分析問(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)試級(jí)別日志，發(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è)改動(dòng)引入的。這個(gè)改動(dòng)使得 UseSystemd 函數(shù)通過(guò)創(chuàng)建 unit 來(lái)測(cè)試 systemd 的功能。UseSystemd 在很多地方被調(diào)用，比如創(chuàng)建容器，或者查看容器性能等操作。
代碼分析
這個(gè)問(wèn)題在線(xià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)有像阿里云這樣的線(xiàn)上環(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)上集群，再次重現(xiàn)了這個(gè)問(wèn)題。
Live Debugging
在征求用戶(hù)同意之后，下載 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è)新的 message 的時(shí)候，systemd 會(huì)先給 cookie的值加一，然后再把這個(gè)值復(fù)制給這個(gè)新的 message。
我們使用 gdb 打印出 dbus->cookie 這個(gè)值，可以很清楚看到，這個(gè)值超過(guò)了0xffffffff 。所以看起來(lái)，問(wèn)題是 systemd 在加封過(guò)大量 message 之后，cookie 這個(gè)值32位溢出了，導(dǎo)致新的消息不能被加封，從而使得 systemd 對(duì) runC 沒(méi)有了響應(yīng)。
另外，在一個(gè)正常的系統(tǒng)上，使用 gdb 把 bus->cookie 這個(gè)值改到接近 0xffffffff，然后觀察到，問(wèn)題在 cookie 溢出的時(shí)候立刻出現(xiàn)，則證明了我們的結(jié)論。
怎么判斷集群節(jié)點(diǎn)NotReady是這個(gè)問(wèn)題導(dǎo)致的
首先我們需要在有問(wèn)題的節(jié)點(diǎn)上安裝 gdb 和 systemd debuginfo，然后用命令 gdb /usr/lib/systemd/systemd1 把 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ò)程中，被頻繁的調(diào)用，讓這個(gè)低概率問(wèn)題的發(fā)生成為了可能。systemd 的修復(fù)已經(jīng)被紅帽接受，預(yù)期不久的將來(lái)，我們可以通過(guò)升級(jí) systemd，從根本上解決這個(gè)問(wèn)題。
