讀懂這一篇，集羣節點不下線

做者 | 聲東  阿里雲售後技術專家

導讀：排查徹底陌生的問題、徹底不熟悉的系統組件，是售後工程師的一大工做樂趣，固然也是挑戰。今天借這篇文章，跟你們分析一例這樣的問題。排查過程當中，須要理解一些本身徹底陌生的組件，好比 systemd 和 dbus。可是排查問題的思路和方法基本上仍是能夠複用了，但願對你們有所幫助。

問題一直在發生

1. I'm NotReady

阿里雲有本身的 Kubernetes 容器集羣產品。隨着 Kubernetes 集羣出貨量的劇增，線上用戶零星的發現，集羣會很是低機率地出現節點 NotReady 狀況。

據咱們觀察，這個問題差很少每月就會有一到兩個客戶遇到。在節點 NotReady 以後，集羣 Master 沒有辦法對這個節點作任何控制，好比下發新的 Pod，再好比抓取節點上正在運行 Pod 的實時信息。

2. 須要知道的 Kubernetes 知識

這裏我稍微補充一點 Kubernetes 集羣的基本知識。Kubernetes 集羣的「硬件基礎」，是以單機形態存在的集羣節點。這些節點能夠是物理機，也能夠是虛擬機。集羣節點分爲 Master 和 Worker 節點。

• Master 節點主要用來負載集羣管控組件，好比調度器和控制器；

• 而 Worker 節點主要用來跑業務。Kubelet 是跑在各個節點上的代理，它負責與管控組件溝通，並按照管控組件的指示，直接管理 Worker 節點。

當集羣節點進入 NotReady 狀態的時候，咱們須要作的第一件事情，確定是檢查運行在節點上的 kubelet 是否正常。在這個問題出現的時候，使用 systemctl 命令查看 kubelet 狀態，發現它做爲 systemd 管理的一個 daemon，是運行正常的。當咱們用 journalctl 查看 kubelet 日誌的時候，發現了下邊的錯誤。

3. 什麼是 PLEG

這個報錯很清楚的告訴咱們，容器 runtime 是不工做的，且 PLEG 是不健康的。這裏容器 runtime 指的就是 docker daemon，Kubelet 經過直接操做 docker daemon 來控制容器的生命週期。

而這裏的 PLEG，指的是 pod lifecycle event generator。

PLEG 是 kubelet 用來檢查容器 runtime 的健康檢查機制。這件事情原本能夠由 kubelet 使用 polling 的方式來作。可是 polling 有其成本上的缺陷，因此 PLEG 應用而生。PLEG 嘗試以一種「中斷」的形式，來實現對容器 runtime 的健康檢查，雖然它實際上同時用了 polling 和「中斷」兩種機制。

基本上看到上邊的報錯，咱們能夠確認，容器 runtime 出了問題。在有問題的節點上，經過 docker 命令嘗試運行新的容器，命令會沒有響應。這說明上邊的報錯是準確的。

容器 runtime

1. Docker Daemon 調用棧分析

Docker 做爲阿里雲 Kubernetes 集羣使用的容器 runtime，在 1.11 以後，被拆分紅了多個組件以適應 OCI 標準。

拆分以後，其包括 docker daemon，containerd，containerd-shim 以及 runC。組件 containerd 負責集羣節點上容器的生命週期管理，並向上爲 docker daemon 提供 gRPC 接口。

在這個問題中，既然 PLEG 認爲容器運行是出了問題，咱們須要先從 docker daemon 進程看起。咱們可使用 kill -USR1 命令發送 USR1 信號給 docker daemon，而 docker daemon 收到信號以後，會把其全部線程調用棧輸出到文件 /var/run/docker 文件夾裏。

Docker daemon 進程的調用棧相對是比較容易分析的。稍微留意，咱們會發現大多數的調用棧都相似下圖中的樣子。
經過觀察棧上每一個函數的名字，以及函數所在的文件（模塊）名稱，咱們能夠看到，這個調用棧下半部分，是進程接到 http 請求，作請求路由的過程；而上半部分則進入實際的處理函數。最終處理函數進入等待狀態，等待的是一個 mutex 實例。

到這裏，咱們須要稍微看一下 ContainerInspectCurrent 這個函數的實現，而最重要的是，咱們能搞明白這個函數的第一個參數，就是 mutex 的指針。使用這個指針搜索整個調用棧文件，咱們會找出，全部等在這個 mutex 上邊的線程。

同時，咱們能夠看到下邊這個線程。

這個線程上，函數 ContainerExecStart 也是在處理具體請求的時候，收到了 mutex 這個參數。但不一樣的是，ContainerExecStart 並無在等待 mutex，而是已經拿到了 mutex 的全部權，並把執行邏輯轉向了 containerd 調用。關於這一點，咱們可使用代碼來驗證。

前邊咱們提到過，containerd 向上經過 gRPC 對 docker daemon 提供接口。此調用棧上半部份內容，正是 docker daemon 在經過 gRPC 請求來呼叫 containerd。

