Kubernetes 应用问题的通用排查思路

大家好，我是明哥！

本片文章介绍下 Kubernetes 应用问题的通用排查思路，分享一个线上此类问题的排查案例，总结下背后的相关知识，以飨读者，大家共勉！

1 技术趋势大背景

我们知道，大数据进一步发展的一个趋势，就是大数据和云计算进一步融合（包括在底层更加青睐存储计算分离的架构，在底层更加青睐对象存储），在部署架构上支持混合云和多云场景，拥抱云计算走向云原生化。

对应到底层具体技术堆栈上，体现在各个主流大数据平台和底层的大数据组件，纷纷开始支持以 Kubernetes 和 Docker 为代表的容器系列技术栈。

所以大数据从业者，需要不断扩展自己的技能包，掌握 Kubernetes 和 Docker 的基础知识和常见命令，才能在排查大数据相关问题时不至于捉襟见肘，因技能储备短缺，无从下手。

从技术视角看大数据行业的发展趋势

在此分享一个大数据平台中 docker 容器相关故障的排查案列，并介绍下此类问题的背后知识和排查思路，以飨读者，大家共勉！

2 问题现象

星环大数据平台 TDH 中， zookeeper 服务无法正常启动。我们知道 TDH 中，各个服务其实是在 k8s 的管控下运行于 docker 容器中，通过 kubectl get pods -owide |grep -i zoo 可以发现，对应的 pod 的状态是CrashLoopBackOff，如下图所示:

pod-CrashLoopBackOff

3 背后知识：什么是 CrashLoopBackOff?

某个 pod 处于 CrashloopBackOff， 意味着该 pod 中的容器被启动了，然后崩溃了，接下来又被自动启动了，但又崩溃了，如此周而复始，陷入了（starting, crashing, starting，crashing）的循坏.

注意：pod 中的容器之所以会被自动重启，其实是通过 PodSpec 中的 restartPolicy 指定的，该配置项默认是 Always，即失败后会自动重启：

• A PodSpec has a restartPolicy field with possible values Always, OnFailure, and Never which applies to all containers in a pod， the default value is Always;
• The restartPolicy only refers to restarts of the containers by the kubelet on the same node (so the restart count will reset if the pod is rescheduled in a different node).
• Failed containers that are restarted by the kubelet are restarted with an exponential back-off delay (10s, 20s, 40s …) capped at five minutes, and is reset after ten minutes of successful execution.

4 背后知识：为什么会发生 CrashLoopBackOff 错误？

pod 的 CrashLoopBackOff 错误还是挺常见的，该错误可能会因为多种原因被触发，几个主要的上层原因有：

• Kubernetes 集群部署有问题;
• 该 pod 或 pod 底层的 container 的某些参数被配置错了；
• 该 pod 内部的 container 中运行的应用程序，在多次重启运行时都一直处于失败状态；

5 背后知识：如何排查 pod 容器底层的应用程序的故障?

当 pod 容器底层的应用程序运行出现故障时，通用的排查思路，一般是：

• 步骤一：通过命令 kubectl describe pod xxx 获取 pod 详细信息
• 步骤二：通过命令 kubectl logs xxx 查看 pod 容器底层的应用程序的日志
• 步骤三：进一步获取并查看 pod 容器底层的应用程序的其它日志文件，深挖问题原因

有的小伙伴可能会有疑问，上述步骤二和步骤三都是查看 pod 容器底层的应用程序的日志，有什么区别呢？

其实步骤二和步骤三在底层查看的是应用程序的不同的日志文件，其底层细节跟 kubernetes 的日志机制，以及该 pod 底层的应用程序将日志写向何处有关：

• kubectl logs 展示的是 pod 底层的 container 的标准输出 stdout 和标准错误 stderr 的日志；
• 应用程序写到其它文件的日志，kubectl logs 展示不了，需要获取日志文件路径，并自行查看；
• k8s 建议应用程序将日志写到 container 的标准输出 stdout 和标准错误 stderr；
• 容器内的应用程序可以将日志直接写到 container 的标准输出 stdout 和标准错误 stderr；
• 如果容器内的应用程序不能或不方便将日志直接写到 container 的标准输出 stdout 和标准错误 stderr，可以使用 sidecar 即边车模式，在应用程序的 container 所在的 pod 内部署另一个 sidecar container，该 sidecar container 负责读取应用程序的日志文件并输出到其标准输出 stdout 和标准错误 stderr 里；
• k8s 在底层会通过运行在各个节点的 kubelet 来收集节点中所有 container 的 stdout 和 stderr 日志，并写到一个 kubelet 管理的本地文件中；
• 用户执行 kubectl logs xx 命令时，该命令在底层会调用该 container 对应节点上的 kubelet 来检索其管理的本地日志文件，以获取日志;
• 用户使用 kubectl log xxx 来检索应用程序日志，省去了用户登录 k8s 集群中对应节点查看对应日志的繁琐操作，提供了很大遍历；

