记录一次修复k8s pod长时间处于CrashLoopBackOff状态问题

前言

这周一，新年后上班第一个完整周，年前一波需求已经评审过了，方案也已经制定好，所以年后就开始了如火如荼的写bug阶段，正在写go bug，突然企业微信，tapd弹出一条消息，提了一个缺陷单，处理人是我，顿时预感不妙，果然5秒后，测试同学那微笑的头像弹出来，嗯，完蛋，bug来了。测试同学告诉我，有一个node组件，使用chaos注入故障，频繁杀掉主线程，大概会在第七轮杀掉主进程，pod会长时间处于CrashLoopBackOff阶段，很久才恢复正常。当时很疑惑，为什么第七轮会长时间处于CrashLoopBackOff尼？讲道理不应该是杀掉主线程，LivenessProbe检测异常，达到阀值就会认为container死掉，因此就会重启container，重启一个container，从经验来看，30s之内，都可以恢复，不过测试说的第七轮才出现问题，就有点儿迷，心里还在犯嘀咕，算了，还是上环境看看吧。问了一下是否还在持续测试，得到肯定的答复后，就开始了debug之旅。

经验告诉我

先上测试环境看看情况，果然，pod还是处于CrashLoopBackOff状态，

[root@10-0-0-13 ~]# kubectl get pods -l  test-app=test-app  -n cloud  -w
NAME                       READY   STATUS             RESTARTS   AGE
api-5966577d7b-49zck   0/1     CrashLoopBackOff   7          56m
api-5966577d7b-5dzsp   0/1     CrashLoopBackOff   7          56m
api-5966577d7b-87hfn   0/1     CrashLoopBackOff   7          55m
api-5966577d7b-bp8zj   0/1     CrashLoopBackOff   7          56m
api-5966577d7b-csjnp   0/1     CrashLoopBackOff   7          56m
api-5966577d7b-fx7rx   0/1     CrashLoopBackOff   7          56m
api-5966577d7b-gc7ht   0/1     CrashLoopBackOff   7          56m
api-5966577d7b-x2m46   0/1     CrashLoopBackOff   7          56m

找来一个看看详情，

kubectl describe pods api-5966577d7b-x2m46 -n cloud
···
Events:
  Type     Reason     Age                   From                Message
  ----     ------     ----                  ----                -------
  Normal   Scheduled  <unknown>             default-scheduler   Successfully assigned cloud/api-5966577d7b-x2m46 to 10.0.0.16
  Normal   Pulled     31m (x4 over 54m)     kubelet, 10.0.0.16  Successfully pulled image "registry.test.com/api:v1.1.1"
  Normal   Created    31m (x4 over 54m)     kubelet, 10.0.0.16  Created container app-tcb-api
  Normal   Started    31m (x4 over 54m)     kubelet, 10.0.0.16  Started container app-tcb-api
  Warning  Unhealthy  21m                   kubelet, 10.0.0.16  Liveness probe failed: dial tcp 192.168.1.119:80: connect: connection refused
  Normal   Pulling    19m (x6 over 54m)     kubelet, 10.0.0.16  Pulling image "registry.test.com/api:v1.1.1"
  Warning  BackOff    9m34s (x39 over 37m)  kubelet, 10.0.0.16  Back-off restarting failed container
  Warning  Unhealthy  46s (x6 over 42m)     kubelet, 10.0.0.16  Readiness probe failed: dial tcp 192.168.1.119:80: connect: connection refused

这里只取了event事件，看起来貌似没啥问题的，不过是Liveness probe failed，并且Readiness probe failed，这两个一个是存活探针，一个是就绪探针，都是检测服务状态的，杀掉主进程当然会这存活探针会失败啊，然后失败次数达到了预设值，container就会重启，这里是container会重启，不是pod，因此pod的名称并不会变化，然后就绪探针就会因为pod状态不是正常状态，因此流量就不会打到这个pod，这些都是常规操作，看起来是没啥问题的。（这里还有个Back-off restarting failed container没注意到，这里会是一个突破口），不过话说重启这个pod为啥要这么尼？想了一想主要步骤：

