作者：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甚至節點的狀態。