Kubernetes 應用問題的通用排查思路

作者： IT明哥 2021-10-14 07:28:03

云計算

本片文章介紹下 Kubernetes 應用問題的通用排查思路，分享一個線上此類問題的排查案例，總結下背后的相關知識，以饗讀者，大家共勉！

[[428799]]

本文轉載自微信公眾號「明哥的IT隨筆」，作者IT明哥。轉載本文請聯系明哥的IT隨筆公眾號。

大家好，我是明哥！

本片文章介紹下 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

該命令的詳細輸出如下：

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 容器底層的應用程序的日志，以期找到問題的原因，該命令的輸出部分截圖如下所示：圖片

如上圖所見，不幸的是，該命令的輸出，沒有展示出問題的根本原因。

在底層日志機制上，應該是星環 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-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 底層存儲在本地文件系統中的文件 /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 集群中對應節點查看對應日志的繁瑣操作，提供了很大便利；
排查問題，需要大膽猜想小心求證！

責任編輯：武曉燕來源：明哥的IT隨筆

Kubernetes 通用排查