大家好,我是明哥!
本片文章介绍下 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
该命令的详细输出如下:
kubectldescribepodzookeeper-server-license-7fbfc544fc-h8nn9 Name:zookeeper-server-license-7fbfc544fc-h8nn9 Namespace:default Priority:0 PriorityClassName: Node:uf30-tdh3-regression/10.20.159.115 StartTime:Mon,11Oct202116:56:30+0800 Labels:name=zookeeper-server-license pod-template-hash=3969710097 podConflictName=zookeeper-server-license Annotations: Status:Running IP:10.20.159.115 ControlledBy:ReplicaSet/zookeeper-server-license-7fbfc544fc Containers: zookeeper-server-license: ContainerID:docker://0887c97ab185f1b004759e8c85b48631f511cb43088424190c3f27c715bb8414 Image:transwarp/zookeeper:transwarp-6.0.2-final ImageID:docker-pullable://transwarp/zookeeper@sha256:19bf952dedc70a1d82ba9dd9217a2b7e34fc018561c2741d8f6065c0d87f8a10 Port: Args: boot.sh LICENSE_NODE State:Terminated Reason:Error ExitCode:1 Started:Mon,11Oct202117:12:09+0800 Finished:Mon,11Oct202117:12:10+0800 LastState:Terminated Reason:Error ExitCode:1 Started:Mon,11Oct202117:07:07+0800 Finished:Mon,11Oct202117:07:08+0800 Ready:False RestartCount:8 Environment: ZOOKEEPER_CONF_DIR:/etc/license/conf Mounts: /etc/license/conffromconf(rw) /etc/localtimefromtimezone(rw) /etc/tos/conffromtos(rw) /etc/transwarp/conffromtranswarphosts(rw) /usr/lib/transwarp/pluginsfromplugin(rw) /var/licensefromdata(rw) /var/log/license/fromlog(rw) /var/run/secrets/kubernetes.io/serviceaccountfromdefault-token-g42jt(ro) /vdirfrommountbind(rw) Conditions: TypeStatus InitializedTrue ReadyFalse PodScheduledTrue Volumes: data: Type:HostPath(barehostdirectoryvolume) Path:/var/license HostPathType: conf: Type:HostPath(barehostdirectoryvolume) Path:/etc/license/conf HostPathType: log: Type:HostPath(barehostdirectoryvolume) Path:/var/log/license/ HostPathType: mountbind: Type:HostPath(barehostdirectoryvolume) Path:/transwarp/mounts/license HostPathType: plugin: Type:HostPath(barehostdirectoryvolume) Path:/usr/lib/transwarp/plugins HostPathType: timezone: Type:HostPath(barehostdirectoryvolume) Path:/etc/localtime HostPathType: transwarphosts: Type:HostPath(barehostdirectoryvolume) Path:/etc/transwarp/conf HostPathType: tos: Type:HostPath(barehostdirectoryvolume) Path:/etc/tos/conf HostPathType: default-token-g42jt: Type:Secret(avolumepopulatedbyaSecret) SecretName:default-token-g42jt Optional:false QoSClass:BestEffort Node-Selectors:zookeeper-server-license=true Tolerations:node.kubernetes.io/not-ready:NoExecutefor300s node.kubernetes.io/unreachable:NoExecutefor300s Events: TypeReasonAgeFromMessage ————————- NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume“default-token-g42jt” NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume“conf” NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume“tos” NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume“mountbind” NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume“transwarphosts” NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume“log” NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume“plugin” NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume“data” NormalSuccessfulMountVolume15mkubelet,uf30-tdh3-regressionMountVolume.SetUpsucceededforvolume“timezone” NormalScheduled15mdefault-schedulerSuccessfullyassignedzookeeper-server-license-7fbfc544fc-h8nn9touf30-tdh3-regression NormalPulled15m(x3over15m)kubelet,uf30-tdh3-regressionSuccessfullypulledimage“transwarp/zookeeper:transwarp-6.0.2-final” NormalCreated15m(x3over15m)kubelet,uf30-tdh3-regressionCreatedcontainer NormalStarted15m(x3over15m)kubelet,uf30-tdh3-regressionStartedcontainer NormalPulling15m(x4over15m)kubelet,uf30-tdh3-regressionpullingimage“transwarp/zookeeper:transwarp-6.0.2-final” WarningBackOff44s(x70over15m)kubelet,uf30-tdh3-regressionBack-offrestartingfailedcontainer6.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 损坏了,所以无法启动:
2021-10-1117:07:08,330ERRORorg.apache.zookeeper.server.persistence.Util:[myid:16]-[main:Util@239]-Lasttransactionwaspartial. 2021-10-1117:07:08,331ERRORorg.apache.zookeeper.server.quorum.QuorumPeer:[myid:16]-[main:QuorumPeer@453]-Unabletoloaddatabaseondisk java.io.EOFExceptionatjava.io.DataInputStream.readInt(DataInputStream.java:392)该日志文件详细内容如下:
tail-50/var/log/license/zookeeper.log 2021-10-1117:07:08,203INFOorg.apache.zookeeper.server.DatadirCleanupManager:[myid:16]-[main:DatadirCleanupManager@101]-Purgetaskisnotscheduled. 2021-10-1117:07:08,212INFOorg.apache.zookeeper.server.quorum.QuorumPeerMain:[myid:16]-[main:QuorumPeerMain@127]-Startingquorumpeer 2021-10-1117:07:08,221INFOorg.apache.zookeeper.server.NIOServerCnxnFactory:[myid:16]-[main:NIOServerCnxnFactory@94]-bindingtoport0.0.0.0/0.0.0.0:2291 2021-10-1117:07:08,235INFOorg.apache.zookeeper.server.quorum.QuorumPeer:[myid:16]-[main:QuorumPeer@913]-tickTimesetto9000 2021-10-1117:07:08,235INFOorg.apache.zookeeper.server.quorum.QuorumPeer:[myid:16]-[main:QuorumPeer@933]-minSessionTimeoutsetto-1 2021-10-1117:07:08,235INFOorg.apache.zookeeper.server.quorum.QuorumPeer:[myid:16]-[main:QuorumPeer@944]-maxSessionTimeoutsetto-1 2021-10-1117:07:08,236INFOorg.apache.zookeeper.server.quorum.QuorumPeer:[myid:16]-[main:QuorumPeer@959]-initLimitsetto10 2021-10-1117:07:08,285INFOorg.apache.zookeeper.server.persistence.FileSnap:[myid:16]-[main:FileSnap@83]-Readingsnapshot/var/license/version-2/snapshot.70000007a 2021-10-1117:07:08,330ERRORorg.apache.zookeeper.server.persistence.Util:[myid:16]-[main:Util@239]-Lasttransactionwaspartial. 2021-10-1117:07:08,331ERRORorg.apache.zookeeper.server.quorum.QuorumPeer:[myid:16]-[main:QuorumPeer@453]-Unabletoloaddatabaseondisk java.io.EOFException atjava.io.DataInputStream.readInt(DataInputStream.java:392) atorg.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63) atorg.apache.zookeeper.server.persistence.FileHeader.deserialize(FileHeader.java:64) atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.inStreamCreated(FileTxnLog.java:558) atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.createInputArchive(FileTxnLog.java:577) atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.goToNextLog(FileTxnLog.java:543) atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.next(FileTxnLog.java:625) atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.init(FileTxnLog.java:529) atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.(FileTxnLog.java:504) atorg.apache.zookeeper.server.persistence.FileTxnLog.read(FileTxnLog.java:341) atorg.apache.zookeeper.server.persistence.FileTxnSnapLog.restore(FileTxnSnapLog.java:132) atorg.apache.zookeeper.server.ZKDatabase.loadDataBase(ZKDatabase.java:223) atorg.apache.zookeeper.server.quorum.QuorumPeer.loadDataBase(QuorumPeer.java:417) atorg.apache.zookeeper.server.quorum.QuorumPeer.start(QuorumPeer.java:409) atorg.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:151) atorg.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:111) atorg.apache.zookeeper.server.quorum.QuorumPeerMain.main(QuorumPeerMain.java:78) 2021-10-1117:07:08,332ERRORorg.apache.zookeeper.server.quorum.QuorumPeerMain:[myid:16]-[main:QuorumPeerMain@89]-Unexpectedexception,exitingabnormally java.lang.RuntimeException:Unabletorunquorumserver atorg.apache.zookeeper.server.quorum.QuorumPeer.loadDataBase(QuorumPeer.java:454) atorg.apache.zookeeper.server.quorum.QuorumPeer.start(QuorumPeer.java:409) atorg.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:151) atorg.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:111) atorg.apache.zookeeper.server.quorum.QuorumPeerMain.main(QuorumPeerMain.java:78) Causedby:java.io.EOFException atjava.io.DataInputStream.readInt(DataInputStream.java:392) atorg.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63) atorg.apache.zookeeper.server.persistence.FileHeader.deserialize(FileHeader.java:64) atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.inStreamCreated(FileTxnLog.java:558) atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.createInputArchive(FileTxnLog.java:577) atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.goToNextLog(FileTxnLog.java:543) atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.next(FileTxnLog.java:625) atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.init(FileTxnLog.java:529) atorg.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.(FileTxnLog.java:504) atorg.apache.zookeeper.server.persistence.FileTxnLog.read(FileTxnLog.java:341) atorg.apache.zookeeper.server.persistence.FileTxnSnapLog.restore(FileTxnSnapLog.java:132) atorg.apache.zookeeper.server.ZKDatabase.loadDataBase(ZKDatabase.java:223) atorg.apache.zookeeper.server.quorum.QuorumPeer.loadDataBase(QuorumPeer.java:417) …4more7 问题解决
通过以上通用问题排查思路,我们查看日志找到了问题原因: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