排查完全陌生的問題，完全不熟悉的系統(tǒng)組件，是售后工程師的一大工作樂趣，當(dāng)然也是挑戰(zhàn)。今天借這篇文章，跟大家分析一例這樣的問題。排查過程中，需要理解一些自己完全陌生的組件，比如systemd和dbus。但是排查問題的思路和方法基本上還是可以復(fù)用了，希望對(duì)大家有所幫助。

問題一直在發(fā)生

I'm NotReady

阿里云有自己的Kubernetes容器集群產(chǎn)品。隨著Kubernetes集群出貨量的劇增，線上用戶零星的發(fā)現(xiàn)，集群會(huì)非常低概率地出現(xiàn)節(jié)點(diǎn)NotReady情況。據(jù)我們觀察，這個(gè)問題差不多每個(gè)月，就會(huì)有一兩個(gè)客戶遇到。在節(jié)點(diǎn)NotReady之后，集群Master沒有辦法對(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和Worker節(jié)點(diǎn)。Master節(jié)點(diǎn)主要用來負(fù)載集群管控組件，比如調(diào)度器和控制器。而Worker節(jié)點(diǎn)主要用來跑業(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è)問題出現(xiàn)的時(shí)候，使用systemctl命令查看kubelet狀態(tài)，發(fā)現(xiàn)它作為systemd管理的一個(gè)daemon，是運(yùn)行正常的。當(dāng)我們用journalctl查看kubelet日志的時(shí)候，發(fā)現(xiàn)下邊的錯(cuò)誤。

什么是PLEG

這個(gè)報(bào)錯(cuò)很清楚的告訴我們，容器runtime是不工作的，且PLEG是不健康的。這里容器runtime指的就是docker daemon。Kubelet通過直接操作docker daemon來控制容器的生命周期。而這里的PLEG，指的是pod lifecycle event generator。PLEG是kubelet用來檢查容器runtime的健康檢查機(jī)制。這件事情本來可以由kubelet使用polling的方式來做。但是polling有其成本上的缺陷，所以PLEG應(yīng)用而生。PLEG嘗試以一種“中斷”的形式，來實(shí)現(xiàn)對(duì)容器runtime的健康檢查，雖然實(shí)際上，它同時(shí)用了polling和”中斷”兩種機(jī)制。

基本上看到上邊的報(bào)錯(cuò)，我們可以確認(rèn)，容器runtime出了問題。在有問題的節(jié)點(diǎn)上，通過docker命令嘗試運(yùn)行新的容器，命令會(huì)沒有響應(yīng)。這說明上邊的報(bào)錯(cuò)是準(zhǔn)確的.

容器runtime

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è)問題中，既然PLEG認(rèn)為容器運(yùn)行是出了問題，我們需要先從docker daemon進(jìn)程看起。我們可以使用kill -USR1 <pid>命令發(fā)送USR1信號(hào)給docker daemon，而docker daemon收到信號(hào)之后，會(huì)把其所有線程調(diào)用棧輸出到文件/var/run/docker文件夾里。

Docker daemon進(jìn)程的調(diào)用棧相對(duì)是比較容易分析的。稍微留意，我們會(huì)發(fā)現(xiàn)大多數(shù)的調(diào)用棧都類似下圖中的樣子。通過觀察棧上每個(gè)函數(shù)的名字，以及函數(shù)所在的文件（模塊）名稱，我們可以看到，這個(gè)調(diào)用棧下半部分，是進(jìn)程接到http請(qǐng)求，做請(qǐng)求路由的過程；而上半部分則進(jìn)入實(shí)際的處理函數(shù)。最終處理函數(shù)進(jìn)入等待狀態(tài)，等待的是一個(gè)mutex實(shí)例。

到這里，我們需要稍微看一下ContainerInspectCurrent這個(gè)函數(shù)的實(shí)現(xiàn)，而最重要的是，我們能搞明白，這個(gè)函數(shù)的第一個(gè)參數(shù)，就是mutex的指針。使用這個(gè)指針?biāo)阉髡麄€(gè)調(diào)用棧文件，我們會(huì)找出，所有等在這個(gè)mutex上邊的線程。同時(shí)，我們可以看到下邊這個(gè)線程。