ps. 我们这里讨论的是运行在 k8s 容器中的应用程序的日志，除了应用程序的日志，其实整个k8s 集群中还有很多系统组件的日志，如：docker，kubelet，kube-proxy，kube-apiserver，kube-scheduler，etcd等。

6 问题排查复盘

按照上述通用问题排查思路，我们复盘回顾下该 CrashLoopBackOff 问题的排查经过。

6.1：问题排查复盘：通过命令 kubeclt describe pod xxx 获取 pod 详细信息

该命令输出的部分截图如下，通过输出中 Events 部分，我们可以获取如下信息：该 pod 被成功地分配到了某个节点上，然后镜像拉取成功，然后 contaier 创建和启动成功，但随后 contaier 中程序运行失败，最后 pod 进入到了 BackOff 状态：

kubectl-describe-pod

该命令的详细输出如下：

1. kubectldescribepodzookeeper-server-license-7fbfc544fc-h8nn9
2. Name:zookeeper-server-license-7fbfc544fc-h8nn9
3. Namespace:default
4. Priority:0
5. PriorityClassName:
6. Node:uf30-tdh3-regression/10.20.159.115
7. StartTime:Mon,11Oct202116:56:30+0800
8. Labels:name=zookeeper-server-license
9. pod-template-hash=3969710097
10. podConflictName=zookeeper-server-license
11. Annotations:
12. Status:Running
13. IP:10.20.159.115
14. ControlledBy:ReplicaSet/zookeeper-server-license-7fbfc544fc
15. Containers:
16. zookeeper-server-license:
17. ContainerID:docker://0887c97ab185f1b004759e8c85b48631f511cb43088424190c3f27c715bb8414
18. Image:transwarp/zookeeper:transwarp-6.0.2-final
19. ImageID:docker-pullable://transwarp/zookeeper@sha256:19bf952dedc70a1d82ba9dd9217a2b7e34fc018561c2741d8f6065c0d87f8a10
20. Port:
21. Args:
22. boot.sh
23. LICENSE_NODE
24. State:Terminated
25. Reason:Error
26. ExitCode:1
27. Started:Mon,11Oct202117:12:09+0800
28. Finished:Mon,11Oct202117:12:10+0800
29. LastState:Terminated
30. Reason:Error
31. ExitCode:1
32. Started:Mon,11Oct202117:07:07+0800
33. Finished:Mon,11Oct202117:07:08+0800
34. Ready:False
35. RestartCount:8
36. Environment:
37. ZOOKEEPER_CONF_DIR:/etc/license/conf
38. Mounts:
39. /etc/license/conffromconf(rw)
40. /etc/localtimefromtimezone(rw)
41. /etc/tos/conffromtos(rw)
42. /etc/transwarp/conffromtranswarphosts(rw)
43. /usr/lib/transwarp/pluginsfromplugin(rw)
44. /var/licensefromdata(rw)
45. /var/log/license/fromlog(rw)
46. /var/run/secrets/kubernetes.io/serviceaccountfromdefault-token-g42jt(ro)
47. /vdirfrommountbind(rw)
48. Conditions:
49. TypeStatus
50. InitializedTrue
51. ReadyFalse
52. PodScheduledTrue
53. Volumes:
54. data:
55. Type:HostPath(barehostdirectoryvolume)
56. Path:/var/license
57. HostPathType:
58. conf:
59. Type:HostPath(barehostdirectoryvolume)
60. Path:/etc/license/conf
61. HostPathType:
62. log:
63. Type:HostPath(barehostdirectoryvolume)
64. Path:/var/log/license/
65. HostPathType:
66. mountbind:
67. Type:HostPath(barehostdirectoryvolume)
68. Path:/transwarp/mounts/license
69. HostPathType:
70. plugin:
71. Type:HostPath(barehostdirectoryvolume)
72. Path:/usr/lib/transwarp/plugins
73. HostPathType:
74. timezone:
75. Type:HostPath(barehostdirectoryvolume)
76. Path:/etc/localtime
77. HostPathType:
78. transwarphosts:
79. Type:HostPath(barehostdirectoryvolume)
80. Path:/etc/transwarp/conf
81. HostPathType:
82. tos:
83. Type:HostPath(barehostdirectoryvolume)
84. Path:/etc/tos/conf
85. HostPathType:
86. default-token-g42jt:
87. Type:Secret(avolumepopulatedbyaSecret)
88. SecretName:default-token-g42jt
89. Optional:false
90. QoSClass:BestEffort
91. Node-Selectors:zookeeper-server-license=true
92. Tolerations:node.kubernetes.io/not-ready:NoExecutefor300s
93. node.kubernetes.io/unreachable:NoExecutefor300s
94. Events:
95. TypeReasonAgeFromMessage
96. -------------------------
97. NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume"default-token-g42jt"
98. NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume"conf"
99. NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume"tos"
100. NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume"mountbind"
101. NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume"transwarphosts"
102. NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume"log"
103. NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume"plugin"
104. NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume"data"
105. NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume"timezone"
106. NormalScheduled15mdefault-schedulerSuccessfullyassignedzookeeper-server-license-7fbfc544fc-h8nn9touf30-tdh3-regression
107. NormalPulled15m(x3over15m)kubelet,uf30-tdh3-regressionSuccessfullypulledimage"transwarp/zookeeper:transwarp-6.0.2-final"
108. NormalCreated15m(x3over15m)kubelet,uf30-tdh3-regressionCreatedcontainer
109. NormalStarted15m(x3over15m)kubelet,uf30-tdh3-regressionStartedcontainer
110. NormalPulling15m(x4over15m)kubelet,uf30-tdh3-regressionpullingimage"transwarp/zookeeper:transwarp-6.0.2-final"
111. WarningBackOff44s(x70over15m)kubelet,uf30-tdh3-regressionBack-offrestartingfailedcontainer

