读懂这一篇，集群节点不下线

做者 | 声东  阿里云售后技术专家

导读：排查彻底陌生的问题、彻底不熟悉的系统组件，是售后工程师的一大工做乐趣，固然也是挑战。今天借这篇文章，跟你们分析一例这样的问题。排查过程当中，须要理解一些本身彻底陌生的组件，好比 systemd 和 dbus。可是排查问题的思路和方法基本上仍是能够复用了，但愿对你们有所帮助。

问题一直在发生

1. I'm NotReady

阿里云有本身的 Kubernetes 容器集群产品。随着 Kubernetes 集群出货量的剧增，线上用户零星的发现，集群会很是低几率地出现节点 NotReady 状况。

据咱们观察，这个问题差很少每月就会有一到两个客户遇到。在节点 NotReady 以后，集群 Master 没有办法对这个节点作任何控制，好比下发新的 Pod，再好比抓取节点上正在运行 Pod 的实时信息。

2. 须要知道的 Kubernetes 知识

这里我稍微补充一点 Kubernetes 集群的基本知识。Kubernetes 集群的“硬件基础”，是以单机形态存在的集群节点。这些节点能够是物理机，也能够是虚拟机。集群节点分为 Master 和 Worker 节点。

• Master 节点主要用来负载集群管控组件，好比调度器和控制器；

• 而 Worker 节点主要用来跑业务。Kubelet 是跑在各个节点上的代理，它负责与管控组件沟通，并按照管控组件的指示，直接管理 Worker 节点。

当集群节点进入 NotReady 状态的时候，咱们须要作的第一件事情，确定是检查运行在节点上的 kubelet 是否正常。在这个问题出现的时候，使用 systemctl 命令查看 kubelet 状态，发现它做为 systemd 管理的一个 daemon，是运行正常的。当咱们用 journalctl 查看 kubelet 日志的时候，发现了下边的错误。

3. 什么是 PLEG

这个报错很清楚的告诉咱们，容器 runtime 是不工做的，且 PLEG 是不健康的。这里容器 runtime 指的就是 docker daemon，Kubelet 经过直接操做 docker daemon 来控制容器的生命周期。

而这里的 PLEG，指的是 pod lifecycle event generator。

PLEG 是 kubelet 用来检查容器 runtime 的健康检查机制。这件事情原本能够由 kubelet 使用 polling 的方式来作。可是 polling 有其成本上的缺陷，因此 PLEG 应用而生。PLEG 尝试以一种“中断”的形式，来实现对容器 runtime 的健康检查，虽然它实际上同时用了 polling 和“中断”两种机制。

基本上看到上边的报错，咱们能够确认，容器 runtime 出了问题。在有问题的节点上，经过 docker 命令尝试运行新的容器，命令会没有响应。这说明上边的报错是准确的。

容器 runtime

1. Docker Daemon 调用栈分析

Docker 做为阿里云 Kubernetes 集群使用的容器 runtime，在 1.11 以后，被拆分红了多个组件以适应 OCI 标准。

拆分以后，其包括 docker daemon，containerd，containerd-shim 以及 runC。组件 containerd 负责集群节点上容器的生命周期管理，并向上为 docker daemon 提供 gRPC 接口。

在这个问题中，既然 PLEG 认为容器运行是出了问题，咱们须要先从 docker daemon 进程看起。咱们可使用 kill -USR1 <pid> 命令发送 USR1 信号给 docker daemon，而 docker daemon 收到信号以后，会把其全部线程调用栈输出到文件 /var/run/docker 文件夹里。

Docker daemon 进程的调用栈相对是比较容易分析的。稍微留意，咱们会发现大多数的调用栈都相似下图中的样子。<br />经过观察栈上每一个函数的名字，以及函数所在的文件（模块）名称，咱们能够看到，这个调用栈下半部分，是进程接到 http 请求，作请求路由的过程；而上半部分则进入实际的处理函数。最终处理函数进入等待状态，等待的是一个 mutex 实例。

到这里，咱们须要稍微看一下 ContainerInspectCurrent 这个函数的实现，而最重要的是，咱们能搞明白这个函数的第一个参数，就是 mutex 的指针。使用这个指针搜索整个调用栈文件，咱们会找出，全部等在这个 mutex 上边的线程。

同时，咱们能够看到下边这个线程。

这个线程上，函数 ContainerExecStart 也是在处理具体请求的时候，收到了 mutex 这个参数。但不一样的是，ContainerExecStart 并无在等待 mutex，而是已经拿到了 mutex 的全部权，并把执行逻辑转向了 containerd 调用。关于这一点，咱们可使用代码来验证。

前边咱们提到过，containerd 向上经过 gRPC 对 docker daemon 提供接口。此调用栈上半部份内容，正是 docker daemon 在经过 gRPC 请求来呼叫 containerd。