2. Containerd 調用棧分析

與輸出 docker daemon 的調用棧相似，咱們能夠經過 kill -SIGUSR1 命令來輸出 containerd 的調用棧。不一樣的是，此次調用棧會直接輸出到 messages 日誌。

Containerd 做爲一個 gRPC 的服務器，它會在接到 docker daemon 的遠程請求以後，新建一個線程去處理此次請求。關於 gRPC 的細節，咱們這裏其實不用關注太多。
在此次請求的客戶端調用棧上，能夠看到此次調用的核心函數是 Start 一個進程。咱們在 containerd 的調用棧裏搜索 Start，Process 以及 process.go 等字段，很容易發現下邊這個線程。

這個線程的核心任務，就是依靠 runC 去建立容器進程。而在容器啓動以後，runC 進程會退出。因此下一步，咱們天然而然會想到，runC 是否是有順利完成本身的任務。

查看進程列表，咱們會發現，系統中有個別 runC 進程，還在執行，這不是預期內的行爲。容器的啓動跟進程的啓動，耗時應該是差不對的，系統裏有正在運行的 runC 進程，則說明 runC 不能正常啓動容器。

什麼是 Dbus

1. RunC 請求 Dbus

容器 runtime 的 runC 命令，是 libcontainer 的一個簡單的封裝。這個工具能夠用來管理單個容器，好比容器建立，或者容器刪除。在上節的最後，咱們發現 runC 不能完成建立容器的任務。

咱們能夠把對應的進程殺掉，而後在命令行用一樣的命令嘗試啓動容器，同時用 strace 追蹤整個過程。

分析發現，runC 停在了向帶有 org.free 字段的 dbus 寫數據的地方。那什麼是 dbus 呢？在 Linux 上，dbus 是一種進程間進行消息通訊的機制。

2. 緣由並不在 Dbus

咱們可使用 busctl 命令列出系統現有的全部 bus。以下圖，在問題發生的時候，我看到客戶集羣節點 Name 的編號很是大。因此我傾向於認爲，dbus 某些相關的數據結構，好比 Name 耗盡了引發了這個問題。

Dbus 機制的實現，依賴於一個組件叫作 dbus-daemon。若是真的是 dbus 相關數據結構耗盡，那麼重啓這個 daemon，應該是能夠解決這個問題。但不幸的是，問題並無這麼直接。重啓 dbus-daemon 以後，問題依然存在。

在上邊用 strace 追蹤 runC 的截圖中，我提到了，runC 卡在向帶有 org.free 字段的 bus 寫數據的地方。在 busctl 輸出的 bus 列表裏，顯然帶有這個字段的 bus，都在被 systemd 使用。這時，咱們用 systemctl daemon-reexec 來重啓 systemd，問題消失了。

因此基本上咱們能夠判斷一個方向：問題可能跟 systemd 有關係。

Systemd 是硬骨頭

Systemd 是至關複雜的一個組件，尤爲對沒有作過相關開發工做的同窗來講，好比我本身。基本上，排查 systemd 的問題，我用到了四個方法：

• （調試級別）日誌
• core dump
• 代碼分析
• 以及 live debugging

其中第一個、第三個和第四個結合起來使用，讓我在通過幾天的鏖戰以後，找到了問題的緣由。可是這裏咱們先從「沒用」的 core dump 提及。

1. 沒用的 Core Dump

由於重啓 systemd 解決了問題，而這個問題自己，是 runC 在使用 dbus 和 systemd 通訊的時候沒有了響應，因此咱們須要驗證的第一件事情，就是 systemd 不是有關鍵線程被鎖住了。

查看 core dump 裏全部線程，只有如下一個線程並無被鎖住，它在等待 dbus 事件，以便作出響應。

2. 零散的信息

由於機關用盡，因此只能作各類測試、嘗試。使用 busctl tree 命令，能夠輸出全部 bus 上對外暴露的接口。從輸出結果看來，org.freedesktop.systemd1 這個 bus 是不能響應接口查詢請求的。

使用下邊的命令，觀察 org.freedesktop.systemd1 上接受到的全部請求，能夠看到，在正常系統裏，有大量 Unit 建立刪除的消息，可是有問題的系統裏，這個 bus 上徹底沒有任何消息。

gdbus monitor --system --dest org.freedesktop.systemd1 --object-path /org/freedesktop/systemd1

分析問題發生先後的系統日誌，runC 在重複地跑一個 libcontainer_%d_systemd_test_default.slice 測試，這個測試很是頻繁，可是當問題發生的時候，這個測試就中止了。

因此直覺告訴我，這個問題可能和這個測試有很大的關係。

另外，我使用 systemd-analyze 命令，打開了 systemd 的調試日誌，發現 systemd 有 Operation not supported 的報錯。