6.2 问题排查复盘：通过命令 kubectl logs xxx 查看 pod 容器底层的应用程序的日志

接下来我们尝试通过命令 kubectl logs xxx 查看 pod 容器底层的应用程序的日志，以期找到问题的原因，该命令的输出部分截图如下所示：图片

如上图所见，不幸的是，该命令的输出，没有展示出问题的根本原因。

在底层日志机制上，应该是星环 tdh 中该 zk 应用没有将日志打印到标准输出 stdout 和标准错误 stderr, 所以 kubectl logs xxx 查看不到对应的日志。

我们需要进一步排查。

6.3 问题排查复盘：进一步获取并查看 pod 容器底层的应用程序的其它日志文件，深挖问题原因

进一步排查问题，我们首先需要获取 pod 容器底层的应用程序的其它日志文件的路径。

由于 tdh 是闭源的，我们查看不到应用程序的源码，在没有联络官方客户的情况下，我们可以通过命令 kubectl describe pod xxx 查看该 pod 挂载了哪些 volume，然后猜测并验证获得具体的日志文件的路劲给，（排查问题就是要，大胆猜想，小心求证！）

该命令输出的部分截图如下，我们看到其中挂载了路径 /var/log/license:

接下来我们查看这些日志文件/var/log/license，尝试深挖问题原因，注意，该文件是本地文件系统的文件，需要登录到对应的节点上去查看，该日志文件部分关键截图如下：

通过日志，问题原因找到了：zk 底层存储在本地文件系统中的文件 /var/license/version-2/snapshot.70000007a 损坏了，所以无法启动:

1. 2021-10-1117:07:08,330ERRORorg.apache.zookeeper.server.persistence.Util:[myid:16]-[main:Util@239]-Lasttransactionwaspartial.
2. 2021-10-1117:07:08,331ERRORorg.apache.zookeeper.server.quorum.QuorumPeer:[myid:16]-[main:QuorumPeer@453]-Unabletoloaddatabaseondisk
3. java.io.EOFExceptionatjava.io.DataInputStream.readInt(DataInputStream.java:392)

