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

問題一直在發生

I'm NotReady

阿里雲有自己的Kubernetes容器叢集產品。隨著Kubernetes叢集出貨量的劇增，線上使用者零星的發現，叢集會非常低概率地出現節點NotReady情況。據我們觀察，這個問題差不多每個月，就會有一兩個客戶遇到。在節點NotReady之後，叢集Master沒有辦法對這個節點做任何控制，比如下發新的Pod，再比如抓取節點上正在執行Pod的實時資訊。

需要知道的Kubernetes知識

這裡我稍微補充一點Kubernetes叢集的基本知識。Kubernetes叢集的“硬體基礎”，是以單機形態存在的叢集節點。這些節點可以是物理機，也可以是虛擬機器。叢集節點分為Master和Worker節點。Master節點主要用來負載叢集管控元件，比如排程器和控制器。而Worker節點主要用來跑業務。Kubelet是跑在各個節點上的代理，它負責與管控元件溝通，並按照管控元件的指示，直接管理Worker節點。

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

什麼是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

Docker Daemon呼叫棧分析

Docker作為阿里雲Kubernetes叢集使用的容器runtime，在1.11之後，被拆分成了多個元件以適應OCI標準。拆分之後，其包括docker daemon，containerd，containerd-shim以及runC。元件containerd負責叢集節點上容器的生命週期管理，並向上為docker daemon提供gRPC介面。

在這個問題中，既然PLEG認為容器執行是出了問題，我們需要先從docker daemon程序看起。我們可以使用kill -USR1 <pid>命令傳送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。

Containerd呼叫棧分析

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

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

這個執行緒的核心任務，就是依靠runC去建立容器程序。而在容器啟動之後，runC程序會退出。所以下一步，我們自然而然會想到，runC是不是有順利完成自己的任務。檢視程序列表，我們會發現，系統中有個別runC程序，還在執行，這不是預期內的行為。容器的啟動，跟程序的啟動，耗時應該是差不對的，系統裡有正在執行的runC程序，則說明runC不能正常啟動容器。

什麼是Dbus

RunC請求Dbus

容器runtime的runC命令，是libcontainer的一個簡單的封裝。這個工具可以用來管理單個容器，比如容器建立，或者容器刪除。在上節的最後，我們發現runC不能完成建立容器的任務。我們可以把對應的程序殺掉，然後在命令列用同樣的命令嘗試啟動容器，同時用strace追蹤整個過程。

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

原因並不在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說起。

沒用的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某一個checkin改寫了UseSystemd這個函式，而這個函式被用來測試，systemd的某些功能是否可用。UseSystemd這個函式在很多地方被呼叫，比如建立容器，或者檢視容器效能等操作。

程式碼分析

這個問題在線上所有Kubernetes叢集中，發生的頻率大概是一個月兩例。問題一直在發生，且只能在問題發生之後，通過重啟systemd來處理，這風險極大。

我們分別給systemd和runC社群提交了bug，但是一個很現實的問題是，他們並沒有像阿里雲這樣的線上環境，他們重現這個問題的概率幾乎是零，所以這個問題沒有辦法指望社群來解決。硬骨頭還得我們自己啃。

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

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

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溢位的時候立刻出現，則證明了我們的結論。

怎麼判斷叢集節點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，從根本上解決這個問題。

https://github.com/lnykryn/systemd-rhel/pull/322

作者：shengdong

原文連結​

本文為雲棲社群原創內容，未經