2. Containerd 调用栈分析

与输出 docker daemon 的调用栈相似，咱们能够经过 kill -SIGUSR1 <pid> 命令来输出 containerd 的调用栈。不一样的是，此次调用栈会直接输出到 messages 日志。

Containerd 做为一个 gRPC 的服务器，它会在接到 docker daemon 的远程请求以后，新建一个线程去处理此次请求。关于 gRPC 的细节，咱们这里其实不用关注太多。<br />在此次请求的客户端调用栈上，能够看到此次调用的核心函数是 Start 一个进程。咱们在 containerd 的调用栈里搜索 Start，Process 以及 process.go 等字段，很容易发现下边这个线程。

这个线程的核心任务，就是依靠 runC 去建立容器进程。而在容器启动以后，runC 进程会退出。因此下一步，咱们天然而然会想到，runC 是否是有顺利完成本身的任务。

查看进程列表，咱们会发现，系统中有个别 runC 进程，还在执行，这不是预期内的行为。容器的启动跟进程的启动，耗时应该是差不对的，系统里有正在运行的 runC 进程，则说明 runC 不能正常启动容器。

什么是 Dbus

1. RunC 请求 Dbus

容器 runtime 的 runC 命令，是 libcontainer 的一个简单的封装。这个工具能够用来管理单个容器，好比容器建立，或者容器删除。在上节的最后，咱们发现 runC 不能完成建立容器的任务。

咱们能够把对应的进程杀掉，而后在命令行用一样的命令尝试启动容器，同时用 strace 追踪整个过程。

分析发现，runC 停在了向带有 org.free 字段的 dbus 写数据的地方。那什么是 dbus 呢？在 Linux 上，dbus 是一种进程间进行消息通讯的机制。

2. 缘由并不在 Dbus

咱们可使用 busctl 命令列出系统现有的全部 bus。以下图，在问题发生的时候，我看到客户集群节点 Name 的编号很是大。因此我倾向于认为，dbus 某些相关的数据结构，好比 Name 耗尽了引发了这个问题。

Dbus 机制的实现，依赖于一个组件叫作 dbus-daemon。若是真的是 dbus 相关数据结构耗尽，那么重启这个 daemon，应该是能够解决这个问题。但不幸的是，问题并无这么直接。重启 dbus-daemon 以后，问题依然存在。

在上边用 strace 追踪 runC 的截图中，我提到了，runC 卡在向带有 org.free 字段的 bus 写数据的地方。在 busctl 输出的 bus 列表里，显然带有这个字段的 bus，都在被 systemd 使用。这时，咱们用 systemctl daemon-reexec 来重启 systemd，问题消失了。

因此基本上咱们能够判断一个方向：问题可能跟 systemd 有关系。

Systemd 是硬骨头

Systemd 是至关复杂的一个组件，尤为对没有作过相关开发工做的同窗来讲，好比我本身。基本上，排查 systemd 的问题，我用到了四个方法：

• （调试级别）日志
• core dump
• 代码分析
• 以及 live debugging

其中第一个、第三个和第四个结合起来使用，让我在通过几天的鏖战以后，找到了问题的缘由。可是这里咱们先从“没用”的 core dump 提及。

1. 没用的 Core Dump

由于重启 systemd 解决了问题，而这个问题自己，是 runC 在使用 dbus 和 systemd 通讯的时候没有了响应，因此咱们须要验证的第一件事情，就是 systemd 不是有关键线程被锁住了。

查看 core dump 里全部线程，只有如下一个线程并无被锁住，它在等待 dbus 事件，以便作出响应。

2. 零散的信息

由于机关用尽，因此只能作各类测试、尝试。使用 busctl tree 命令，能够输出全部 bus 上对外暴露的接口。从输出结果看来，org.freedesktop.systemd1 这个 bus 是不能响应接口查询请求的。

使用下边的命令，观察 org.freedesktop.systemd1 上接受到的全部请求，能够看到，在正常系统里，有大量 Unit 建立删除的消息，可是有问题的系统里，这个 bus 上彻底没有任何消息。

gdbus monitor --system --dest org.freedesktop.systemd1 --object-path /org/freedesktop/systemd1

分析问题发生先后的系统日志，runC 在重复地跑一个 libcontainer_%d_systemd_test_default.slice 测试，这个测试很是频繁，可是当问题发生的时候，这个测试就中止了。

因此直觉告诉我，这个问题可能和这个测试有很大的关系。

另外，我使用 systemd-analyze 命令，打开了 systemd 的调试日志，发现 systemd 有 Operation not supported 的报错。