這個(gè)線程上，函數(shù)ContainerExecStart也是在處理具體請(qǐng)求的時(shí)候，收到了這個(gè)mutex這個(gè)參數(shù)。但不同的是，ContainerExecStart并沒有在等待mutex，而是已經(jīng)拿到了mutex的所有權(quán)，并把執(zhí)行邏輯轉(zhuǎn)向了containerd調(diào)用。關(guān)于這一點(diǎn)，我們可以使用代碼來驗(yàn)證。前邊我們提到過，containerd向上通過gRPC對(duì)docker daemon提供接口。此調(diào)用棧上半部分內(nèi)容，正是docker daemon在通過gRPC請(qǐng)求來呼叫containerd。

Containerd調(diào)用棧分析

與輸出docker daemon的調(diào)用棧類似，我們可以通過kill -SIGUSR1 <pid>命令來輸出containerd的調(diào)用棧。不同的是，這次調(diào)用棧會(huì)直接輸出到messages日志。

Containerd作為一個(gè)gRPC的服務(wù)器，它會(huì)在接到docker daemon的遠(yuǎn)程請(qǐng)求之后，新建一個(gè)線程去處理這次請(qǐng)求。關(guān)于gRPC的細(xì)節(jié)，我們這里其實(shí)不用關(guān)注太多。在這次請(qǐng)求的客戶端調(diào)用棧上，可以看到這次調(diào)用的核心函數(shù)是Start一個(gè)進(jìn)程。我們在containerd的調(diào)用棧里搜索Start，Process以及process.go等字段，很容易發(fā)現(xiàn)下邊這個(gè)線程。

這個(gè)線程的核心任務(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ù)期內(nèi)的行為。容器的啟動(dòng)，跟進(jìn)程的啟動(dòng)，耗時(shí)應(yīng)該是差不對(duì)的，系統(tǒng)里有正在運(yùn)行的runC進(jìn)程，則說明runC不能正常啟動(dòng)容器。

什么是Dbus

RunC請(qǐng)求Dbus

容器runtime的runC命令，是libcontainer的一個(gè)簡單的封裝。這個(gè)工具可以用來管理單個(gè)容器，比如容器創(chuàng)建，或者容器刪除。在上節(jié)的最后，我們發(fā)現(xiàn)runC不能完成創(chuàng)建容器的任務(wù)。我們可以把對(duì)應(yīng)的進(jìn)程殺掉，然后在命令行用同樣的命令嘗試啟動(dòng)容器，同時(shí)用strace追蹤整個(gè)過程。

分析發(fā)現(xiàn)，runC停在了向帶有org.free字段的dbus寫數(shù)據(jù)的地方。那什么是dbus呢？在Linux上，dbus是一種進(jìn)程間進(jìn)行消息通信的機(jī)制。

原因并不在Dbus

我們可以使用busctl命令列出系統(tǒng)現(xiàn)有的所有bus。如下圖，在問題發(fā)生的時(shí)候，我看到客戶集群節(jié)點(diǎn)Name的編號(hào)非常大。所以我傾向于認(rèn)為，dbus某些相關(guān)的數(shù)據(jù)結(jié)構(gòu)，比如Name，耗盡了引起了這個(gè)問題。

Dbus機(jī)制的實(shí)現(xiàn)，依賴于一個(gè)組件叫做dbus-daemon。如果真的是dbus相關(guān)數(shù)據(jù)結(jié)構(gòu)耗盡，那么重啟這個(gè)daemon，應(yīng)該是可以解決這個(gè)問題。但不幸的是，問題并沒有這么直接。重啟dbus-daemon之后，問題依然存在。

在上邊用strace追蹤runC的截圖中，我提到了，runC卡在向帶有org.free字段的bus寫數(shù)據(jù)的地方。在busctl輸出的bus列表里，顯然帶有這個(gè)字段的bus，都在被systemd使用。這時(shí)，我們用systemctl daemon-reexec來重啟systemd，問題消失了。所以基本上我們可以判斷一個(gè)方向：問題可能跟systemd有關(guān)系。

