之前分享過一例集群節(jié)點(diǎn)NotReady的問題。在那個(gè)問題中，我們的排查路勁，從K8S集群到容器運(yùn)行時(shí)，再到sdbus和systemd，不可謂不復(fù)雜。那個(gè)問題目前已經(jīng)在systemd中做了修復(fù)，所以基本上能看到那個(gè)問題的幾率是越來越低了。

但是，集群節(jié)點(diǎn)就緒問題還是有的，然而原因卻有所不同。

今天這篇文章，跟大家分享另外一例集群節(jié)點(diǎn)NotReady的問題。這個(gè)問題和之前那個(gè)問題相比，排查路勁完全不同。作為姊妹篇分享給大家。

問題現(xiàn)象

這個(gè)問題的現(xiàn)象，也是集群節(jié)點(diǎn)會(huì)變成NotReady狀態(tài)。問題可以通過重啟節(jié)點(diǎn)暫時(shí)解決，但是在經(jīng)過大概20天左右之后，問題會(huì)再次出現(xiàn)。

問題出現(xiàn)之后，如果我們重啟節(jié)點(diǎn)上kubelet，則節(jié)點(diǎn)會(huì)變成Ready狀態(tài)，但這種狀態(tài)只會(huì)持續(xù)三分鐘。這是一個(gè)特別的情況。

大邏輯

在具體分析這個(gè)問題之前，我們先來看一下集群節(jié)點(diǎn)就緒狀態(tài)背后的大邏輯。K8S集群中，與節(jié)點(diǎn)就緒狀態(tài)有關(guān)的組件，主要有四個(gè)，分別是集群的核心數(shù)據(jù)庫etcd，集群的入口API Server，節(jié)點(diǎn)控制器以及駐守在集群節(jié)點(diǎn)上，直接管理節(jié)點(diǎn)的kubelet。

一方面，kubelet扮演的是集群控制器的角色，它定期從API Server獲取Pod等相關(guān)資源的信息，并依照這些信息，控制運(yùn)行在節(jié)點(diǎn)上Pod的執(zhí)行；另外一方面，kubelet作為節(jié)點(diǎn)狀況的監(jiān)視器，它獲取節(jié)點(diǎn)信息，并以集群客戶端的角色，把這些狀況同步到API Server。

在這個(gè)問題中，kubelet扮演的是第二種角色。

Kubelet會(huì)使用上圖中的NodeStatus機(jī)制，定期檢查集群節(jié)點(diǎn)狀況，并把節(jié)點(diǎn)狀況同步到API Server。而NodeStatus判斷節(jié)點(diǎn)就緒狀況的一個(gè)主要依據(jù)，就是PLEG。

PLEG是Pod Lifecycle Events Generator的縮寫，基本上它的執(zhí)行邏輯，是定期檢查節(jié)點(diǎn)上Pod運(yùn)行情況，如果發(fā)現(xiàn)感興趣的變化，PLEG就會(huì)把這種變化包裝成Event發(fā)送給Kubelet的主同步機(jī)制syncLoop去處理。但是，在PLEG的Pod檢查機(jī)制不能定期執(zhí)行的時(shí)候，NodeStatus機(jī)制就會(huì)認(rèn)為，這個(gè)節(jié)點(diǎn)的狀況是不對(duì)的，從而把這種狀況同步到API Server。

而最終把kubelet上報(bào)的節(jié)點(diǎn)狀況，落實(shí)到節(jié)點(diǎn)狀態(tài)的是節(jié)點(diǎn)控制這個(gè)組件。這里我故意區(qū)分了kubelet上報(bào)的節(jié)點(diǎn)狀況，和節(jié)點(diǎn)的最終狀態(tài)。因?yàn)榍罢?#xff0c;其實(shí)是我們describe node時(shí)看到的Condition，而后者是真正節(jié)點(diǎn)列表里的NotReady狀態(tài)。

就緒三分鐘

在問題發(fā)生之后，我們重啟kubelet，節(jié)點(diǎn)三分鐘之后才會(huì)變成NotReady狀態(tài)。這個(gè)現(xiàn)象是問題的一個(gè)關(guān)鍵切入點(diǎn)。

在解釋它之前，請(qǐng)大家看一下官方這張PLEG示意圖。這個(gè)圖片主要展示了兩個(gè)過程。一方面，kubelet作為集群控制器，從API Server處獲取pod spec changes，然后通過創(chuàng)建worker線程來創(chuàng)建或結(jié)束掉pod；另外一方面，PLEG定期檢查容器狀態(tài)，然后把狀態(tài)，以事件的形式反饋給kubelet。