该日志文件详细内容如下：

1. tail-50/var/log/license/zookeeper.log
2. 2021-10-1117:07:08,203INFOorg.apache.zookeeper.server.DatadirCleanupManager:[myid:16]-[main:DatadirCleanupManager@101]-Purgetaskisnotscheduled.
3. 2021-10-1117:07:08,212INFOorg.apache.zookeeper.server.quorum.QuorumPeerMain:[myid:16]-[main:QuorumPeerMain@127]-Startingquorumpeer
4. 2021-10-1117:07:08,221INFOorg.apache.zookeeper.server.NIOServerCnxnFactory:[myid:16]-[main:NIOServerCnxnFactory@94]-bindingtoport0.0.0.0/0.0.0.0:2291
5. 2021-10-1117:07:08,235INFOorg.apache.zookeeper.server.quorum.QuorumPeer:[myid:16]-[main:QuorumPeer@913]-tickTimesetto9000
6. 2021-10-1117:07:08,235INFOorg.apache.zookeeper.server.quorum.QuorumPeer:[myid:16]-[main:QuorumPeer@933]-minSessionTimeoutsetto-1
7. 2021-10-1117:07:08,235INFOorg.apache.zookeeper.server.quorum.QuorumPeer:[myid:16]-[main:QuorumPeer@944]-maxSessionTimeoutsetto-1
8. 2021-10-1117:07:08,236INFOorg.apache.zookeeper.server.quorum.QuorumPeer:[myid:16]-[main:QuorumPeer@959]-initLimitsetto10
9. 2021-10-1117:07:08,285INFOorg.apache.zookeeper.server.persistence.FileSnap:[myid:16]-[main:FileSnap@83]-Readingsnapshot/var/license/version-2/snapshot.70000007a
10. 2021-10-1117:07:08,330ERRORorg.apache.zookeeper.server.persistence.Util:[myid:16]-[main:Util@239]-Lasttransactionwaspartial.
11. 2021-10-1117:07:08,331ERRORorg.apache.zookeeper.server.quorum.QuorumPeer:[myid:16]-[main:QuorumPeer@453]-Unabletoloaddatabaseondisk
12. java.io.EOFException
13. atjava.io.DataInputStream.readInt(DataInputStream.java:392)
14. atorg.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
15. atorg.apache.zookeeper.server.persistence.FileHeader.deserialize(FileHeader.java:64)
16. atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.inStreamCreated(FileTxnLog.java:558)
17. atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.createInputArchive(FileTxnLog.java:577)
18. atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.goToNextLog(FileTxnLog.java:543)
19. atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.next(FileTxnLog.java:625)
20. atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.init(FileTxnLog.java:529)
21. atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.(FileTxnLog.java:504)
22. atorg.apache.zookeeper.server.persistence.FileTxnLog.read(FileTxnLog.java:341)
23. atorg.apache.zookeeper.server.persistence.FileTxnSnapLog.restore(FileTxnSnapLog.java:132)
24. atorg.apache.zookeeper.server.ZKDatabase.loadDataBase(ZKDatabase.java:223)
25. atorg.apache.zookeeper.server.quorum.QuorumPeer.loadDataBase(QuorumPeer.java:417)
26. atorg.apache.zookeeper.server.quorum.QuorumPeer.start(QuorumPeer.java:409)
27. atorg.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:151)
28. atorg.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:111)
29. atorg.apache.zookeeper.server.quorum.QuorumPeerMain.main(QuorumPeerMain.java:78)
30. 2021-10-1117:07:08,332ERRORorg.apache.zookeeper.server.quorum.QuorumPeerMain:[myid:16]-[main:QuorumPeerMain@89]-Unexpectedexception,exitingabnormally
31. java.lang.RuntimeException:Unabletorunquorumserver
32. atorg.apache.zookeeper.server.quorum.QuorumPeer.loadDataBase(QuorumPeer.java:454)
33. atorg.apache.zookeeper.server.quorum.QuorumPeer.start(QuorumPeer.java:409)
34. atorg.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:151)
35. atorg.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:111)
36. atorg.apache.zookeeper.server.quorum.QuorumPeerMain.main(QuorumPeerMain.java:78)
37. Causedby:java.io.EOFException
38. atjava.io.DataInputStream.readInt(DataInputStream.java:392)
39. atorg.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
40. atorg.apache.zookeeper.server.persistence.FileHeader.deserialize(FileHeader.java:64)
41. atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.inStreamCreated(FileTxnLog.java:558)
42. atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.createInputArchive(FileTxnLog.java:577)
43. atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.goToNextLog(FileTxnLog.java:543)
44. atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.next(FileTxnLog.java:625)
45. atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.init(FileTxnLog.java:529)
46. atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.(FileTxnLog.java:504)
47. atorg.apache.zookeeper.server.persistence.FileTxnLog.read(FileTxnLog.java:341)
48. atorg.apache.zookeeper.server.persistence.FileTxnSnapLog.restore(FileTxnSnapLog.java:132)
49. atorg.apache.zookeeper.server.ZKDatabase.loadDataBase(ZKDatabase.java:223)
50. atorg.apache.zookeeper.server.quorum.QuorumPeer.loadDataBase(QuorumPeer.java:417)
51. ...4more

