开发者社区> 阿里云支持与服务> 正文

K8S从懵圈到熟练 - 节点下线姊妹篇

简介: 之前分享过一例集群节点NotReady的问题。在那个问题中,我们的排查路劲,从K8S集群到容器运行时,再到sdbus和systemd,不可谓不复杂。那个问题目前已经在systemd中做了修复,所以基本上能看到那个问题的几率是越来越低了。

之前分享过一例集群节点NotReady的问题。在那个问题中,我们的排查路劲,从K8S集群到容器运行时,再到sdbus和systemd,不可谓不复杂。那个问题目前已经在systemd中做了修复,所以基本上能看到那个问题的几率是越来越低了。

但是,集群节点就绪问题还是有的,然而原因却有所不同。

今天这篇文章,跟大家分享另外一例集群节点NotReady的问题。这个问题和之前那个问题相比,排查路劲完全不同。作为姊妹篇分享给大家。

问题现象

这个问题的现象,也是集群节点会变成NotReady状态。问题可以通过重启节点暂时解决,但是在经过大概20天左右之后,问题会再次出现。

333

问题出现之后,如果我们重启节点上kubelet,则节点会变成Ready状态,但这种状态只会持续三分钟。这是一个特别的情况。

大逻辑

在具体分析这个问题之前,我们先来看一下集群节点就绪状态背后的大逻辑。K8S集群中,与节点就绪状态有关的组件,主要有四个,分别是集群的核心数据库etcd,集群的入口API Server,节点控制器以及驻守在集群节点上,直接管理节点的kubelet。

111

一方面,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状态。

222

就绪三分钟

在问题发生之后,我们重启kubelet,节点三分钟之后才会变成NotReady状态。这个现象是问题的一个关键切入点。

81172457cbfd560dafb029cb277db88f

在解释它之前,请大家看一下官方这张PLEG示意图。这个图片主要展示了两个过程。一方面,kubelet作为集群控制器,从API Server处获取pod spec changes,然后通过创建worker线程来创建或结束掉pod;另外一方面,PLEG定期检查容器状态,然后把状态,以事件的形式反馈给kubelet。

在这里,PLEG有两个关键的时间参数,一个是检查的执行间隔,另外一个是检查的超时时间。以默认情况为准,PLEG检查会间隔一秒,换句话说,每一次检查过程执行之后,PLEG会等待一秒钟,然后进行下一次检查;而每一次检查的超时时间是三分钟,如果一次PLEG检查操作不能在三分钟内完成,那么这个状况,会被上一节提到的NodeStatus机制,当做集群节点NotReady的凭据,同步给API Server。

而我们之所以观察到节点会在重启kubelet之后就绪三分钟,是因为kubelet重启之后,第一次PLEG检查操作就没有顺利结束。节点就绪状态,直到三分钟超时之后,才被同步到集群。

如下图,上边一行表示正常情况下PLEG的执行流程,下边一行则表示有问题的情况。relist是检查的主函数。

Untitled_Diagram_2019_09_09T130328_891

止步不前的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接口的插件。

terway_deploy_diagram

而在上一节最后,我们看到的问题,是kubelet调用CNI terway去配置pod网络的时候,Terway长时间无响应。正常情况下这个操作应该是秒级的,非常快速。而出问题的时候,Terway没有正常完成任务,因而我们在集群节点上看到大量terway进程堆积。

4444

同样的,我们可以发送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甚至节点的状态。

版权声明:如果您发现本社区中有涉嫌抄袭的内容,欢迎发送邮件至:developerteam@list.alibaba-inc.com 进行举报,并提供相关证据,一经查实,本社区将立刻删除涉嫌侵权内容。

分享:
上一篇:Istio从懵圈到熟练 – 二分之一活的微服务
阿里云支持与服务
使用钉钉扫一扫加入圈子
+ 订阅

分享阿里云支持与服务团队最佳实践、经典案例与故障排查。

官方博客
文档