在這里，PLEG有兩個(gè)關(guān)鍵的時(shí)間參數(shù)，一個(gè)是檢查的執(zhí)行間隔，另外一個(gè)是檢查的超時(shí)時(shí)間。以默認(rèn)情況為準(zhǔn)，PLEG檢查會(huì)間隔一秒，換句話說，每一次檢查過程執(zhí)行之后，PLEG會(huì)等待一秒鐘，然后進(jìn)行下一次檢查；而每一次檢查的超時(shí)時(shí)間是三分鐘，如果一次PLEG檢查操作不能在三分鐘內(nèi)完成，那么這個(gè)狀況，會(huì)被上一節(jié)提到的NodeStatus機(jī)制，當(dāng)做集群節(jié)點(diǎn)NotReady的憑據(jù)，同步給API Server。

而我們之所以觀察到節(jié)點(diǎn)會(huì)在重啟kubelet之后就緒三分鐘，是因?yàn)閗ubelet重啟之后，第一次PLEG檢查操作就沒有順利結(jié)束。節(jié)點(diǎn)就緒狀態(tài)，直到三分鐘超時(shí)之后，才被同步到集群。

如下圖，上邊一行表示正常情況下PLEG的執(zhí)行流程，下邊一行則表示有問題的情況。relist是檢查的主函數(shù)。

止步不前的PLEG

了解了原理，我們來看一下PLEG的日志。日志基本上可以分為兩部分，其中skipping pod synchronization這部分是kubelet同步函數(shù)syncLoop輸出的，說明它跳過了一次pod同步；而剩余PLEG is not healthy: pleg was last seen active ago; threshold is 3m0s，則很清楚的展現(xiàn)了，上一節(jié)提到的relist超時(shí)三分鐘的問題。

17:08:22.299597 kubelet skipping pod synchronization - [PLEG is not healthy: pleg was last seen active 3m0.000091019s ago; threshold is 3m0s] 17:08:22.399758 kubelet skipping pod synchronization - [PLEG is not healthy: pleg was last seen active 3m0.100259802s ago; threshold is 3m0s] 17:08:22.599931 kubelet skipping pod synchronization - [PLEG is not healthy: pleg was last seen active 3m0.300436887s ago; threshold is 3m0s] 17:08:23.000087 kubelet skipping pod synchronization - [PLEG is not healthy: pleg was last seen active 3m0.700575691s ago; threshold is 3m0s] 17:08:23.800258 kubelet skipping pod synchronization - [PLEG is not healthy: pleg was last seen active 3m1.500754856s ago; threshold is 3m0s] 17:08:25.400439 kubelet skipping pod synchronization - [PLEG is not healthy: pleg was last seen active 3m3.100936232s ago; threshold is 3m0s] 17:08:28.600599 kubelet skipping pod synchronization - [PLEG is not healthy: pleg was last seen active 3m6.301098811s ago; threshold is 3m0s] 17:08:33.600812 kubelet skipping pod synchronization - [PLEG is not healthy: pleg was last seen active 3m11.30128783s ago; threshold is 3m0s] 17:08:38.600983 kubelet skipping pod synchronization - [PLEG is not healthy: pleg was last seen active 3m16.301473637s ago; threshold is 3m0s] 17:08:43.601157 kubelet skipping pod synchronization - [PLEG is not healthy: pleg was last seen active 3m21.301651575s ago; threshold is 3m0s] 17:08:48.601331 kubelet skipping pod synchronization - [PLEG is not healthy: pleg was last seen active 3m26.301826001s ago; threshold is 3m0s]

能直接看到relist函數(shù)執(zhí)行情況的，是kubelet的調(diào)用棧。我們只要向kubelet進(jìn)程發(fā)送SIGABRT信號(hào)，golang運(yùn)行時(shí)就會(huì)幫我們輸出kubelet進(jìn)程的所有調(diào)用棧。需要注意的是，這個(gè)操作會(huì)殺死kubelet進(jìn)程。但是因?yàn)檫@個(gè)問題中，重啟kubelet并不會(huì)破壞重現(xiàn)環(huán)境，所以影響不大。

以下調(diào)用棧是PLEG relist函數(shù)的調(diào)用棧。從下往上，我們可以看到，relist等在通過grpc獲取PodSandboxStatus。

