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

> **導讀**：排查完全陌生的問題、完全不熟悉的系統元件，是售後工程師的一大工作樂趣，當然也是挑戰。今天借這篇文章，跟大家分析一例這樣的問題。排查過程中，需要理解一些自己完全陌生的元件，比如 systemd 和 dbus。但是排查問題的思路和方法基本上還是可以複用了，希望對大家有所幫助。

# 問題一直在發生

### 1. I'm NotReady

阿里雲有自己的 Kubernetes 容器叢集產品。隨著 Kubernetes 叢集出貨量的劇增，線上使用者零星的發現，叢集會非常低機率地出現節點 NotReady 情況。

據我們觀察，這個問題差不多每個月就會有一到兩個客戶遇到。在節點 NotReady 之後，叢集 Master 沒有辦法對這個節點做任何控制，比如下發新的 Pod，再比如抓取節點上正在執行 Pod 的實時資訊。

![1.jpeg](https://ucc.alicdn.com/pic/developer-ecology/3dc230cb02954b22a372c3c7202124db.jpeg)

### 2. 需要知道的 Kubernetes 知識

這裡我稍微補充一點 Kubernetes 叢集的基本知識。Kubernetes 叢集的“硬體基礎”，是以單機形態存在的叢集節點。這些節點可以是物理機，也可以是虛擬機器。叢集節點分為 Master 和 Worker 節點。

- Master 節點主要用來負載叢集管控元件，比如排程器和控制器；

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

![2.png](https://ucc.alicdn.com/pic/developer-ecology/1e053ce40b09439e863a597a287c1071.png)

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

![3.jpeg](https://ucc.alicdn.com/pic/developer-ecology/bd5c28f33d0843f1b278c9d32a186dee.jpeg)

### 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 和“中斷”兩種機制。

![4.png](https://ucc.alicdn.com/pic/developer-ecology/694b0ef38e5a4cdfbe233011cab1ef75.png)

基本上看到上邊的報錯，我們可以確認，容器 runtime 出了問題。在有問題的節點上，透過 docker 命令嘗試執行新的容器，命令會沒有響應。這說明上邊的報錯是準確的。
# 容器 runtime

### 1. Docker Daemon 呼叫棧分析

Docker 作為阿里雲 Kubernetes 叢集使用的容器 runtime，在 1.11 之後，被拆分成了多個元件以適應 OCI 標準。

拆分之後，其包括 docker daemon，containerd，containerd-shim 以及 runC。元件 containerd 負責叢集節點上容器的生命週期管理，並向上為 docker daemon 提供 gRPC 介面。

![5.png](https://ucc.alicdn.com/pic/developer-ecology/58b332b63dd04e70bdaf13acfbcf8aeb.png)

在這個問題中，既然 PLEG 認為容器執行是出了問題，我們需要先從 docker daemon 程式看起。我們可以使用 kill -USR1 <pid> 命令傳送 USR1 訊號給 docker daemon，而 docker daemon 收到訊號之後，會把其所有執行緒呼叫棧輸出到檔案 /var/run/docker 資料夾裡。

Docker daemon 程式的呼叫棧相對是比較容易分析的。稍微留意，我們會發現大多數的呼叫棧都類似下圖中的樣子。<br>透過觀察棧上每個函式的名字，以及函式所在的檔案（模組）名稱，我們可以看到，這個呼叫棧下半部分，是程式接到 http 請求，做請求路由的過程；而上半部分則進入實際的處理函式。最終處理函式進入等待狀態，等待的是一個 mutex 例項。

![6.png](https://ucc.alicdn.com/pic/developer-ecology/f0f71f0f2ee547ecaaff640ba14c87f5.png)

到這裡，我們需要稍微看一下 ContainerInspectCurrent 這個函式的實現，而最重要的是，我們能搞明白這個函式的第一個引數，就是 mutex 的指標。使用這個指標搜尋整個呼叫棧檔案，我們會找出，所有等在這個 mutex 上邊的執行緒。

同時，我們可以看到下邊這個執行緒。

![7.png](https://ucc.alicdn.com/pic/developer-ecology/d6b30396276744e4ad6509bb9d17a5e1.png)

這個執行緒上，函式 ContainerExecStart 也是在處理具體請求的時候，收到了 mutex 這個引數。但不同的是，ContainerExecStart 並沒有在等待 mutex，而是已經拿到了 mutex 的所有權，並把執行邏輯轉向了 containerd 呼叫。關於這一點，我們可以使用程式碼來驗證。

前邊我們提到過，containerd 向上透過 gRPC 對 docker daemon 提供介面。此呼叫棧上半部分內容，正是 docker daemon 在透過 gRPC 請求來呼叫 containerd。

### 2. Containerd 呼叫棧分析

與輸出 docker daemon 的呼叫棧類似，我們可以透過 kill -SIGUSR1 <pid> 命令來輸出 containerd 的呼叫棧。不同的是，這次呼叫棧會直接輸出到 messages 日誌。

Containerd 作為一個 gRPC 的伺服器，它會在接到 docker daemon 的遠端請求之後，新建一個執行緒去處理這次請求。關於 gRPC 的細節，我們這裡其實不用關注太多。<br>在這次請求的客戶端呼叫棧上，可以看到這次呼叫的核心函式是 Start 一個程式。我們在 containerd 的呼叫棧裡搜尋 Start，Process 以及 process.go 等欄位，很容易發現下邊這個執行緒。

![8.png](https://ucc.alicdn.com/pic/developer-ecology/8ce4bcbee19b4fd98dec2cd8411f50da.png)

這個執行緒的核心任務，就是依靠 runC 去建立容器程式。而在容器啟動之後，runC 程式會退出。所以下一步，我們自然而然會想到，runC 是不是有順利完成自己的任務。

檢視程式列表，我們會發現，系統中有個別 runC 程式，還在執行，這不是預期內的行為。容器的啟動跟程式的啟動，耗時應該是差不對的，系統裡有正在執行的 runC 程式，則說明 runC 不能正常啟動容器。
# 什麼是 Dbus

### 1. RunC 請求 Dbus

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

我們可以把對應的程式殺掉，然後在命令列用同樣的命令嘗試啟動容器，同時用 strace 追蹤整個過程。

![9.png](https://ucc.alicdn.com/pic/developer-ecology/38ff9e28ec644c38b940d04bd911c584.png)

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

### 2. 原因並不在 Dbus

![10.png](https://ucc.alicdn.com/pic/developer-ecology/71b9481a47d2460d8ccaa7ac632726d1.png)

我們可以使用 busctl 命令列出系統現有的所有 bus。如下圖，在問題發生的時候，我看到客戶叢集節點 Name 的編號非常大。所以我傾向於認為，dbus 某些相關的資料結構，比如 Name 耗盡了引起了這個問題。

![11.png](https://ucc.alicdn.com/pic/developer-ecology/7d43af6851d0435fb40af122baec17fb.png)

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 事件，以便做出響應。

![12.png](https://ucc.alicdn.com/pic/developer-ecology/b87193dc2fb54782ba2f21bbedb918f2.png)

### 2. 零散的資訊

因為無計可施，所以只能做各種測試、嘗試。使用 busctl tree 命令，可以輸出所有 bus 上對外暴露的介面。從輸出結果看來，org.freedesktop.systemd1 這個 bus 是不能響應介面查詢請求的。

![13.png](https://ucc.alicdn.com/pic/developer-ecology/47b1eb0c124d4c61b3b1d7fedb514399.png)

使用下邊的命令，觀察 org.freedesktop.systemd1 上接受到的所有請求，可以看到，在正常系統裡，有大量 Unit 建立刪除的訊息，但是有問題的系統裡，這個 bus 上完全沒有任何訊息。
```
gdbus monitor --system --dest org.freedesktop.systemd1 --object-path /org/freedesktop/systemd1
```

![14.png](https://ucc.alicdn.com/pic/developer-ecology/2ea1c0cc46f048428cfc2e0d1148b1ca.png)

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

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

![15.jpeg](https://ucc.alicdn.com/pic/developer-ecology/4e88d757aa2641de82276cda90d32a57.jpeg)

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

![16.jpeg](https://ucc.alicdn.com/pic/developer-ecology/80fda5b0400e47efa74b2900ca8d12c2.jpeg)

根據以上零散的知識，只能做出一個大概的結論：org.freedesktop.systemd1 這個 bus 在經過大量 Unit 建立刪除之後，沒有了響應。<br>而這些頻繁的 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 報錯。

![17.png](https://ucc.alicdn.com/pic/developer-ecology/87a5462fa7e445af80fe75eb1f915efe.png)

這個報錯背後的道理是，systemd 使用了一個變數 cookie，來追蹤自己處理的所有 dbus message。每次在加封一個新訊息的時候，systemd 都會先把 cookie 這個值加一，然後再把這個 cookie 值複製給這個新的 message。

我們使用 gdb 列印出 dbus->cookie 這個值，可以很清楚看到，這個值超過了 0xffffffff。所以看起來，這個問題是 systemd 在加封過大量 message 之後，cookie 這個值 32 位溢位，新的訊息不能被加封導致的。

![18.jpeg](https://ucc.alicdn.com/pic/developer-ecology/bbab1bcfa00e4b139911aff9a1f7221d.jpeg)

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

### 5. 怎麼判斷叢集節點 NotReady 是這個問題導致的

首先我們需要在有問題的節點上安裝 gdb 和 systemd debuginfo，然後用命令 gdb / usr/lib / systemd / systemd 1 把 gdb attach 到 systemd，在函式 sd_bus_send 設定斷點，之後繼續執行。<br>等 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 的[修復](https://mp.weixin.qq.com/s/d6qKT3CWZv9cfY5WyBT7YA)已經被紅帽接受，預期不久的將來，我們可以透過升級 systemd，從根本上解決這個問題。

**相關文章推薦**
[K8s 故障排查系列 | 我們為什麼會刪除不了叢集的 Namespace？](https://developer.aliyun.com/article/742349)
[K8s 故障排查系列 | 映象拉取這件小事](https://developer.aliyun.com/article/720278)

# 雲原生實踐峰會即將開幕

![18.png](https://ucc.alicdn.com/pic/developer-ecology/43df4309594849328f889df896c70a09.png)

> “[阿里巴巴雲原生](https://developer.aliyun.com/group/alisoftwaretech/)關注微服務、Serverless、容器、Service Mesh 等技術領域、聚焦雲原生流行技術趨勢、雲原生大規模的落地實踐，做最懂雲原生開發者的技術圈。”</pid></pid>

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

相關文章