排障的前置條件
k8s的成熟度很高，伴隨着整個項目的擴增，以及新功能和新流程的不斷引入，也伴隨這產生了一些問題。雖然自動化測試可以排除掉大部分，但是一些復雜流程以及極端情況卻很難做到bug的完全覆蓋。因此在實際的工作過程中，需要對運行的集群進行故障定位和解決。
當然，進行排障的前提是對於k8s的流程和概念進行掌握，對於源碼有一定的掌握能力，才可以更好的進行。待排障的環境和版本和源代碼的版本需要進行匹配。版本號可以通過version命令獲取，然后從源碼進行對照。而且kubectl version還可以展示更為git的commit id。這樣更為精准一些。本文以一次排障過程為例，介紹進行kubernetes問題排障的一般思路和方法。
故障背景
在某個壓測的集群(集群版本為v1.12.10)內，為了測試極端性能，於是kubelet上配置了單節點可以創建的容器數從110調整為了600。並且進行反復大批量的容器創建和刪除。在壓測后一段時間，陸續多個節點變為NotReady，直到整個節點全部變為了NotReady。在節點上看到有大量的容器待刪除。kubelet雖然仍在運行，但是已經不進行任何的pod生命周期的管理了，已經呆住了。其他組件大都正常。此時停了壓測工具，kubelet仍然不能夠恢復正常。嘗試將一個節點的kubelet重啟后，節點恢復正常。
故障分析
日志分析
首先從日志上進行分析。日志是日常排障的最主要的工具。從長期經驗來看，我們的主要方式是將日志寫入到文件，並配合glogrotate進行日志的回滾。不使用journal的主要原因一個是習慣，另外就是使用效率上也沒有文件來的快速。關於日志級別，日志級別太高，日志量會很大；而級別太低，日志信息量又不足。日志級別按照經驗我們一般定位4級。
從日志上進行分析，可以看到這樣一條日志。
I1105 09:50:27.583544 548093 kubelet.go:1829] skipping pod synchronization - [PLEG is not healthy: pleg was last seen active 58h29m3.043779855s ago; threshold is 3m0s]
也就是PLEG不再健康了。那么這一行是怎么報出來的呢？對照代碼，我們可以找到這樣的信息。
func (kl *Kubelet) syncLoop(updates <-chan kubetypes.PodUpdate, handler SyncHandler) {
......
for {
if rs := kl.runtimeState.runtimeErrors(); len(rs) != 0 {
glog.Infof("skipping pod synchronization - %v", rs)
// exponential backoff
time.Sleep(duration)
duration = time.Duration(math.Min(float64(max), factor*float64(duration)))
continue
}
// reset backoff if we have a success
duration = base
kl.syncLoopMonitor.Store(kl.clock.Now())
if !kl.syncLoopIteration(updates, handler, syncTicker.C, housekeepingTicker.C, plegCh) {
break
}
kl.syncLoopMonitor.Store(kl.clock.Now())
}
......
PLEG不再健康，這里就會直接continue，也就不會走到下面的syncLoopIteration函數。而這個函數通過逐層調用，最終會到syncPod上。這也就解釋了為什么節點上kubelet不再處理pod生命周期的原因了。但是為什么PLEG不再健康。那么它的判斷標准又是什么呢？繼續看代碼。
func (g *GenericPLEG) Healthy() (bool, error) {
relistTime := g.getRelistTime()
elapsed := g.clock.Since(relistTime)
if elapsed > relistThreshold {
return false, fmt.Errorf("pleg was last seen active %v ago; threshold is %v", elapsed, relistT
hreshold)
}
return true, nil
}
同時，這里可以看到PLEG的健康狀態是以上次relist的時間來確定的。那么relist的時間又是在哪更新的呢？這個可以通過代碼找到func (g *GenericPLEG) relist(){...}函數，也就是在這個函數里進行relist的時間更新的。那么可以初步判定應該可能在這個函數的某個流程里卡住了，導致的整個問題。但是這個函數有上百行，我們怎么定位呢？好像日志分析能夠提供的幫助已經很有限了。那么我們需要一些其他的工具來輔助定位。
pprof
pprof就是這樣的一個工具。pprof是什么，怎么用，這里不展開講，可以去搜具體的資料。kubelet里有一個配置enable-debugging-handlers，通過配置為true進行開啟（默認為true）。開啟后，借助於這個工具，我們進行進一步的定位。kubelet的工作默認端口為10250。因為我們的集群中kubelet開啟了認證，所以我們這里用curl命令直接把需要的堆棧信息拉取下來。
curl -k --cert admin.pem --key admin-key.pem "https://127.0.0.1:10250/debug/pprof/goroutine?debug=1" > stack.txt
因為卡住了，所以有非常多的goroutine信息。堆棧信息太長，這里就不全部拉取了，這里只截取我們關心的，就是relist卡在了哪里。我們搜索relist，可以看到這樣的信息。
goroutine profile: total 2814
...
1 @ 0x42fcaa 0x42fd5e 0x4066cb 0x406465 0x30d4f3e 0x30d682a 0xad7474 0xad6a0d 0xad693d 0x45d2f1
# 0x30d4f3d k8s.io/kubernetes/pkg/kubelet/pleg.(*GenericPLEG).relist+0x74d /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/pkg/kubelet/pleg/generic.go:261
# 0x30d6829 k8s.io/kubernetes/pkg/kubelet/pleg.(*GenericPLEG).(k8s.io/kubernetes/pkg/kubelet/pleg.relist)-fm+0x29 /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/pkg/kubelet/pleg/generic.go:130
# 0xad7473 k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil.func1+0x53 /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:133
# 0xad6a0c k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil+0xbc /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:134
# 0xad693c k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.Until+0x4c /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait/wait.go:88
而且我們反復對照了多個節點，可以看到出現故障的節點，都卡在了這個261行的地方。這時候去找代碼。
func (g *GenericPLEG) relist() {
......
for i := range events {
// Filter out events that are not reliable and no other components use yet.
if events[i].Type == ContainerChanged {
continue
}
g.eventChannel <- events[i] //261行
}
位於261行的地方是g.eventChannel <- events[i]這個代碼。很奇怪，這個就發送一個event到channel里，為什么會卡住？難道channel close掉了？這個eventChannel又是個什么。追溯eventChannel的使用可以看到channel是在syncLoopIteration中被消費。同時還發現，eventChannel是一個有固定容量，1000的一個channel。那么問題逐漸變得清晰了起來。
故障推斷分析
反復大量的創建和刪除，導致產生了非常多的event。這些event被發送進了eventChannel里，進而在syncLoopIteration的流程中進行消費。但是當syncLoopIteration消費的速度過慢，而events產生過快的時候，就會在g.eventChannel <- events[i]地方卡住。
由於上面event發送卡住了，relist流程無法正常進行。那么這里會導致PLEG變為not healthy。PLEG not healthy之后，rs := kl.runtimeState.runtimeErrors(); 將會生成錯誤。生成的錯誤就是PLEG is not healthy。更加糟糕的事情就這樣發生了，PLEG不健康會導致調過syncLoopIteration的流程。而PLEG里面的eventChannel的消費是在syncLoopIteration里完成的。也就是說eventChannel沒有人去消費，會一直保持滿的狀態。導致整體死鎖了。新數據進不來，已有數據也無人消費。
故障模擬
分析完成后是不是就可以完全斷定了呢？最為安全保險的做法是在進行一下故障的模擬驗證，以便驗證自己的猜想。
那么對於本次的問題，那么我們如何驗證呢？其實也很簡單，減少eventChannel的容量，增加幾行日志，打印channel的len，在進行一下壓測，很快就能復現了。這里就不重復敘述了。
故障解決
知道了問題的定位之后，想辦法解決就可以了。對於這個問題我們如何解決呢？第一反應是可以增加eventChannel的容量。這個會額外消耗一些資源，但是整體問題不大。但是有沒有更加優雅的方式呢？我試着去社區找一下，發現在今年已經有人發現並解決了這一問題了。https://github.com/kubernetes/kubernetes/pull/72709
解決方式很簡潔，就是直接往eventChannel里塞，如果塞滿了，直接記錄一個錯誤日志，就不管了。
for i := range events {
// Filter out events that are not reliable and no other components use yet.
if events[i].Type == ContainerChanged {
continue
}
select {
case g.eventChannel <- events[i]:
default:
metrics.PLEGDiscardEvents.WithLabelValues().Inc()
klog.Error("event channel is full, discard this relist() cycle event")
}
}
這樣的方式合理么？會丟棄event么？當然不會。因為relist是定時執行的。本次雖然丟棄了event，但是在下次relist的時候，會重新產生，並嘗試再次塞入eventChannel。因此這種方式還是很簡潔和高效的。這個bug fix已經合入了1.14以后的版本，但是1.12的版本未能覆蓋。這里我們就將這個代碼手動合入了我們自己的版本了。
寫在最后
在生產和測試環境中，由於種種原因，可能是k8s的問題，可能是運維的問題，也可能是用戶使用的問題，可能會出現種種狀況。排查問題還是務求謹慎細致。我的一般原則是生產環境優先保存日志和堆棧后，立即恢復環境，保障用戶使用。而在測試環境，優先把問題定位出來，盡量把錯誤前置，在測試環境發現並解決，防止其擴散到生產環境。