kubelet: k8s.io/kubernetes/vendor/google.golang.org/grpc/transport.(*Stream).Header() kubelet: k8s.io/kubernetes/vendor/google.golang.org/grpc.recvResponse() kubelet: k8s.io/kubernetes/vendor/google.golang.org/grpc.invoke() kubelet: k8s.io/kubernetes/vendor/google.golang.org/grpc.Invoke() kubelet: k8s.io/kubernetes/pkg/kubelet/apis/cri/runtime/v1alpha2.(*runtimeServiceClient).PodSandboxStatus() kubelet: k8s.io/kubernetes/pkg/kubelet/remote.(*RemoteRuntimeService).PodSandboxStatus() kubelet: k8s.io/kubernetes/pkg/kubelet/kuberuntime.instrumentedRuntimeService.PodSandboxStatus() kubelet: k8s.io/kubernetes/pkg/kubelet/kuberuntime.(*kubeGenericRuntimeManager).GetPodStatus() kubelet: k8s.io/kubernetes/pkg/kubelet/pleg.(*GenericPLEG).updateCache() kubelet: k8s.io/kubernetes/pkg/kubelet/pleg.(*GenericPLEG).relist() kubelet: k8s.io/kubernetes/pkg/kubelet/pleg.(*GenericPLEG).(k8s.io/kubernetes/pkg/kubelet/pleg.relist)-fm() kubelet: k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil.func1(0xc420309260) kubelet: k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil() kubelet: k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.Until()

使用PodSandboxStatus搜索kubelet調(diào)用棧，很容易找到下邊這個(gè)線程，此線程是真正查詢Sandbox狀態(tài)的線程，從下往上看，我們會(huì)發(fā)現(xiàn)這個(gè)線程在Plugin Manager里嘗試去拿一個(gè)Mutex。

kubelet: sync.runtime_SemacquireMutex()kubelet: sync.(*Mutex).Lock() kubelet: k8s.io/kubernetes/pkg/kubelet/dockershim/network.(*PluginManager).GetPodNetworkStatus() kubelet: k8s.io/kubernetes/pkg/kubelet/dockershim.(*dockerService).getIPFromPlugin() kubelet: k8s.io/kubernetes/pkg/kubelet/dockershim.(*dockerService).getIP() kubelet: k8s.io/kubernetes/pkg/kubelet/dockershim.(*dockerService).PodSandboxStatus() kubelet: k8s.io/kubernetes/pkg/kubelet/apis/cri/runtime/v1alpha2._RuntimeService_PodSandboxStatus_Handler() kubelet: k8s.io/kubernetes/vendor/google.golang.org/grpc.(*Server).processUnaryRPC() kubelet: k8s.io/kubernetes/vendor/google.golang.org/grpc.(*Server).handleStream() kubelet: k8s.io/kubernetes/vendor/google.golang.org/grpc.(*Server).serveStreams.func1.1() kubelet: created by k8s.io/kubernetes/vendor/google.golang.org/grpc.(*Server).serveStreams.func1

而這個(gè)Mutex只有在Plugin Manager里邊有用到，所以我們查看所有Plugin Manager相關(guān)的調(diào)用棧。線程中一部分在等Mutex，而剩余的都是在等Terway cni plugin。

kubelet: syscall.Syscall6()kubelet: os.(*Process).blockUntilWaitable() kubelet: os.(*Process).wait()kubelet: os.(*Process).Wait() kubelet: os/exec.(*Cmd).Wait()kubelet: os/exec.(*Cmd).Run() kubelet: k8s.io/kubernetes/vendor/github.com/containernetworking/cni/pkg/invoke.(*RawExec).ExecPlugin() kubelet: k8s.io/kubernetes/vendor/github.com/containernetworking/cni/pkg/invoke.(*PluginExec).WithResult() kubelet: k8s.io/kubernetes/vendor/github.com/containernetworking/cni/pkg/invoke.ExecPluginWithResult() kubelet: k8s.io/kubernetes/vendor/github.com/containernetworking/cni/libcni.(*CNIConfig).AddNetworkList() kubelet: k8s.io/kubernetes/pkg/kubelet/dockershim/network/cni.(*cniNetworkPlugin).addToNetwork() kubelet: k8s.io/kubernetes/pkg/kubelet/dockershim/network/cni.(*cniNetworkPlugin).SetUpPod() kubelet: k8s.io/kubernetes/pkg/kubelet/dockershim/network.(*PluginManager).SetUpPod() kubelet: k8s.io/kubernetes/pkg/kubelet/dockershim.(*dockerService).RunPodSandbox() kubelet: k8s.io/kubernetes/pkg/kubelet/apis/cri/runtime/v1alpha2._RuntimeService_RunPodSandbox_Handler() kubelet: k8s.io/kubernetes/vendor/google.golang.org/grpc.(*Server).processUnaryRPC() kubelet: k8s.io/kubernetes/vendor/google.golang.org/grpc.(*Server).handleStream() kubelet: k8s.io/kubernetes/vendor/google.golang.org/grpc.(*Server).serveStreams.func1.1()

