K8S從懵圈到熟練 - 節點下線姊妹篇

以前分享過一例集羣節點NotReady的問題。在那個問題中，咱們的排查路勁，從K8S集羣到容器運行時，再到sdbus和systemd，不可謂不復雜。那個問題目前已經在systemd中作了修復，因此基本上能看到那個問題的概率是愈來愈低了。

可是，集羣節點就緒問題仍是有的，然而緣由卻有所不一樣。

今天這篇文章，跟你們分享另一例集羣節點NotReady的問題。這個問題和以前那個問題相比，排查路勁徹底不一樣。做爲姊妹篇分享給你們。

問題現象

這個問題的現象，也是集羣節點會變成NotReady狀態。問題能夠經過重啓節點暫時解決，可是在通過大概20天左右以後，問題會再次出現。

問題出現以後，若是咱們重啓節點上kubelet，則節點會變成Ready狀態，但這種狀態只會持續三分鐘。這是一個特別的狀況。

大邏輯

在具體分析這個問題以前，咱們先來看一下集羣節點就緒狀態背後的大邏輯。K8S集羣中，與節點就緒狀態有關的組件，主要有四個，分別是集羣的核心數據庫etcd，集羣的入口API Server，節點控制器以及駐守在集羣節點上，直接管理節點的kubelet。

一方面，kubelet扮演的是集羣控制器的角色，它按期從API Server獲取Pod等相關資源的信息，並依照這些信息，控制運行在節點上Pod的執行；另一方面，kubelet做爲節點情況的監視器，它獲取節點信息，並以集羣客戶端的角色，把這些情況同步到API Server。

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

Kubelet會使用上圖中的NodeStatus機制，按期檢查集羣節點情況，並把節點情況同步到API Server。而NodeStatus判斷節點就緒情況的一個主要依據，就是PLEG。

PLEG是Pod Lifecycle Events Generator的縮寫，基本上它的執行邏輯，是按期檢查節點上Pod運行狀況，若是發現感興趣的變化，PLEG就會把這種變化包裝成Event發送給Kubelet的主同步機制syncLoop去處理。可是，在PLEG的Pod檢查機制不能按期執行的時候，NodeStatus機制就會認爲，這個節點的情況是不對的，從而把這種情況同步到API Server。

而最終把kubelet上報的節點情況，落實到節點狀態的是節點控制這個組件。這裏我故意區分了kubelet上報的節點情況，和節點的最終狀態。由於前者，實際上是咱們describe node時看到的Condition，然後者是真正節點列表裏的NotReady狀態。

就緒三分鐘

在問題發生以後，咱們重啓kubelet，節點三分鐘以後纔會變成NotReady狀態。這個現象是問題的一個關鍵切入點。

在解釋它以前，請你們看一下官方這張PLEG示意圖。這個圖片主要展現了兩個過程。一方面，kubelet做爲集羣控制器，從API Server處獲取pod spec changes，而後經過建立worker線程來建立或結束掉pod；另一方面，PLEG按期檢查容器狀態，而後把狀態，以事件的形式反饋給kubelet。

在這裏，PLEG有兩個關鍵的時間參數，一個是檢查的執行間隔，另一個是檢查的超時時間。以默認狀況爲準，PLEG檢查會間隔一秒，換句話說，每一次檢查過程執行以後，PLEG會等待一秒鐘，而後進行下一次檢查；而每一次檢查的超時時間是三分鐘，若是一次PLEG檢查操做不能在三分鐘內完成，那麼這個情況，會被上一節提到的NodeStatus機制，當作集羣節點NotReady的憑據，同步給API Server。

而咱們之因此觀察到節點會在重啓kubelet以後就緒三分鐘，是由於kubelet重啓以後，第一次PLEG檢查操做就沒有順利結束。節點就緒狀態，直到三分鐘超時以後，才被同步到集羣。

以下圖，上邊一行表示正常狀況下PLEG的執行流程，下邊一行則表示有問題的狀況。relist是檢查的主函數。

止步不前的PLEG

瞭解了原理，咱們來看一下PLEG的日誌。日誌基本上能夠分爲兩部分，其中skipping pod synchronization這部分是kubelet同步函數syncLoop輸出的，說明它跳過了一次pod同步；而剩餘PLEG is not healthy: pleg was last seen active ago; threshold is 3m0s，則很清楚的展示了，上一節提到的relist超時三分鐘的問題。

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函數執行狀況的，是kubelet的調用棧。咱們只要向kubelet進程發送SIGABRT信號，golang運行時就會幫咱們輸出kubelet進程的全部調用棧。須要注意的是，這個操做會殺死kubelet進程。可是由於這個問題中，重啓kubelet並不會破壞重現環境，因此影響不大。

