2019-04-30
分類：後端
閱讀(398) 評論(0)
排查完全陌生的問題、不熟悉的系統元件，對許多工程師來說是無與倫比的工作樂趣，當然也是一大挑戰。今天，阿裡巴巴售後技術專家聲東跟大家分享一例 Kubernetes 叢集上的問題。這個問題影響範圍較廣，或許某天你也會遇到。更重要的是，作者在問題排查過程中的思路和方法，也會讓你有所啟發。
阿裡雲有自己的 Kubernetes 容器叢集產品。隨著 Kubernetes 叢集出貨量劇增，線上使用者零星地發現，叢集會非常低機率地出現節點 NotReady 情況。據我們觀察，這個問題差不多每個月，都會有一兩個使用者遇到。在節點 NotReady 之後，叢集 Master 沒有辦法對這個節點做任何控制，比如下發新的 Pod，再比如抓取節點上正在執行 Pod 的實時資訊。
這裡我稍微補充一點 Kubernetes 叢集的基本知識。Kubernetes 叢集的“硬體基礎”，是以單機形態存在的叢集節點。這些節點可以是物理機，也可以是虛擬機器。叢集節點分為 Master 節點和 Worker 節點。Master 節點主要用來承載叢集管控元件，比如排程器和控制器。而 Worker 節點主要用來跑業務。Kubelet 是跑在各個節點上的代理，它負責與管控元件溝通，並按照管控元件的指示，直接管理 Worker節點。
當叢集節點進入 NotReady 狀態的時候，我們需要做的第一件事情，是檢查執行在節點上的 kubelet 是否正常。在這個問題出現的時候，使用 systemctl 命令檢視的kubelet 狀態（kubelet 是 systemd 管理的一個 daemon ）發現它是正常執行的。當我們用 journalctl 檢視 kubelet 日誌的時候，發現以下錯誤。
這個報錯清楚地告訴我們，容器 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 命令嘗試執行新的容器，命令會沒有響應，這說明上邊的報錯是準確的。
Docker 作為阿裡雲 Kubernetes 叢集使用的容器 Runtime ，在 1.11 之後，被拆分成了多個元件以適應 OCI 標準。拆分之後，其包括 Docker Daemon，containerd，containerd-shim 以及 runC。元件 containerd 負責叢集節點上容器的生命週期管理，並向上為 Docker Daemon 提供 gRPC 介面。
在這個問題中，既然 PLEG 認為容器 Runtime 出了問題，我們需要從 Docker Daemon 行程看起。我們可以使用 kill -USR1 命令傳送 USR1 訊號給 Docker Daemon，而 Docker Daemon 收到訊號之後，會把所有執行緒呼叫棧輸出到 /var/run/docker 檔案夾裡。
Docker Daemon 行程的呼叫棧是比較容易分析的。稍加留意，我們會發現大多數的呼叫棧都長成下圖中的樣子。透過觀察棧上每個函式的名字，以及函式所在的檔案（模組）名稱，我們可以瞭解到，這個呼叫棧的下半部分，是行程接到 http 請求，做請求路由的過程；而上半部分則是具體的處理函式。最終處理函式進入等待狀態，等待一個 mutex 實體。
到這裡，我們需要稍微看一下 ContainerInspectCurrent 這個函式的實現。從實現可以看到，這個函式的第一個引數，就是這個執行緒正在操作的容器名指標。使用這個指標搜尋整個呼叫棧檔案，我們會找出所有等在這個容器上的執行緒。同時，我們可以看到下邊這個執行緒。
這個執行緒呼叫棧上的函式 ContainerExecStart 也是在處理相同容器。但不同的是，ContainerExecStart 並沒有在等這個容器，而是已經拿到了這個容器的操作權（mutex），並把執行邏輯轉向了 containerd 呼叫。關於這一點，我們也可以使用程式碼來驗證。前邊我提到過，containerd 透過 gRPC 向上對 Docker Daemon 提供介面。此呼叫棧上半部分內容，正是 Docker Daemon 在透過 gRPC 請求來呼叫 containerd。
與 Docker Daemon 類似，我們可以透過 kill -SIGUSR1 命令來輸出containerd 的呼叫棧。不同的是，這次呼叫棧會直接輸出到 messages 日誌。
Containerd 作為一個 gRPC 的伺服器，會在接到 Docker Daemon 的遠端呼叫之後，新建一個執行緒去處理這次請求。關於 gRPC 的細節，我們這裡其實不用太多關註。在這次請求的客戶端呼叫棧上，可以看到這次呼叫的核心函式在 Start 一個 Process 。我們在 containerd 的呼叫棧裡搜尋 Start，Process 以及 process.go 等欄位，很容易發現下邊這個執行緒。
這個執行緒的核心任務，就是依靠 runC 去建立容器行程。而在容器啟動之後，runC 行程會退出。所以下一步，我們自然而然會想到，runC 是不是有順利完成自己的任務。檢視行程串列，我們會發現，系統中有個別 runC 行程還在執行，這不是預期的行為。容器的啟動，跟行程的啟動，耗時應該是差不多數量級的，系統裡有正在執行的 runC 行程，則說明 runC 不能正常啟動容器。
容器 Runtime 的 runC 命令，是 libcontainer 的一個簡單的封裝。這個工具可以用來管理單個容器，比如容器建立和容器刪除。在上節的最後，我們發現 runC 不能完成建立容器的任務。我們可以把對應的行程殺掉，然後在命令列用同樣的命令啟動容器，同時用 strace 追蹤整個過程。
分析發現，runC 停在了向帶有 org.free 欄位的 dbus socket 寫資料的地方。那什麼是 dbus 呢？在 Linux 上，dbus 是一種行程間進行訊息通訊的機制。
我們可以使用 busctl 命令列出系統現有的所有 bus 。如下圖，在問題發生的時候，我看到問題節點 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 的問題，我用到了四個方法，（除錯級別）日誌，core dump，程式碼分析，以及 live debugging。其中第一個，第三個和第四個結合起來使用，讓我在經過幾天的鏖戰之後，找到了問題的原因。但是這裡我們先從“沒用”的 core dump 說起。
因為重啟 systemd 解決了問題，而這個問題本身，是 runC 在使用 dbus 和systemd 通訊的時候沒有了響應，所以我們需要驗證的第一件事情，就是 systemd不是有關鍵執行緒被鎖住了。檢視 core dump 裡所有執行緒，只有以下一個執行緒，此執行緒並沒有被鎖住，它在等待 dbus 事件，以便做出響應。
因為無計可施，所以只能做各種測試、嘗試。使用 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 某一個改動引入的。這個改動使得 UseSystemd 函式透過建立 unit 來測試 systemd 的功能。UseSystemd 在很多地方被呼叫，比如建立容器，或者檢視容器效能等操作。
這個問題線上上所有 Kubernetes 叢集中，發生的頻率大概是一個月兩例。問題一直在發生，且只能在問題發生之後，透過重啟 systemd 來處理，這風險極大。
我們分別給 systemd 和 runC 社群提交了 bug，但是一個很現實的問題是，他們並沒有像阿裡雲這樣的線上環境，他們重現這個問題的機率幾乎是零，所以這個問題沒有辦法指望社群來解決。硬骨頭還得我們自己啃。
在上一節最後，我們看到了，問題出現的時候，systemd 會輸出一些 Operation not supported 報錯。這個報錯看起來和問題本身風馬牛不相及，但是直覺告訴我，這，或許是離問題最近的一個地方，所以我決定，先搞清楚這個報錯因何而來。
Systemd 程式碼量比較大，而報這個錯誤的地方非常多。透過大量的程式碼分析（這裡略去一千字），我發現有幾處比較可疑地方，有了這些可疑的地方，接下來需要做的事情，就是等待。在等了三週以後，終於有線上叢集，再次重現了這個問題。
在徵求使用者同意之後，下載 systemd 除錯符號，掛載 gdb 到 systemd 上，在可疑的函式下斷點，continue 繼續執行。經過多次驗證，發現 systemd 最終踩到了sd_bus_message_seal 這個函式裡的 EOPNOTSUPP 報錯。
這個報錯背後的道理是，systemd 使用了一個變數 cookie，來追蹤自己處理的 dbus message 。每次在加封一個新的 message 的時候，systemd 會先給 cookie的值加一，然後再把這個值複製給這個新的 message。
我們使用 gdb 打印出 dbus->cookie 這個值，可以很清楚看到，這個值超過了0xffffffff 。所以看起來，問題是 systemd 在加封過大量 message 之後，cookie 這個值32位上限溢位了，導致新的訊息不能被加封，從而使得 systemd 對 runC 沒有了響應。
另外，在一個正常的系統上，使用 gdb 把 bus->cookie 這個值改到接近 0xffffffff，然後觀察到，問題在 cookie 上限溢位的時候立刻出現，則證明瞭我們的結論。
怎麼判斷叢集節點 NotReady 是這個問題導致的
首先我們需要在有問題的節點上安裝 gdb 和 systemd debuginfo，然後用命令 gdb /usr/lib/systemd/systemd1 把 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，從根本上解決這個問題。
知識星球
朋友會在“發現-看一看”看到你“在看”的內容