無響應(yīng)的Terwayd

在進(jìn)一步解釋這個(gè)問題之前，我們需要區(qū)分下Terway和Terwayd。本質(zhì)上來說，Terway和Terwayd是客戶端服務(wù)器的關(guān)系，這跟flannel和flanneld之間的關(guān)系是一樣的。Terway是按照kubelet的定義，實(shí)現(xiàn)了cni接口的插件。

而在上一節(jié)最后，我們看到的問題，是kubelet調(diào)用CNI terway去配置pod網(wǎng)絡(luò)的時(shí)候，Terway長(zhǎng)時(shí)間無響應(yīng)。正常情況下這個(gè)操作應(yīng)該是秒級(jí)的，非常快速。而出問題的時(shí)候，Terway沒有正常完成任務(wù)，因而我們?cè)诩汗?jié)點(diǎn)上看到大量terway進(jìn)程堆積。

同樣的，我們可以發(fā)送SIGABRT給這些terway插件進(jìn)程，來打印出進(jìn)程的調(diào)用棧。下邊是其中一個(gè)terway的調(diào)用棧。這個(gè)線程在執(zhí)行cmdDel函數(shù)，其作用是刪除一個(gè)pod網(wǎng)絡(luò)相關(guān)配置。

kubelet: net/rpc.(*Client).Call() kubelet: main.rpcCall()kubelet: main.cmdDel() kubelet: github.com/AliyunContainerService/terway/vendor/github.com/containernetworking/cni/pkg/skel.(*dispatcher).checkVersionAndCall() kubelet: github.com/AliyunContainerService/terway/vendor/github.com/containernetworking/cni/pkg/skel.(*dispatcher).pluginMain() kubelet: github.com/AliyunContainerService/terway/vendor/github.com/containernetworking/cni/pkg/skel.PluginMainWithError() kubelet: github.com/AliyunContainerService/terway/vendor/github.com/containernetworking/cni/pkg/skel.PluginMain()

以上線程通過rpc調(diào)用terwayd，來真正的移除pod網(wǎng)絡(luò)。所以我們需要進(jìn)一步排查terwayd的調(diào)用棧來進(jìn)一步定位此問題。Terwayd作為Terway的服務(wù)器端，其接受Terway的遠(yuǎn)程調(diào)用，并替Terway完成其cmdAdd或者cmdDel來創(chuàng)建或者移除pod網(wǎng)絡(luò)配置。

我們?cè)谏线叺慕貓D里可以看到，集群節(jié)點(diǎn)上有成千Terway進(jìn)程，他們都在等待Terwayd，所以實(shí)際上Terwayd里，也有成千的線程在處理Terway的請(qǐng)求。

使用下邊的命令，可以在不重啟Terwayd的情況下，輸出調(diào)用棧。

curl? --unix-socket /var/run/eni/eni.socket 'http:/debug/pprof/goroutine?debug=2'

因?yàn)門erwayd的調(diào)用棧非常復(fù)雜，而且?guī)缀跛械木€程都在等鎖，直接去分析鎖的等待持有關(guān)系比較復(fù)雜。這個(gè)時(shí)候我們可以使用“時(shí)間大法”，即假設(shè)最早進(jìn)入等待狀態(tài)的線程，大概率是持有鎖的線程。

經(jīng)過調(diào)用棧和代碼分析，我們發(fā)現(xiàn)下邊這個(gè)是等待時(shí)間最長(zhǎng)（1595分鐘），且拿了鎖的線程。而這個(gè)鎖會(huì)block所有創(chuàng)建或者銷毀pod網(wǎng)絡(luò)的線程。