如下調用棧是PLEG relist函數的調用棧。從下往上，咱們能夠看到，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調用棧，很容易找到下邊這個線程，此線程是真正查詢Sandbox狀態的線程，從下往上看，咱們會發現這個線程在Plugin Manager裏嘗試去拿一個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

而這個Mutex只有在Plugin Manager裏邊有用到，因此咱們查看全部Plugin Manager相關的調用棧。線程中一部分在等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()

無響應的Terwayd

在進一步解釋這個問題以前，咱們須要區分下Terway和Terwayd。本質上來講，Terway和Terwayd是客戶端服務器的關係，這跟flannel和flanneld之間的關係是同樣的。Terway是按照kubelet的定義，實現了cni接口的插件。

而在上一節最後，咱們看到的問題，是kubelet調用CNI terway去配置pod網絡的時候，Terway長時間無響應。正常狀況下這個操做應該是秒級的，很是快速。而出問題的時候，Terway沒有正常完成任務，於是咱們在集羣節點上看到大量terway進程堆積。

一樣的，咱們能夠發送SIGABRT給這些terway插件進程，來打印出進程的調用棧。下邊是其中一個terway的調用棧。這個線程在執行cmdDel函數，其做用是刪除一個pod網絡相關配置。

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調用terwayd，來真正的移除pod網絡。因此咱們須要進一步排查terwayd的調用棧來進一步定位此問題。Terwayd做爲Terway的服務器端，其接受Terway的遠程調用，並替Terway完成其cmdAdd或者cmdDel來建立或者移除pod網絡配置。

咱們在上邊的截圖裏能夠看到，集羣節點上有成千Terway進程，他們都在等待Terwayd，因此實際上Terwayd裏，也有成千的線程在處理Terway的請求。

使用下邊的命令，能夠在不重啓Terwayd的狀況下，輸出調用棧。

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

由於Terwayd的調用棧很是複雜，並且幾乎全部的線程都在等鎖，直接去分析鎖的等待持有關係比較複雜。這個時候咱們可使用「時間大法」，即假設最先進入等待狀態的線程，大機率是持有鎖的線程。

通過調用棧和代碼分析，咱們發現下邊這個是等待時間最長（1595分鐘），且拿了鎖的線程。而這個鎖會block全部建立或者銷燬pod網絡的線程。

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()

緣由深刻分析前一個線程的調用棧，咱們能夠肯定三件事情。第一，Terwayd使用了netlink這個庫來管理節點上的虛擬網卡，IP地址及路由等資源，且netlink實現了相似iproute2的功能；第二，netlink使用socket直接和內核通訊；第三，以上線程等在recvfrom系統調用上。

這樣的狀況下，咱們須要去查看這個線程的內核調用棧，才能進一步確認這個線程等待的緣由。由於從goroutine線程號比較不容易找到這個線程的系統線程id，這裏咱們經過抓取系統的core dump來找出上邊線程的內核調用棧。

在內核調用棧中，搜索recvfrom，定位到下邊這個線程。基本上從下邊的調用棧上，咱們只能肯定，此線程等在recvfrom函數上。

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)

這個問題進一步深刻排查，是比較困難的，這顯然是一個內核問題，或者內核相關的問題。咱們翻遍了整個內核core，檢查了全部的線程調用棧，看不到其餘可能與這個問題相關聯的線程。

修復

這個問題的修復基於一個假設，就是netlink並非100%可靠的。netlink能夠響應很慢，甚至徹底沒有響應。因此咱們能夠給netlink操做增長超時，從而保證就算某一次netlink調用不能完成的狀況下，terwayd也不會被阻塞。

總結

在節點就緒狀態這種場景下，kubelet實際上實現了節點的心跳機制。kubelet會按期把節點相關的各類狀態，包括內存，PID，磁盤，固然包括這個文章中關注的就緒狀態等，同步到集羣管控。kubelet在監控或者管理集羣節點的過程當中，使用了各類插件來直接操做節點資源。這包括網絡，磁盤，甚至容器運行時等插件，這些插件的情況，會直接應用kubelet甚至節點的狀態。

---

本文做者：shengdong

閱讀原文

本文爲雲棲社區原創內容，未經容許不得轉載。