Systemd是硬骨頭

Systemd是相當(dāng)復(fù)雜的一個(gè)組件，尤其對(duì)沒有做過相關(guān)開發(fā)工作的同學(xué)來說，比如我自己。基本上，排查systemd的問題，我用到了四個(gè)方法，（調(diào)試級(jí)別）日志，core dump，代碼分析，以及l(fā)ive debugging。其中第一個(gè)，第三個(gè)和第四個(gè)結(jié)合起來使用，讓我在經(jīng)過幾天的鏖戰(zhàn)之后，找到了問題的原因。但是這里我們先從“沒用”的core dump說起。

沒用的Core Dump

因?yàn)橹貑ystemd解決了問題，而這個(gè)問題本身，是runC在使用dbus和systemd通信的時(shí)候沒有了響應(yīng)，所以我們需要驗(yàn)證的第一件事情，就是systemd不是有關(guān)鍵線程被鎖住了。查看core dump里所有線程，只有以下一個(gè)線程，此線程并沒有被鎖住，它在等待dbus事件，以便做出響應(yīng)。

零散的信息

因?yàn)闊o計(jì)可施，所以只能做各種測試、嘗試。使用busctl tree命令，可以輸出所有bus上對(duì)外暴露的接口。從輸出結(jié)果看來，org.freedesktop.systemd1這個(gè)bus是不能響應(yīng)接口查詢請(qǐng)求的。

使用下邊的命令，觀察org.freedesktop.systemd1上接受到的所以請(qǐng)求，可以看到，在正常系統(tǒng)里，有大量Unit創(chuàng)建刪除的消息，但是有問題的系統(tǒng)里，這個(gè)bus上完全沒有任何消息。

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

分析問題發(fā)生前后的系統(tǒng)日志，runC在重復(fù)的跑一個(gè)libcontainer_%d_systemd_test_default.slice測試，這個(gè)測試非常頻繁，但是當(dāng)問題發(fā)生的時(shí)候，這個(gè)測試就停止了。所以直覺告訴我，這個(gè)問題，可能和這個(gè)測試，有很大的關(guān)系。

另外，我使用systemd-analyze命令，打開了systemd的調(diào)試日志，發(fā)現(xiàn)systemd有Operation not supported的報(bào)錯(cuò)。

根據(jù)以上零散的知識(shí)，只能做出一個(gè)大概的結(jié)論：org.freedesktop.systemd1這個(gè)bus在經(jīng)過大量Unit創(chuàng)建刪除之后，沒有了響應(yīng)。而這些頻繁的Unit創(chuàng)建刪除測試，是runC某一個(gè)checkin改寫了UseSystemd這個(gè)函數(shù)，而這個(gè)函數(shù)被用來測試，systemd的某些功能是否可用。UseSystemd這個(gè)函數(shù)在很多地方被調(diào)用，比如創(chuàng)建容器，或者查看容器性能等操作。

代碼分析

這個(gè)問題在線上所有Kubernetes集群中，發(fā)生的頻率大概是一個(gè)月兩例。問題一直在發(fā)生，且只能在問題發(fā)生之后，通過重啟systemd來處理，這風(fēng)險(xiǎn)極大。

我們分別給systemd和runC社區(qū)提交了bug，但是一個(gè)很現(xiàn)實(shí)的問題是，他們并沒有像阿里云這樣的線上環(huán)境，他們重現(xiàn)這個(gè)問題的概率幾乎是零，所以這個(gè)問題沒有辦法指望社區(qū)來解決。硬骨頭還得我們自己啃。

在上一節(jié)最后，我們看到了，問題出現(xiàn)的時(shí)候，systemd會(huì)輸出一些Operation not supported報(bào)錯(cuò)。這個(gè)報(bào)錯(cuò)看起來和問題本身風(fēng)馬牛不相及，但是直覺告訴我，這，或許是離問題最近的一個(gè)地方，所以我決定，先搞清楚這個(gè)報(bào)錯(cuò)因何而來。

