Kubernetes 應用問題的通用排查思路
本文轉載自微信公眾號「明哥的IT隨筆」,作者IT明哥。轉載本文請聯(lián)系明哥的IT隨筆公眾號。
大家好,我是明哥!
本片文章介紹下 Kubernetes 應用問題的通用排查思路,分享一個線上此類問題的排查案例,總結下背后的相關知識,以饗讀者,大家共勉!
1 技術趨勢大背景
我們知道,大數(shù)據(jù)進一步發(fā)展的一個趨勢,就是大數(shù)據(jù)和云計算進一步融合(包括在底層更加青睞存儲計算分離的架構,在底層更加青睞對象存儲),在部署架構上支持混合云和多云場景,擁抱云計算走向云原生化。
對應到底層具體技術堆棧上,體現(xiàn)在各個主流大數(shù)據(jù)平臺和底層的大數(shù)據(jù)組件,紛紛開始支持以 Kubernetes 和 Docker 為代表的容器系列技術棧。
所以大數(shù)據(jù)從業(yè)者,需要不斷擴展自己的技能包,掌握 Kubernetes 和 Docker 的基礎知識和常見命令,才能在排查大數(shù)據(jù)相關問題時不至于捉襟見肘,因技能儲備短缺,無從下手。
從技術視角看大數(shù)據(jù)行業(yè)的發(fā)展趨勢
在此分享一個大數(shù)據(jù)平臺中 docker 容器相關故障的排查案列,并介紹下此類問題的背后知識和排查思路,以饗讀者,大家共勉!
2 問題現(xiàn)象
星環(huán)大數(shù)據(jù)平臺 TDH 中, zookeeper 服務無法正常啟動。我們知道 TDH 中,各個服務其實是在 k8s 的管控下運行于 docker 容器中,通過 kubectl get pods -owide |grep -i zoo 可以發(fā)現(xiàn),對應的 pod 的狀態(tài)是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 背后知識:為什么會發(fā)生 CrashLoopBackOff 錯誤?
pod 的 CrashLoopBackOff 錯誤還是挺常見的,該錯誤可能會因為多種原因被觸發(fā),幾個主要的上層原因有:
- Kubernetes 集群部署有問題;
- 該 pod 或 pod 底層的 container 的某些參數(shù)被配置錯了;
- 該 pod 內部的 container 中運行的應用程序,在多次重啟運行時都一直處于失敗狀態(tài);
5 背后知識:如何排查 pod 容器底層的應用程序的故障?
當 pod 容器底層的應用程序運行出現(xiàn)故障時,通用的排查思路,一般是:
- 步驟一:通過命令 kubectl describe pod xxx 獲取 pod 詳細信息
- 步驟二:通過命令 kubectl logs xxx 查看 pod 容器底層的應用程序的日志
- 步驟三:進一步獲取并查看 pod 容器底層的應用程序的其它日志文件,深挖問題原因
有的小伙伴可能會有疑問,上述步驟二和步驟三都是查看 pod 容器底層的應用程序的日志,有什么區(qū)別呢?
其實步驟二和步驟三在底層查看的是應用程序的不同的日志文件,其底層細節(jié)跟 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 在底層會通過運行在各個節(jié)點的 kubelet 來收集節(jié)點中所有 container 的 stdout 和 stderr 日志,并寫到一個 kubelet 管理的本地文件中;
- 用戶執(zhí)行 kubectl logs xx 命令時,該命令在底層會調用該 container 對應節(jié)點上的 kubelet 來檢索其管理的本地日志文件,以獲取日志;
- 用戶使用 kubectl log xxx 來檢索應用程序日志,省去了用戶登錄 k8s 集群中對應節(jié)點查看對應日志的繁瑣操作,提供了很大遍歷;
ps. 我們這里討論的是運行在 k8s 容器中的應用程序的日志,除了應用程序的日志,其實整個k8s 集群中還有很多系統(tǒng)組件的日志,如:docker,kubelet,kube-proxy,kube-apiserver,kube-scheduler,etcd等。
6 問題排查復盤
按照上述通用問題排查思路,我們復盤回顧下該 CrashLoopBackOff 問題的排查經(jīng)過。
6.1:問題排查復盤:通過命令 kubeclt describe pod xxx 獲取 pod 詳細信息
該命令輸出的部分截圖如下,通過輸出中 Events 部分,我們可以獲取如下信息:該 pod 被成功地分配到了某個節(jié)點上,然后鏡像拉取成功,然后 contaier 創(chuàng)建和啟動成功,但隨后 contaier 中程序運行失敗,最后 pod 進入到了 BackOff 狀態(tài):
kubectl-describe-pod
該命令的詳細輸出如下:
- kubectl describe pod zookeeper-server-license-7fbfc544fc-h8nn9
- Name: zookeeper-server-license-7fbfc544fc-h8nn9
- Namespace: default
- Priority: 0
- PriorityClassName: <none>
- Node: uf30-tdh3-regression/10.20.159.115
- Start Time: Mon, 11 Oct 2021 16:56:30 +0800
- Labels: name=zookeeper-server-license
- pod-template-hash=3969710097
- podConflictName=zookeeper-server-license
- Annotations: <none>
- Status: Running
- IP: 10.20.159.115
- Controlled By: ReplicaSet/zookeeper-server-license-7fbfc544fc
- Containers:
- zookeeper-server-license:
- Container ID: docker://0887c97ab185f1b004759e8c85b48631f511cb43088424190c3f27c715bb8414
- Image: transwarp/zookeeper:transwarp-6.0.2-final
- Image ID: docker-pullable://transwarp/zookeeper@sha256:19bf952dedc70a1d82ba9dd9217a2b7e34fc018561c2741d8f6065c0d87f8a10
- Port: <none>
- Args:
- boot.sh
- LICENSE_NODE
- State: Terminated
- Reason: Error
- Exit Code: 1
- Started: Mon, 11 Oct 2021 17:12:09 +0800
- Finished: Mon, 11 Oct 2021 17:12:10 +0800
- Last State: Terminated
- Reason: Error
- Exit Code: 1
- Started: Mon, 11 Oct 2021 17:07:07 +0800
- Finished: Mon, 11 Oct 2021 17:07:08 +0800
- Ready: False
- Restart Count: 8
- Environment:
- ZOOKEEPER_CONF_DIR: /etc/license/conf
- Mounts:
- /etc/license/conf from conf (rw)
- /etc/localtime from timezone (rw)
- /etc/tos/conf from tos (rw)
- /etc/transwarp/conf from transwarphosts (rw)
- /usr/lib/transwarp/plugins from plugin (rw)
- /var/license from data (rw)
- /var/log/license/ from log (rw)
- /var/run/secrets/kubernetes.io/serviceaccount from default-token-g42jt (ro)
- /vdir from mountbind (rw)
- Conditions:
- Type Status
- Initialized True
- Ready False
- PodScheduled True
- Volumes:
- data:
- Type: HostPath (bare host directory volume)
- Path: /var/license
- HostPathType:
- conf:
- Type: HostPath (bare host directory volume)
- Path: /etc/license/conf
- HostPathType:
- log:
- Type: HostPath (bare host directory volume)
- Path: /var/log/license/
- HostPathType:
- mountbind:
- Type: HostPath (bare host directory volume)
- Path: /transwarp/mounts/license
- HostPathType:
- plugin:
- Type: HostPath (bare host directory volume)
- Path: /usr/lib/transwarp/plugins
- HostPathType:
- timezone:
- Type: HostPath (bare host directory volume)
- Path: /etc/localtime
- HostPathType:
- transwarphosts:
- Type: HostPath (bare host directory volume)
- Path: /etc/transwarp/conf
- HostPathType:
- tos:
- Type: HostPath (bare host directory volume)
- Path: /etc/tos/conf
- HostPathType:
- default-token-g42jt:
- Type: Secret (a volume populated by a Secret)
- SecretName: default-token-g42jt
- Optional: false
- QoS Class: BestEffort
- Node-Selectors: zookeeper-server-license=true
- Tolerations: node.kubernetes.io/not-ready:NoExecute for 300s
- node.kubernetes.io/unreachable:NoExecute for 300s
- Events:
- Type Reason Age From Message
- ---- ------ ---- ---- -------
- Normal SuccessfulMountVolume 15m kubelet, uf30-tdh3-regression MountVolume.SetUp succeeded for volume "default-token-g42jt"
- Normal SuccessfulMountVolume 15m kubelet, uf30-tdh3-regression MountVolume.SetUp succeeded for volume "conf"
- Normal SuccessfulMountVolume 15m kubelet, uf30-tdh3-regression MountVolume.SetUp succeeded for volume "tos"
- Normal SuccessfulMountVolume 15m kubelet, uf30-tdh3-regression MountVolume.SetUp succeeded for volume "mountbind"
- Normal SuccessfulMountVolume 15m kubelet, uf30-tdh3-regression MountVolume.SetUp succeeded for volume "transwarphosts"
- Normal SuccessfulMountVolume 15m kubelet, uf30-tdh3-regression MountVolume.SetUp succeeded for volume "log"
- Normal SuccessfulMountVolume 15m kubelet, uf30-tdh3-regression MountVolume.SetUp succeeded for volume "plugin"
- Normal SuccessfulMountVolume 15m kubelet, uf30-tdh3-regression MountVolume.SetUp succeeded for volume "data"
- Normal SuccessfulMountVolume 15m kubelet, uf30-tdh3-regression MountVolume.SetUp succeeded for volume "timezone"
- Normal Scheduled 15m default-scheduler Successfully assigned zookeeper-server-license-7fbfc544fc-h8nn9 to uf30-tdh3-regression
- Normal Pulled 15m (x3 over 15m) kubelet, uf30-tdh3-regression Successfully pulled image "transwarp/zookeeper:transwarp-6.0.2-final"
- Normal Created 15m (x3 over 15m) kubelet, uf30-tdh3-regression Created container
- Normal Started 15m (x3 over 15m) kubelet, uf30-tdh3-regression Started container
- Normal Pulling 15m (x4 over 15m) kubelet, uf30-tdh3-regression pulling image "transwarp/zookeeper:transwarp-6.0.2-final"
- Warning BackOff 44s (x70 over 15m) kubelet, uf30-tdh3-regression Back-off restarting failed container
6.2 問題排查復盤:通過命令 kubectl logs xxx 查看 pod 容器底層的應用程序的日志
接下來我們嘗試通過命令 kubectl logs xxx 查看 pod 容器底層的應用程序的日志,以期找到問題的原因,該命令的輸出部分截圖如下所示:圖片
如上圖所見,不幸的是,該命令的輸出,沒有展示出問題的根本原因。
在底層日志機制上,應該是星環(huán) tdh 中該 zk 應用沒有將日志打印到標準輸出 stdout 和標準錯誤 stderr, 所以 kubectl logs xxx 查看不到對應的日志。
我們需要進一步排查。
6.3 問題排查復盤:進一步獲取并查看 pod 容器底層的應用程序的其它日志文件,深挖問題原因
進一步排查問題,我們首先需要獲取 pod 容器底層的應用程序的其它日志文件的路徑。
由于 tdh 是閉源的,我們查看不到應用程序的源碼,在沒有聯(lián)絡官方客戶的情況下,我們可以通過命令 kubectl describe pod xxx 查看該 pod 掛載了哪些 volume,然后猜測并驗證獲得具體的日志文件的路勁給,(排查問題就是要,大膽猜想,小心求證!)
該命令輸出的部分截圖如下,我們看到其中掛載了路徑 /var/log/license:
接下來我們查看這些日志文件/var/log/license,嘗試深挖問題原因,注意,該文件是本地文件系統(tǒng)的文件,需要登錄到對應的節(jié)點上去查看,該日志文件部分關鍵截圖如下:
通過日志,問題原因找到了:zk 底層存儲在本地文件系統(tǒng)中的文件 /var/license/version-2/snapshot.70000007a 損壞了,所以無法啟動:
- 2021-10-11 17:07:08,330 ERROR org.apache.zookeeper.server.persistence.Util: [myid:16] - [main:Util@239] - Last transaction was partial.
- 2021-10-11 17:07:08,331 ERROR org.apache.zookeeper.server.quorum.QuorumPeer: [myid:16] - [main:QuorumPeer@453] - Unable to load database on disk
- java.io.EOFException at java.io.DataInputStream.readInt(DataInputStream.java:392)
該日志文件詳細內容如下:
- tail -50 /var/log/license/zookeeper.log
- 2021-10-11 17:07:08,203 INFO org.apache.zookeeper.server.DatadirCleanupManager: [myid:16] - [main:DatadirCleanupManager@101] - Purge task is not scheduled.
- 2021-10-11 17:07:08,212 INFO org.apache.zookeeper.server.quorum.QuorumPeerMain: [myid:16] - [main:QuorumPeerMain@127] - Starting quorum peer
- 2021-10-11 17:07:08,221 INFO org.apache.zookeeper.server.NIOServerCnxnFactory: [myid:16] - [main:NIOServerCnxnFactory@94] - binding to port 0.0.0.0/0.0.0.0:2291
- 2021-10-11 17:07:08,235 INFO org.apache.zookeeper.server.quorum.QuorumPeer: [myid:16] - [main:QuorumPeer@913] - tickTime set to 9000
- 2021-10-11 17:07:08,235 INFO org.apache.zookeeper.server.quorum.QuorumPeer: [myid:16] - [main:QuorumPeer@933] - minSessionTimeout set to -1
- 2021-10-11 17:07:08,235 INFO org.apache.zookeeper.server.quorum.QuorumPeer: [myid:16] - [main:QuorumPeer@944] - maxSessionTimeout set to -1
- 2021-10-11 17:07:08,236 INFO org.apache.zookeeper.server.quorum.QuorumPeer: [myid:16] - [main:QuorumPeer@959] - initLimit set to 10
- 2021-10-11 17:07:08,285 INFO org.apache.zookeeper.server.persistence.FileSnap: [myid:16] - [main:FileSnap@83] - Reading snapshot /var/license/version-2/snapshot.70000007a
- 2021-10-11 17:07:08,330 ERROR org.apache.zookeeper.server.persistence.Util: [myid:16] - [main:Util@239] - Last transaction was partial.
- 2021-10-11 17:07:08,331 ERROR org.apache.zookeeper.server.quorum.QuorumPeer: [myid:16] - [main:QuorumPeer@453] - Unable to load database on disk
- java.io.EOFException
- at java.io.DataInputStream.readInt(DataInputStream.java:392)
- at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
- at org.apache.zookeeper.server.persistence.FileHeader.deserialize(FileHeader.java:64)
- at org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.inStreamCreated(FileTxnLog.java:558)
- at org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.createInputArchive(FileTxnLog.java:577)
- at org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.goToNextLog(FileTxnLog.java:543)
- at org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.next(FileTxnLog.java:625)
- at org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.init(FileTxnLog.java:529)
- at org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.<init>(FileTxnLog.java:504)
- at org.apache.zookeeper.server.persistence.FileTxnLog.read(FileTxnLog.java:341)
- at org.apache.zookeeper.server.persistence.FileTxnSnapLog.restore(FileTxnSnapLog.java:132)
- at org.apache.zookeeper.server.ZKDatabase.loadDataBase(ZKDatabase.java:223)
- at org.apache.zookeeper.server.quorum.QuorumPeer.loadDataBase(QuorumPeer.java:417)
- at org.apache.zookeeper.server.quorum.QuorumPeer.start(QuorumPeer.java:409)
- at org.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:151)
- at org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:111)
- at org.apache.zookeeper.server.quorum.QuorumPeerMain.main(QuorumPeerMain.java:78)
- 2021-10-11 17:07:08,332 ERROR org.apache.zookeeper.server.quorum.QuorumPeerMain: [myid:16] - [main:QuorumPeerMain@89] - Unexpected exception, exiting abnormally
- java.lang.RuntimeException: Unable to run quorum server
- at org.apache.zookeeper.server.quorum.QuorumPeer.loadDataBase(QuorumPeer.java:454)
- at org.apache.zookeeper.server.quorum.QuorumPeer.start(QuorumPeer.java:409)
- at org.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:151)
- at org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:111)
- at org.apache.zookeeper.server.quorum.QuorumPeerMain.main(QuorumPeerMain.java:78)
- Caused by: java.io.EOFException
- at java.io.DataInputStream.readInt(DataInputStream.java:392)
- at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63)
- at org.apache.zookeeper.server.persistence.FileHeader.deserialize(FileHeader.java:64)
- at org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.inStreamCreated(FileTxnLog.java:558)
- at org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.createInputArchive(FileTxnLog.java:577)
- at org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.goToNextLog(FileTxnLog.java:543)
- at org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.next(FileTxnLog.java:625)
- at org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.init(FileTxnLog.java:529)
- at org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.<init>(FileTxnLog.java:504)
- at org.apache.zookeeper.server.persistence.FileTxnLog.read(FileTxnLog.java:341)
- at org.apache.zookeeper.server.persistence.FileTxnSnapLog.restore(FileTxnSnapLog.java:132)
- at org.apache.zookeeper.server.ZKDatabase.loadDataBase(ZKDatabase.java:223)
- at org.apache.zookeeper.server.quorum.QuorumPeer.loadDataBase(QuorumPeer.java:417)
- ... 4 more
7 問題解決
通過以上通用問題排查思路,我們查看日志找到了問題原因:zk 底層存儲在本地文件系統(tǒng)中的文件 /var/license/version-2/snapshot.70000007a 損壞了,所以無法啟動。由于集群中 zk 是有多個節(jié)點的,且其它節(jié)點的 zk 啟動是成功的,所以我們 可以刪除該問題節(jié)點上述目錄下的數(shù)據(jù)文件,然后重啟該節(jié)點的 zk, 重啟后該節(jié)點的 zk 就可以從其它節(jié)點復制數(shù)據(jù)到本地,就可以正常對外提供服務了!
zk 底層存儲在本地文件系統(tǒng)中的文件,在正常節(jié)點于問題節(jié)點,對比截圖如下:
zk data on good node
zk data on bad node
按照上述方法,清空目錄重啟zk后,kubectl get pods 查看服務正常,截圖如下:
kubectl-get-pods-after-fix
注意:其實 zk 也提供了系統(tǒng)工具 zkCleanup.sh 來清理本地數(shù)據(jù)文件,筆者沒有使用該工具,而是手工備份和清空了問題節(jié)點的本地文件。大家可以自行嘗試該工具。
zkCleanup.sh
8 知識總結
- 大數(shù)據(jù)從業(yè)者,需要不斷擴展自己的技能包,掌握 Kubernetes 和 Docker 的基礎知識和常見命令,才能在排查大數(shù)據(jù)相關問題時不至于捉襟見肘,因技能儲備短缺,無從下手;
- 某個 pod 處于 CrashloopBackOff, 意味著該 pod 中的容器被啟動了,然后崩潰了,接下來又被自動啟動了,但又崩潰了,如此周而復始,陷入了(starting, crashing, starting,crashing)的循壞;
- 當 pod 容器底層的應用程序運行出現(xiàn)故障時,通用的排查思路,一般是:
步驟一:通過命令 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 在底層會通過運行在各個節(jié)點的 kubelet 來收集節(jié)點中所有 container 的 stdout 和 stderr 日志,并寫到一個 kubelet 管理的本地文件中;
- 用戶執(zhí)行 kubectl logs xx 命令時,該命令在底層會調用該 container 對應節(jié)點上的 kubelet 來檢索其管理的本地日志文件,以獲取日志;
- 用戶使用 kubectl log xxx 來檢索應用程序日志,省去了用戶登錄 k8s 集群中對應節(jié)點查看對應日志的繁瑣操作,提供了很大便利;
- 排查問題,需要大膽猜想小心求證!