根據以上零散的知識，只能作出一個大概的結論：org.freedesktop.systemd1 這個 bus 在通過大量 Unit 建立刪除以後，沒有了響應。
而這些頻繁的 Unit 建立刪除測試，是 runC 某一個 checkin 改寫了 UseSystemd 這個函數，而這個函數被用來測試 systemd 的某些功能是否可用。UseSystemd 這個函數在不少地方被調用，好比建立容器、查看容器性能等操做。

3. 代碼分析

這個問題在線上全部 Kubernetes 集羣中，發生的頻率大概是一個月兩例。問題一直在發生，且只能在問題發生以後，經過重啓 systemd 來處理，這風險極大。

咱們分別給 systemd 和 runC 社區提交了 bug，可是一個很現實的問題是，他們並無像阿里雲這樣的線上環境，他們重現這個問題的機率幾乎是零，因此這個問題沒有辦法期望社區來解決。硬骨頭還得咱們本身啃。

在上一節最後，咱們看到了問題出現的時候，systemd 會輸出一些 Operation not supported 報錯。這個報錯看起來和問題自己風馬牛不相及，可是直覺告訴我，這或許是離問題最近的一個地方，因此我決定，先搞清楚這個報錯因何而來。

Systemd 代碼量比較大，而報這個錯誤的地方也比較多。經過大量的代碼分析（這裏略去一千字），我發現有幾處比較可疑地方，有了這些可疑的地方，接下來須要作的事情，就是等待。在等待了三週之後，終於有線上集羣再次重現了這個問題。

4. Live Debugging

在徵求客戶贊成以後，下載 systemd 調試符號，掛載 gdb 到 systemd 上，在可疑的函數下斷點，continue 繼續執行。通過屢次驗證，發現 systemd 最終踩到了 sd_bus_message_seal 這個函數裏的 EOPNOTSUPP 報錯。

這個報錯背後的道理是，systemd 使用了一個變量 cookie，來追蹤本身處理的全部 dbus message。每次在加封一個新消息的時候，systemd 都會先把 cookie 這個值加一，而後再把這個 cookie 值複製給這個新的 message。

咱們使用 gdb 打印出 dbus->cookie 這個值，能夠很清楚看到，這個值超過了 0xffffffff。因此看起來，這個問題是 systemd 在加封過大量 message 以後，cookie 這個值 32 位溢出，新的消息不能被加封致使的。

另外，在一個正常的系統上，使用 gdb 把 bus->cookie 這個值改到接近 0xffffffff，而後觀察到，問題在 cookie 溢出的時候馬上出現，則證實了咱們的結論。

5. 怎麼判斷集羣節點 NotReady 是這個問題致使的

首先咱們須要在有問題的節點上安裝 gdb 和 systemd debuginfo，而後用命令 gdb / usr/lib / systemd / systemd 1 把 gdb attach 到 systemd，在函數 sd_bus_send 設置斷點，以後繼續執行。
等 systemd 踩到斷點以後，用 p /x bus->cookie 查看對應的 cookie 值，若是此值超過了 0xffffffff，那麼 cookie 就溢出了，則必然致使節點 NotReady 的問題。確認完以後，可使用 quit 來 detach 調試器。

問題修復

這個問題的修復，並無那麼直截了當。緣由之一是 systemd 使用了同一個 cookie 變量來兼容 dbus1 和 dbus2。

• 對於 dbus1 來講，cookie 是 32 位的，這個值在通過 systemd 三五個月頻繁建立刪除 Unit 以後，是確定會溢出的；

• 而 dbus2 的 cookie 是 64 位的，可能到了時間的盡頭它也不會溢出。

另一個緣由是，咱們並不能簡單的讓 cookie 折返，來解決溢出問題。由於這有可能致使 systemd 使用同一個 cookie 來加封不一樣的消息，這樣的結果將是災難性的。

最終的修復方法是，使用 32 位 cookie 來一樣處理 dbus1 和 dbus2 兩種情形。同時在 cookie 達到 0xfffffff 以後的下一個 cookie 返回 0x80000000，用最高位來標記 cookie 已經處於溢出狀態。檢查到 cookie 處於這種狀態時，咱們須要檢查是否下一個 cookie 正在被其餘 message 使用，來避免 cookie 衝突。

後記

這個問題根本緣由確定在 systemd，可是 runC 的函數 UseSystemd 使用不那麼美麗的方法，去測試 systemd 的功能，這個函數在整個容器生命週期管理過程當中，被頻繁地觸發，讓這個低機率問題的發生成爲了可能。systemd 的修復已經被紅帽接受，預期不久的未來，咱們能夠經過升級 systemd，從根本上解決這個問題。

相關文章推薦
K8s 故障排查系列 | 咱們爲何會刪除不了集羣的 Namespace？
K8s 故障排查系列 | 鏡像拉取這件小事

雲原生實踐峯會即將開幕

「阿里巴巴雲原生關注微服務、Serverless、容器、Service Mesh 等技術領域、聚焦雲原生流行技術趨勢、雲原生大規模的落地實踐，作最懂雲原生開發者的技術圈。」