goroutine 67570 [syscall, 1595 minutes, locked to thread]: syscall.Syscall6() github.com/AliyunContainerService/terway/vendor/golang.org/x/sys/unix.recvfrom() github.com/AliyunContainerService/terway/vendor/golang.org/x/sys/unix.Recvfrom() github.com/AliyunContainerService/terway/vendor/github.com/vishvananda/netlink/nl.(*NetlinkSocket).Receive() github.com/AliyunContainerService/terway/vendor/github.com/vishvananda/netlink/nl.(*NetlinkRequest).Execute() github.com/AliyunContainerService/terway/vendor/github.com/vishvananda/netlink.(*Handle).LinkSetNsFd() github.com/AliyunContainerService/terway/vendor/github.com/vishvananda/netlink.LinkSetNsFd() github.com/AliyunContainerService/terway/daemon.SetupVethPair()github.com/AliyunContainerService/terway/daemon.setupContainerVeth.func1() github.com/AliyunContainerService/terway/vendor/github.com/containernetworking/plugins/pkg/ns.(*netNS).Do.func1() github.com/AliyunContainerService/terway/vendor/github.com/containernetworking/plugins/pkg/ns.(*netNS).Do.func2()

原因深入分析前一個(gè)線程的調(diào)用棧，我們可以確定三件事情。第一，Terwayd使用了netlink這個(gè)庫來管理節(jié)點(diǎn)上的虛擬網(wǎng)卡，IP地址及路由等資源，且netlink實(shí)現(xiàn)了類似iproute2的功能；第二，netlink使用socket直接和內(nèi)核通信；第三，以上線程等在recvfrom系統(tǒng)調(diào)用上。

這樣的情況下，我們需要去查看這個(gè)線程的內(nèi)核調(diào)用棧，才能進(jìn)一步確認(rèn)這個(gè)線程等待的原因。因?yàn)閺膅oroutine線程號(hào)比較不容易找到這個(gè)線程的系統(tǒng)線程id，這里我們通過抓取系統(tǒng)的core dump來找出上邊線程的內(nèi)核調(diào)用棧。

在內(nèi)核調(diào)用棧中，搜索recvfrom，定位到下邊這個(gè)線程。基本上從下邊的調(diào)用棧上，我們只能確定，此線程等在recvfrom函數(shù)上。

PID: 19246? TASK: ffff880951f70fd0? CPU: 16? COMMAND: "terwayd" #0 [ffff880826267a40] __schedule at ffffffff816a8f65 #1 [ffff880826267aa8] schedule at ffffffff816a94e9 #2 [ffff880826267ab8] schedule_timeout at ffffffff816a6ff9 #3 [ffff880826267b68] __skb_wait_for_more_packets at ffffffff81578f80 #4 [ffff880826267bd0] __skb_recv_datagram at ffffffff8157935f #5 [ffff880826267c38] skb_recv_datagram at ffffffff81579403 #6 [ffff880826267c58] netlink_recvmsg at ffffffff815bb312 #7 [ffff880826267ce8] sock_recvmsg at ffffffff8156a88f #8 [ffff880826267e58] SYSC_recvfrom at ffffffff8156aa08 #9 [ffff880826267f70] sys_recvfrom at ffffffff8156b2fe #10 [ffff880826267f80] tracesys at ffffffff816b5212 (via system_call)

這個(gè)問題進(jìn)一步深入排查，是比較困難的，這顯然是一個(gè)內(nèi)核問題，或者內(nèi)核相關(guān)的問題。我們翻遍了整個(gè)內(nèi)核core，檢查了所有的線程調(diào)用棧，看不到其他可能與這個(gè)問題相關(guān)聯(lián)的線程。

修復(fù)

這個(gè)問題的修復(fù)基于一個(gè)假設(shè)，就是netlink并不是100%可靠的。netlink可以響應(yīng)很慢，甚至完全沒有響應(yīng)。所以我們可以給netlink操作增加超時(shí)，從而保證就算某一次netlink調(diào)用不能完成的情況下，terwayd也不會(huì)被阻塞。

總結(jié)

在節(jié)點(diǎn)就緒狀態(tài)這種場(chǎng)景下，kubelet實(shí)際上實(shí)現(xiàn)了節(jié)點(diǎn)的心跳機(jī)制。kubelet會(huì)定期把節(jié)點(diǎn)相關(guān)的各種狀態(tài)，包括內(nèi)存，PID，磁盤，當(dāng)然包括這個(gè)文章中關(guān)注的就緒狀態(tài)等，同步到集群管控。kubelet在監(jiān)控或者管理集群節(jié)點(diǎn)的過程中，使用了各種插件來直接操作節(jié)點(diǎn)資源。這包括網(wǎng)絡(luò)，磁盤，甚至容器運(yùn)行時(shí)等插件，這些插件的狀況，會(huì)直接應(yīng)用kubelet甚至節(jié)點(diǎn)的狀態(tài)。

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

總結(jié)

以上是生活随笔為你收集整理的K8S从懵圈到熟练 - 节点下线姊妹篇的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問題。

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