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

阅读原文

本文为云栖社区原创内容，未经容许不得转载。