• 计算pod申请资源，取出非master节点node，看是否够资源条件
• 排查掉亲和和反亲和的节点，计算score
• 取得分最多的node，然后将其调度到这个节点上
• pull镜像
• 创建pod
• 按照init delay大小，启动探针ReadinessProbe和LivenessProbe
• LivenessProbe判断服务正常
• ReadinessProbe判断可用，将ip添加到endpoint提供服务
• 执行postStart钩子
• 服务正常运行
• 服务出现异常（测试删掉主线程）
• ReadinessProbe失败，流量不会击中此pod
• LivenessProbe失败，准备重启container
• 执行preStop钩子
• 发送重启信号，准备k8s重启pod
• 等待最长terminationGracePeriodSeconds（默认值为60）秒，关闭container
• 如果超过terminationGracePeriodSeconds，系统将会强制关闭container
• 尝试重建container，创建主进程
• LivenessProbe检测
• …循环…
  这大概是一个pod的生命周期了。（其实是翻书才能知道原来还有这么多步骤来着），嗯，根据这个pod生命周期，可以提出合理的猜测：

大胆推测

可能的原因一：PreStop钩子执行时间太久了，导致container删不掉

这里稍微看了一下，根本就没有设置PreStop钩子，所以不是关不掉的问题，不过这里可以优化，直接使用exit退出命令，立刻退出，多好。

···
        containers:
        - image: registry.test.com/api:v1.1.1
          imagePullPolicy: Always
          lifecycle:
            preStop:
              exec:
                command:
                - sh
                - -c
                - exit 1

可能的原因二：terminationGracePeriodSeconds设置的太久了

简单看了一下，默认是60秒，直接改成0秒，不过实验中发现，如果设置为0，则不生效，还是会变成60秒的默认值，那就改成一秒吧：

  spec:
    progressDeadlineSeconds: 600
    replicas: 8
    strategy:
      rollingUpdate:
        maxSurge: 25%
        maxUnavailable: 25%
      type: RollingUpdate
    template:
      metadata:
        labels:
          test-app: test-app
      spec:
        terminationGracePeriodSeconds: 1      

嗯，都优化完了，再把存活和就绪探针也加快点儿频率吧：

        - image: registry.tce.com/mpaas.matrix/api:v1.2.1
          imagePullPolicy: Always
          livenessProbe:
            failureThreshold: 3
            initialDelaySeconds: 5
            periodSeconds: 3
            successThreshold: 1
            tcpSocket:
              port: 80
            timeoutSeconds: 1
          readinessProbe:
            failureThreshold: 3
            initialDelaySeconds: 5
            periodSeconds: 3
            successThreshold: 1
            tcpSocket:
              port: 80
            timeoutSeconds: 1            

嗯，一波操作猛如虎，反正测试用例还在跑，直接edit了yaml，然后自动创建出pod，等待好消息的到来，看着一次次重启，满心欢喜应该是修好了，然后到了第六次就crashloopbackoff了。。。顿时血压升高到200，爆炸

击中k8s规则天花板

嗯，看着还是卡住，有点儿烦躁，到底是哪里出了问题尼？不行了，还是找老大哥Google帮忙吧，检索到k8s的文档，然后有一段话引起了我的注意:

Container restart policy
The spec of a Pod has a restartPolicy field with possible values Always, OnFailure, and Never. The default value is Always.

The restartPolicy applies to all containers in the Pod. restartPolicy only refers to restarts of the containers by the kubelet on the same node. After containers in a Pod exit, the kubelet restarts them with an exponential back-off delay (10s, 20s, 40s, …), that is capped at five minutes. Once a container has executed for 10 minutes without any problems, the kubelet resets the restart backoff timer for that container.

当 Pod 中的容器退出时，kubelet 会按指数回退 方式计算重启的延迟（10s、20s、40s、…），其最长延迟为 5 分钟。 一旦某容器执行了 10 分钟并且没有出现问题，kubelet 对该容器的重启回退计时器执行 重置操作。然而测试是3～4分钟杀掉主进程一次，所以出现的情况就是回退计时器不会重置，因次无法通过测试，k8s并没有相关的配置选项来这进行设置，k8s期望的是最长5分钟重启一次，希望程序自身能够解决一直退出的问题。
成功击中k8s天花板，这是k8s的container重启特性，无解。然后和测试沟通了一下，这种频繁的操作应该也是很少的，所以这里的测试用例要么修改为10分钟一次杀掉主线程让container重启，要么这个用例就不测了。

后记

这里还是蛮有意思的，通过一次debug的过程，还是学到了不少知识的，赞