7 问题解决

通过以上通用问题排查思路，我们查看日志找到了问题原因：zk 底层存储在本地文件系统中的文件 /var/license/version-2/snapshot.70000007a 损坏了，所以无法启动。由于集群中 zk 是有多个节点的，且其它节点的 zk 启动是成功的，所以我们 可以删除该问题节点上述目录下的数据文件，然后重启该节点的 zk， 重启后该节点的 zk 就可以从其它节点复制数据到本地，就可以正常对外提供服务了！

zk 底层存储在本地文件系统中的文件，在正常节点于问题节点，对比截图如下：

zk data on good node

zk data on bad node

按照上述方法，清空目录重启zk后，kubectl get pods 查看服务正常，截图如下：

kubectl-get-pods-after-fix

注意：其实 zk 也提供了系统工具 zkCleanup.sh 来清理本地数据文件，笔者没有使用该工具，而是手工备份和清空了问题节点的本地文件。大家可以自行尝试该工具。

zkCleanup.sh

8 知识总结

• 大数据从业者，需要不断扩展自己的技能包，掌握 Kubernetes 和 Docker 的基础知识和常见命令，才能在排查大数据相关问题时不至于捉襟见肘，因技能储备短缺，无从下手;
• 某个 pod 处于 CrashloopBackOff， 意味着该 pod 中的容器被启动了，然后崩溃了，接下来又被自动启动了，但又崩溃了，如此周而复始，陷入了（starting, crashing, starting，crashing）的循坏;
• 当 pod 容器底层的应用程序运行出现故障时，通用的排查思路，一般是：

步骤一：通过命令 kubectl describe pod xxx 获取 pod 详细信息;

步骤二：通过命令 kubectl logs xxx 查看 pod 容器底层的应用程序的日志;

步骤三：进一步获取并查看 pod 容器底层的应用程序的其它日志文件，深挖问题原因;

• kubectl logs 展示的是 pod 底层的 container 的标准输出 stdout 和标准错误 stderr 的日志, 应用程序写到其它文件的日志，kubectl logs 展示不了，需要获取日志文件路径，并自行查看；
• k8s 建议应用程序将日志写到 container 的标准输出 stdout 和标准错误 stderr；
• 容器内的应用程序可以将日志直接写到 container 的标准输出 stdout 和标准错误 stderr；如果容器内的应用程序不能或不方便将日志直接写到 container 的标准输出 stdout 和标准错误 stderr，可以使用 sidecar 即边车模式，在应用程序的 container 所在的 pod 内部署另一个 sidecar container，该 sidecar container 负责读取应用程序的日志文件并输出到其标准输出 stdout 和标准错误 stderr 里；
• k8s 在底层会通过运行在各个节点的 kubelet 来收集节点中所有 container 的 stdout 和 stderr 日志，并写到一个 kubelet 管理的本地文件中；
• 用户执行 kubectl logs xx 命令时，该命令在底层会调用该 container 对应节点上的 kubelet 来检索其管理的本地日志文件，以获取日志;
• 用户使用 kubectl log xxx 来检索应用程序日志，省去了用户登录 k8s 集群中对应节点查看对应日志的繁琐操作，提供了很大便利；
• 排查问题，需要大胆猜想小心求证！

原文链接：https://mp.weixin.qq.com/s/qA3dHhsOQtu56UNwn-tsLQ