Systemd代碼量比較大，而報(bào)這個(gè)錯(cuò)誤的地方也比較多。通過大量的代碼分析（這里略去一千字），我發(fā)現(xiàn)有幾處比較可疑地方，有了這些可疑的地方，接下來需要做的事情，就是等待。在等待了三周以后，終于有線上集群，再次重現(xiàn)了這個(gè)問題。

Live Debugging

在征求客戶同意之后，下載systemd調(diào)試符號(hào)，掛載gdb到systemd上，在可疑的函數(shù)下斷點(diǎn)，continue繼續(xù)執(zhí)行。經(jīng)過多次驗(yàn)證，發(fā)現(xiàn)systemd最終踩到了sd_bus_message_seal這個(gè)函數(shù)里的EOPNOTSUPP報(bào)錯(cuò)。

這個(gè)報(bào)錯(cuò)背后的道理是，systemd使用了一個(gè)變量cookie，來追蹤自己處理的所有dbus message。每次在在加封一個(gè)新的消息的時(shí)候，systemd都會(huì)先把cookie這個(gè)值加一，然后再把這個(gè)cookie值復(fù)制給這個(gè)新的message。

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

另外，在一個(gè)正常的系統(tǒng)上，使用gdb把bus->cookie這個(gè)值改到接近0xffffffff，然后觀察到，問題在cookie溢出的時(shí)候立刻出現(xiàn)，則證明了我們的結(jié)論。

怎么判斷集群節(jié)點(diǎn)NotReady是這個(gè)問題導(dǎo)致的

首先我們需要在有問題的節(jié)點(diǎn)上安裝gdb和systemd debuginfo，然后用命令gdb /usr/lib/systemd/systemd 1把gdb attach到systemd，在函數(shù)sd_bus_send設(shè)置斷點(diǎn)，然后繼續(xù)執(zhí)行。等systemd踩到斷點(diǎn)之后，用p /x bus->cookie查看對(duì)應(yīng)的cookie值，如果此值超過了0xffffffff，那么cookie就溢出了，則必然導(dǎo)致節(jié)點(diǎn)NotReady的問題。確認(rèn)完之后，可以使用quit來detach調(diào)試器。

問題修復(fù)

這個(gè)問題的修復(fù)，并沒有那么直截了當(dāng)。原因之一，是systemd使用了同一個(gè)cookie變量，來兼容dbus1和dbus2。對(duì)于dbus1來說，cookie是32位的，這個(gè)值在經(jīng)過systemd三五個(gè)月頻繁創(chuàng)建刪除Unit之后，是肯定會(huì)溢出的；而dbus2的cookie是64位的，可能到了時(shí)間的盡頭，它也不會(huì)溢出。

另外一個(gè)原因是，我們并不能簡單的讓cookie折返，來解決溢出問題。因?yàn)檫@有可能導(dǎo)致systemd使用同一個(gè)cookie來加封不同的消息，這樣的結(jié)果將是災(zāi)難性的。

最終的修復(fù)方法是，使用32位cookie來同樣處理dbus1和dbus2兩種情形。同時(shí)在cookie達(dá)到0xfffffff的之后下一個(gè)cookie返回0x80000000，用最高位來標(biāo)記cookie已經(jīng)處于溢出狀態(tài)。檢查到cookie處于這種狀態(tài)時(shí)，我們需要檢查是否下一個(gè)cookie正在被其他message使用，來避免cookie沖突。

后記

這個(gè)問題根本原因肯定在systemd，但是runC的函數(shù)UseSystemd使用不那么美麗的方法，去測試systemd的功能，而這個(gè)函數(shù)在整個(gè)容器生命周期管理過程中，被頻繁的觸發(fā)，讓這個(gè)低概率問題的發(fā)生成為了可能。systemd的修復(fù)已經(jīng)被紅帽接受，預(yù)期不久的將來，我們可以通過升級(jí)systemd，從根本上解決這個(gè)問題。

原文鏈接
本文為云棲社區(qū)原創(chuàng)內(nèi)容，未經(jīng)允許不得轉(zhuǎn)載。

總結(jié)

以上是生活随笔為你收集整理的Kubernetes从懵圈到熟练：读懂这一篇，集群节点不下线的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。