k8s排查Pod异常重启次数过多

k8s排查Pod异常重启次数过多

Scroll Down

日常巡查,发现线上k8s集群有部分业务Pod经常发生重启,这个问题说大不大,说小也不小。发现了就必须马上着手处理一下,不然对外服务肯定会有一定影响(这几个业务pod的客户端大多是远程iot设备)

$ kubectl get pod -n qld2-production | grep -E "pod1|pod2|pod3|pod4"
pod1-deployment-56744f755c-hx2w7              1/1     Running   140        46d
pod2-deployment-77c46bfb79-vr5n5              1/1     Running   5          51d
pod3-deployment-75fbbb8b6b-sh9s8               1/1     Running   53         118d
pod4-deployment-7d7b75974d-4zlj6                1/1     Running   24         109d
pod4-deployment-7d7b75974d-76n89                1/1     Running   19         109d
pod4-deployment-7d7b75974d-z4nnf                1/1     Running   19         109d

一、从日志下手

当前集群的restartPolicy统一都是Always,也就是说当容器终止退出后,总是重启容器。

而Pod重启次数过多,如果是外部因素导致(诸如oom等常见原因),第一反应下觉得要么是集群级别,要么是操作系统内核级别的。

集群Events:

第一个操作就是查看Pod的异常Events,只不过Events默认只在Etcd中保存一个小时,过了这个时间就看不到任何信息了。

$ kubectl describe pod -n namespace pod1-deployment-56744f755c-hx2w7

$ kubectl get events -n namespace

很可惜,进行排查的时候并没有看到任何有用的Events。如果集群级别看不到有用的信息,那么下一站就是筛查操作系统级别的日志信息。
image.png

操作系统级别日志:

在内核级别结果依旧,翻遍了集群master和pod所在node的kubelet日志信息仍旧没有看到一行有用的信息。

$ cat /var/log/messages | more

$ journalctl -xe -u kubelet // --since

二、排查Pod内应用程序

Pod频繁重启,而外部又没有太多信息,余以为这问题要么出在Pod层面要么就是更深一步的应用程序层面。

问题如果是在Pod层面的话,一般情况下有健康检查、OOM等原因,这些都会在Pod的Event记录下相应的事件,但正如上面提到的,这个Pod事件并不是持久化的,默认只会在Etcd中保留一个小时。

结合我们的实际情况,这个服务并没有做资源限制,也没有做探针检测什么的,所以频繁重启也不大可能是Pod层面的原因。

既然排除了探针检测、OOM等原因,只能从退出状态码和LastState字段入手了,经过排查,大部分服务Pod的退出状态码都是清一色的2LastState均显示为Error,这个退出状态码2Redhat的解释滥用shell内置函数,empty_function(){},缺少关键字或命令。shell错误?Pod里边Pid为1的进程就是一个Go代码打包的可执行程序,难道是Dockerfile打包镜像的时候启动命令有问题?(因为我们的k8s集群默认没有为Pod容器指定启动命令)为此特意去看了一眼Dockerfile文件,该容器的启动命令使用的是CMD,而在Dockerfile中,启动命令ENTRYPOINTCMD的区别就在于启动容器的时候命令参数会不会被覆盖掉。

说实话,在k8s集群没有指定Pod容器启动命令的前提下,我想不出Dockerfile的CMD指令是造成Pod以退出状态码2频繁重启的元凶理由=(可能只是因为我才疏学浅~)

在这里看到一段Exit Code 2的描述:

退出代码为2,表明应用程序选择返回该错误代码,或者(按照惯例)存在misuse of a shell builtin。检查您的Pod的命令规格,以确保命令正确无误。如果您认为正确,请尝试使用Shell在本地运行映像,然后直接运行命令。

三、后续修改与筛查

本次排查并没有查找到具体的频繁退出原因,后续准备分几步走以排查原因和消除频繁重启的问题

3.1 修改Dockerfile指令CMDENTRYPOINT
线上某个以退出状态码2频繁退出的Pod并没有监听端口和提供接口,所以优先尝试,修改其打包镜像的Dockerfile中的CMDENTRYPOINT,观察一段时间。

修改完之后不到几分钟就出现了一次重启,实际证明和Dockerfile的启动命令无关
image.png

3.2 设置探针检测

之所以使用就绪检测、存活检测是因为,在节点、集群级别并没有发现Pod被异常杀死的相关信息,说明问题很可能就是在应用程序级别。而现阶段这些Pod重启次数那么高,说明它们正陷入了运行一段时间随后异常退出,然后又被重新拉起的死循环。如果我们为Pod设置了liveness/startup Probe,那就能使Pod内的程序避免在就绪之前被杀掉。(相当于减少了慢启动容器被杀掉的次数)。[参考8]/[参考10]。同时,配置了探针之后,在Events之中也可以看到更多的输出信息,便于筛查信息排查问题。

上一个3.1中的那个服务Pod本没有向外提供接口和端口,为了使用tcp端口形式的就绪探针和存活探针(其实可以使用exec执行命令的形式检测进程是否还在),拜托开发同学向外监听了一个gRPC端口,做了一个tcp就绪检测和存活检测,以此观察服务之后的重启情况。

containers:
      - name: xxxx
        image: xxxx:0.0.4
        imagePullPolicy: Always
        ports:
        - containerPort: 8356
        readinessProbe:
          tcpSocket:
            port: 8356
          initialDelaySeconds: 3
          periodSeconds: 3
        livenessProbe:
          tcpSocket:
            port: 8356
          initialDelaySeconds: 5
          periodSeconds: 10

配置了探针检测之后,可能出于偶然,至目前程序没有出现重启的情况(持续观察)
image.png

加了就绪和存活检测之后,一天时间,虽说Exit Code 2异常退出的情况并没有消失,只是频率降低了一些。如图:

image.png

3.3 从应用程序下手

Exit Code 2按照官方定义那就是misuse of a shell builtin,是应用程序本身返回的错误退出状态码。既然这样,那还是得从应用程序本身(开发都是大爷。我还是从日志输出着手吧)入手。因为要看的是Pod崩溃时的日志信息,而我们薄弱的地方也正是日志处理,这里选择将日志集成到阿里云SLS完成日志收集。

等待程序再次崩溃的时候检查日志输出。。

四、破案

后续注意到上述Exit Code 2崩溃的又再次重现了

pod-restart-more

describe pod输出可以看到,Pod上次异常重启的突出状态码依然是2,时间是2022年1月1日的23:36:48秒

因为已经集成日志输出到SlS了,查看一下Pod内部日志输出叭

pod-restart-reason

从日志内容可以看出来,代码报错invalid memory address or nil pointer dereference,破案,代码bug。

移交开发~

参考:

k8s events:
1、k8s 的实时日志 Events
2、记一次k8s pod频繁重启的优化之旅
3、Kubernetes(K8s)Events介绍(上)
4、Redhat退出状态码
5、docker-cmd-vs-entrypoint
6、通过 Exit Code 定位 Pod 异常退出原因
7、K8S 常见POD 退出码
8、配置存活、就绪和启动探测器
9、k8s资源限制资源限制、重启策略与探针
10、配置Pod的liveness和readiness探针