作者：shengdong
之前分享過一例叢集節點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甚至節點的狀态。