根据以上零散的知识，只能作出一个大概的结论：org.freedesktop.systemd1 这个 bus 在通过大量 Unit 建立删除以后，没有了响应。<br />而这些频繁的 Unit 建立删除测试，是 runC 某一个 checkin 改写了 UseSystemd 这个函数，而这个函数被用来测试 systemd 的某些功能是否可用。UseSystemd 这个函数在不少地方被调用，好比建立容器、查看容器性能等操做。

3. 代码分析

这个问题在线上全部 Kubernetes 集群中，发生的频率大概是一个月两例。问题一直在发生，且只能在问题发生以后，经过重启 systemd 来处理，这风险极大。

咱们分别给 systemd 和 runC 社区提交了 bug，可是一个很现实的问题是，他们并无像阿里云这样的线上环境，他们重现这个问题的几率几乎是零，因此这个问题没有办法期望社区来解决。硬骨头还得咱们本身啃。

在上一节最后，咱们看到了问题出现的时候，systemd 会输出一些 Operation not supported 报错。这个报错看起来和问题自己风马牛不相及，可是直觉告诉我，这或许是离问题最近的一个地方，因此我决定，先搞清楚这个报错因何而来。

Systemd 代码量比较大，而报这个错误的地方也比较多。经过大量的代码分析（这里略去一千字），我发现有几处比较可疑地方，有了这些可疑的地方，接下来须要作的事情，就是等待。在等待了三周之后，终于有线上集群再次重现了这个问题。

4. Live Debugging

在征求客户赞成以后，下载 systemd 调试符号，挂载 gdb 到 systemd 上，在可疑的函数下断点，continue 继续执行。通过屡次验证，发现 systemd 最终踩到了 sd_bus_message_seal 这个函数里的 EOPNOTSUPP 报错。

这个报错背后的道理是，systemd 使用了一个变量 cookie，来追踪本身处理的全部 dbus message。每次在加封一个新消息的时候，systemd 都会先把 cookie 这个值加一，而后再把这个 cookie 值复制给这个新的 message。

咱们使用 gdb 打印出 dbus->cookie 这个值，能够很清楚看到，这个值超过了 0xffffffff。因此看起来，这个问题是 systemd 在加封过大量 message 以后，cookie 这个值 32 位溢出，新的消息不能被加封致使的。

另外，在一个正常的系统上，使用 gdb 把 bus->cookie 这个值改到接近 0xffffffff，而后观察到，问题在 cookie 溢出的时候马上出现，则证实了咱们的结论。

5. 怎么判断集群节点 NotReady 是这个问题致使的

首先咱们须要在有问题的节点上安装 gdb 和 systemd debuginfo，而后用命令 gdb / usr/lib / systemd / systemd 1 把 gdb attach 到 systemd，在函数 sd_bus_send 设置断点，以后继续执行。<br />等 systemd 踩到断点以后，用 p /x bus->cookie 查看对应的 cookie 值，若是此值超过了 0xffffffff，那么 cookie 就溢出了，则必然致使节点 NotReady 的问题。确认完以后，可使用 quit 来 detach 调试器。

问题修复

这个问题的修复，并无那么直截了当。缘由之一是 systemd 使用了同一个 cookie 变量来兼容 dbus1 和 dbus2。

• 对于 dbus1 来讲，cookie 是 32 位的，这个值在通过 systemd 三五个月频繁建立删除 Unit 以后，是确定会溢出的；

• 而 dbus2 的 cookie 是 64 位的，可能到了时间的尽头它也不会溢出。

另一个缘由是，咱们并不能简单的让 cookie 折返，来解决溢出问题。由于这有可能致使 systemd 使用同一个 cookie 来加封不一样的消息，这样的结果将是灾难性的。

最终的修复方法是，使用 32 位 cookie 来一样处理 dbus1 和 dbus2 两种情形。同时在 cookie 达到 0xfffffff 以后的下一个 cookie 返回 0x80000000，用最高位来标记 cookie 已经处于溢出状态。检查到 cookie 处于这种状态时，咱们须要检查是否下一个 cookie 正在被其余 message 使用，来避免 cookie 冲突。

后记

这个问题根本缘由确定在 systemd，可是 runC 的函数 UseSystemd 使用不那么美丽的方法，去测试 systemd 的功能，这个函数在整个容器生命周期管理过程当中，被频繁地触发，让这个低几率问题的发生成为了可能。systemd 的修复已经被红帽接受，预期不久的未来，咱们能够经过升级 systemd，从根本上解决这个问题。

相关文章推荐
K8s 故障排查系列 | 咱们为何会删除不了集群的 Namespace？
K8s 故障排查系列 | 镜像拉取这件小事

云原生实践峰会即将开幕

“阿里巴巴云原生关注微服务、Serverless、容器、Service Mesh 等技术领域、聚焦云原生流行技术趋势、云原生大规模的落地实践，作最懂云原生开发者的技术圈。”