Pod Terminating 狀態(tài)排查
1. 背景
近期，彈性云線上集群發(fā)生了幾起特殊的容器漂移失敗事件，其特殊之處在于容器處于Pod Terminating狀態(tài)，而宿主則處于Ready狀態(tài)。
宿主狀態(tài)為Ready說(shuō)明其能夠正常處理Pod事件，但是Pod卻卡在了退出階段，說(shuō)明此問(wèn)題并非由kubelet引起，那么docker就是1號(hào)犯罪嫌疑人了。
下文將詳細(xì)介紹問(wèn)題的排查與分析全過(guò)程。
2. 抽絲剝繭
2.1 排除kubelet嫌疑
Pod狀態(tài)如下：
[stupig@master ~]$ kubectl get pod -owide
pod-976a0-5 0/1 Terminating 0 112m
盡管kubelet的犯罪嫌疑已經(jīng)很小，但是我們還是需要排查kubelet日志進(jìn)一步確認(rèn)。截取kubelet關(guān)鍵日志片段如下：
I1014 10:56:46.492682 34976 kubelet_pods.go:1017] Pod "pod-976a0-5_default(f1e03a3d-0dc7-11eb-b4b1-246e967c4efc)" is terminated, but some containers have not been cleaned up: {ID:{Type:docker ID:41020461ed4d801afa8d10847a16907e65f6e8ca34d1704edf15b0d0e72bf4ef} Name:stupig State:exited CreatedAt:2020-10-14 10:49:57.859913657 +0800 CST StartedAt:2020-10-14 10:49:57.928654495 +0800 CST FinishedAt:2020-10-14 10:50:28.661263065 +0800 CST ExitCode:0 Hash:2101852810 HashWithoutResources:2673273670 RestartCount:0 Reason:Completed Message: Resources:map[CpuQuota:200000 Memory:2147483648 MemorySwap:2147483648]}
E1014 10:56:46.709255 34976 remote_runtime.go:250] RemoveContainer "41020461ed4d801afa8d10847a16907e65f6e8ca34d1704edf15b0d0e72bf4ef" from runtime service failed: rpc error: code = Unknown desc = failed to remove container "41020461ed4d801afa8d10847a16907e65f6e8ca34d1704edf15b0d0e72bf4ef": Error response from daemon: container 41020461ed4d801afa8d10847a16907e65f6e8ca34d1704edf15b0d0e72bf4ef: driver "overlay2" failed to remove root filesystem: unlinkat /home/docker_rt/overlay2/e5dab77be213d9f9cfc0b0b3281dbef9c2878fee3b8e406bc8ab97adc30ae4d5/merged: device or resource busy
E1014 10:56:46.709292 34976 kuberuntime_gc.go:126] Failed to remove container "41020461ed4d801afa8d10847a16907e65f6e8ca34d1704edf15b0d0e72bf4ef": rpc error: code = Unknown desc = failed to remove container "41020461ed4d801afa8d10847a16907e65f6e8ca34d1704edf15b0d0e72bf4ef": Error response from daemon: container 41020461ed4d801afa8d10847a16907e65f6e8ca34d1704edf15b0d0e72bf4ef: driver "overlay2" failed to remove root filesystem: unlinkat /home/docker_rt/overlay2/e5dab77be213d9f9cfc0b0b3281dbef9c2878fee3b8e406bc8ab97adc30ae4d5/merged: device or resource busy
日志顯示kubelet處于Pod Terminating狀態(tài)的原因很清楚：清理容器失敗。
kubelet清理容器的命令是 docker rm -f ，其失敗的原因在于刪除容器目錄 xxx/merged 時(shí)報(bào)錯(cuò)，錯(cuò)誤提示為 device or resource busy 。
除此之外，kubelet無(wú)法再提供其他關(guān)鍵信息。
登陸宿主，我們驗(yàn)證對(duì)應(yīng)容器的狀態(tài)：
[stupig@hostname ~]$ sudo docker ps -a | grep pod-976a0-5
41020461ed4d Removal In Progress k8s_stupig_pod-976a0-5_default_f1e03a3d-0dc7-11eb-b4b1-246e967c4efc_0
f0a75e10b252 Exited (0) 2 minutes ago k8s_POD_pod-976a0-5_default_f1e03a3d-0dc7-11eb-b4b1-246e967c4efc_0
[stupig@hostname ~]$ sudo docker rm -f 41020461ed4d
Error response from daemon: container 41020461ed4d801afa8d10847a16907e65f6e8ca34d1704edf15b0d0e72bf4ef: driver "overlay2" failed to remove root filesystem: unlinkat /home/docker_rt/overlay2/e5dab77be213d9f9cfc0b0b3281dbef9c2878fee3b8e406bc8ab97adc30ae4d5/merged: device or resource busy
問(wèn)題已然清楚，現(xiàn)在我們有兩種排查思路：
參考Google上解決 device or resource busy問(wèn)題的思路結(jié)合現(xiàn)象分析代碼
2.2 Google大法
有問(wèn)題找Google！所以，我們首先咨詢了Google，檢索結(jié)果顯示很多人都碰到了類似的問(wèn)題。
而網(wǎng)絡(luò)上主流的解決方案：配置docker服務(wù)MountFlags為slave，避免docker掛載點(diǎn)信息泄漏到其他mnt命名空間，詳細(xì)原因請(qǐng)參閱：docker device busy問(wèn)題解決方案。
這么簡(jiǎn)單？？？顯然不能，檢查發(fā)現(xiàn)docker服務(wù)當(dāng)前已配置MountFlags為slave。網(wǎng)絡(luò)銀彈再次失去功效。
so，我們還是老老實(shí)實(shí)結(jié)合現(xiàn)場(chǎng)分析代碼吧。
2.3 docker處理流程
在具體分析docker代碼之前，先簡(jiǎn)單介紹下docker的處理流程，避免作為一只無(wú)頭蒼蠅處處碰壁。
清楚了docker的處理流程之后，我們?cè)賮?lái)分析現(xiàn)場(chǎng)。
2.4 提審docker
問(wèn)題發(fā)生在docker清理階段，docker清理容器讀寫層出錯(cuò)，報(bào)錯(cuò)信息為 device or resource busy，說(shuō)明docker讀寫層并沒(méi)有被正確卸載，或者是沒(méi)有完全卸載。下面的命令可以驗(yàn)證這個(gè)結(jié)論：
[stupig@hostname ~]$ grep -rwn '/home/docker_rt/overlay2/e5dab77be213d9f9cfc0b0b3281dbef9c2878fee3b8e406bc8ab97adc30ae4d5/merged' /proc/*/mountinfo
/proc/22283/mountinfo:50:386 542 0:92 / /home/docker_rt/overlay2/e5dab77be213d9f9cfc0b0b3281dbef9c2878fee3b8e406bc8ab97adc30ae4d5/merged rw,relatime - overlay overlay rw,lowerdir=XXX,upperdir=XXX,workdir=XXX
/proc/22407/mountinfo:50:386 542 0:92 / /home/docker_rt/overlay2/e5dab77be213d9f9cfc0b0b3281dbef9c2878fee3b8e406bc8ab97adc30ae4d5/merged rw,relatime - overlay overlay rw,lowerdir=XXX,upperdir=XXX,workdir=XXX
/proc/28454/mountinfo:50:386 542 0:92 / /home/docker_rt/overlay2/e5dab77be213d9f9cfc0b0b3281dbef9c2878fee3b8e406bc8ab97adc30ae4d5/merged rw,relatime - overlay overlay rw,lowerdir=XXX,upperdir=XXX,workdir=XXX
/proc/28530/mountinfo:50:386 542 0:92 / /home/docker_rt/overlay2/e5dab77be213d9f9cfc0b0b3281dbef9c2878fee3b8e406bc8ab97adc30ae4d5/merged rw,relatime - overlay overlay rw,lowerdir=XXX,upperdir=XXX,workdir=XXX
不出所料，容器讀寫層仍然被以上四個(gè)進(jìn)程所掛載，進(jìn)而導(dǎo)致docker在清理讀寫層目錄時(shí)報(bào)錯(cuò)。
隨之而來(lái)的問(wèn)題是，為什么docker沒(méi)有正確卸載容器讀寫層？我們先展示下 docker stop 中卸載容器讀寫層掛載的相關(guān)部分代碼：
func (daemon *Daemon) Cleanup(container *container.Container) {
if err := daemon.conditionalUnmountOnCleanup(container); err != nil {
if mountid, err := daemon.imageService.GetLayerMountID(container.ID, container.OS); err == nil {
daemon.cleanupMountsByID(mountid)
}
}
}
func (daemon *Daemon) conditionalUnmountOnCleanup(container *container.Container) error {
return daemon.Unmount(container)
}
func (daemon *Daemon) Unmount(container *container.Container) error {
if container.RWLayer == nil {
return errors.New("RWLayer of container " + container.ID + " is unexpectedly nil")
}
if err := container.RWLayer.Unmount(); err != nil {
logrus.Errorf("Error unmounting container %s: %s", container.ID, err)
return err
}
return nil
}
func (rl *referencedRWLayer) Unmount() error {
return rl.layerStore.driver.Put(rl.mountedLayer.mountID)
}
func (d *Driver) Put(id string) error {
d.locker.Lock(id)
defer d.locker.Unlock(id)
dir := d.dir(id)
mountpoint := path.Join(dir, "merged")
logger := logrus.WithField("storage-driver", "overlay2")
if err := unix.Unmount(mountpoint, unix.MNT_DETACH); err != nil {
logger.Debugf("Failed to unmount %s overlay: %s - %v", id, mountpoint, err)
}
if err := unix.Rmdir(mountpoint); err != nil && !os.IsNotExist(err) {
logger.Debugf("Failed to remove %s overlay: %v", id, err)
}
return nil
}
代碼處理流程清晰明了，最終docker會(huì)發(fā)起 SYS_UMOUNT2 系統(tǒng)調(diào)用卸載容器讀寫層。
但是，docker在清理容器讀寫層時(shí)卻提示錯(cuò)誤，并且容器讀寫層掛載信息也出現(xiàn)在其他進(jìn)程中。難不成docker沒(méi)有執(zhí)行卸載操作？結(jié)合docker日志分析：
Oct 14 10:50:28 hostname dockerd: time="2020-10-14T10:50:28.769199725+08:00" level=debug msg="Failed to unmount e5dab77be213d9f9cfc0b0b3281dbef9c2878fee3b8e406bc8ab97adc30ae4d5 overlay: /home/docker_rt/overlay2/e5dab77be213d9f9cfc0b0b3281dbef9c2878fee3b8e406bc8ab97adc30ae4d5/merged - invalid argument" storage-driver=overlay2
Oct 14 10:50:28 hostname dockerd: time="2020-10-14T10:50:28.769213547+08:00" level=debug msg="Failed to remove e5dab77be213d9f9cfc0b0b3281dbef9c2878fee3b8e406bc8ab97adc30ae4d5 overlay: device or resource busy" storage-driver=overlay2
日志顯示docker在執(zhí)行卸載容器讀寫層命令時(shí)出錯(cuò)，提示 invalid argument。結(jié)合 umount2 文檔可知，容器讀寫層并非是dockerd（docker后臺(tái)進(jìn)程）的掛載點(diǎn)？？？
現(xiàn)在，回過(guò)頭來(lái)分析擁有容器讀寫層掛載信息的進(jìn)程，我們發(fā)現(xiàn)一個(gè)驚人的信息：
[stupig@hostname ~]$ ps -ef|grep -E "22283|22407|28454|28530"
root 22283 1 0 10:48 ? 00:00:00 docker-containerd-shim -namespace moby
root 22407 1 0 10:48 ? 00:00:00 docker-containerd-shim -namespace moby
root 28454 1 0 10:49 ? 00:00:00 docker-containerd-shim -namespace moby
root 28530 1 0 10:49 ? 00:00:00 docker-containerd-shim -namespace moby
容器讀寫層掛載信息沒(méi)有出現(xiàn)在dockerd進(jìn)程命名空間中，卻出現(xiàn)在其他容器的托管服務(wù)shim進(jìn)程的命名空間內(nèi)，推斷dockerd進(jìn)程發(fā)生了重啟，對(duì)比進(jìn)程啟動(dòng)時(shí)間與命名空間詳情可以進(jìn)行驗(yàn)證：
[stupig@hostname ~]$ ps -eo pid,cmd,lstart|grep dockerd
34836 /usr/bin/dockerd --storage- Wed Oct 14 10:50:15 2020
[stupig@hostname ~]$ sudo ls -la /proc/$(pidof dockerd)/ns
lrwxrwxrwx 1 root root 0 Oct 14 10:50 ipc -> ipc:[4026531839]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 mnt -> mnt:[4026533327]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 net -> net:[4026531968]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 pid -> pid:[4026531836]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 user -> user:[4026531837]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 uts -> uts:[4026531838]
[stupig@hostname ~]$ ps -eo pid,cmd,lstart|grep -w containerd|grep -v shim
34849 docker-containerd --config Wed Oct 14 10:50:15 2020
[stupig@hostname ~]$ sudo ls -la /proc/$(pidof docker-containerd)/ns
lrwxrwxrwx 1 root root 0 Oct 14 10:50 ipc -> ipc:[4026531839]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 mnt -> mnt:[4026533327]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 net -> net:[4026531968]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 pid -> pid:[4026531836]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 user -> user:[4026531837]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 uts -> uts:[4026531838]
[stupig@hostname ~]$ ps -eo pid,cmd,lstart|grep -w containerd-shim
22283 docker-containerd-shim -nam Wed Oct 14 10:48:50 2020
22407 docker-containerd-shim -nam Wed Oct 14 10:48:55 2020
28454 docker-containerd-shim -nam Wed Oct 14 10:49:53 2020
28530 docker-containerd-shim -nam Wed Oct 14 10:49:53 2020
[stupig@hostname ~]$ sudo ls -la /proc/28454/ns
lrwxrwxrwx 1 root root 0 Oct 14 10:50 ipc -> ipc:[4026531839]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 mnt -> mnt:[4026533200]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 net -> net:[4026531968]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 pid -> pid:[4026531836]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 user -> user:[4026531837]
lrwxrwxrwx 1 root root 0 Oct 14 10:50 uts -> uts:[4026531838]
[stupig@hostname ~]$ sudo ls -la /proc/$$/ns
lrwxrwxrwx 1 panpeilong panpeilong 0 Oct 14 21:49 ipc -> ipc:[4026531839]
lrwxrwxrwx 1 panpeilong panpeilong 0 Oct 14 21:49 mnt -> mnt:[4026531840]
lrwxrwxrwx 1 panpeilong panpeilong 0 Oct 14 21:49 net -> net:[4026531968]
lrwxrwxrwx 1 panpeilong panpeilong 0 Oct 14 21:49 pid -> pid:[4026531836]
lrwxrwxrwx 1 panpeilong panpeilong 0 Oct 14 21:49 user -> user:[4026531837]
lrwxrwxrwx 1 panpeilong panpeilong 0 Oct 14 21:49 uts -> uts:[4026531838]
結(jié)果驗(yàn)證了我們推斷的正確性。現(xiàn)在再補(bǔ)充下docker組件的進(jìn)程樹(shù)模型，用以解釋這個(gè)現(xiàn)象，模型如下：
dockerd進(jìn)程啟動(dòng)時(shí)，會(huì)自動(dòng)拉起containerd進(jìn)程；當(dāng)用戶創(chuàng)建并啟動(dòng)容器時(shí)，containerd會(huì)啟動(dòng)containerd-shim進(jìn)程用于托管容器進(jìn)程，最終由containerd-shim調(diào)用runc啟動(dòng)容器進(jìn)程。runc負(fù)責(zé)初始化進(jìn)程命名空間，并exec容器啟動(dòng)命令。
上述模型中shim進(jìn)程存在的意義是：允許dockerd/containerd升級(jí)或重啟，同時(shí)不影響已運(yùn)行容器。docker提供了 live-restore 的能力，而我們的集群也的確啟用了該配置。
此外，由于我們?cè)趕ystemd的docker配置選項(xiàng)中配置了 MountFlags=slave，參考systemd配置說(shuō)明，systemd在啟動(dòng)dockerd進(jìn)程時(shí)，會(huì)創(chuàng)建一個(gè)新的mnt命名空間。
至此，問(wèn)題已基本定位清楚：
systemd在啟動(dòng)dockerd服務(wù)時(shí)，將dockerd安置在一個(gè)新的mnt命名空間中 用戶創(chuàng)建并啟動(dòng)容器時(shí)，dockerd會(huì)在本mnt命名空間內(nèi)掛載容器讀寫層目錄，并啟動(dòng)shim進(jìn)程托管容器進(jìn)程 由于某種原因，dockerd服務(wù)發(fā)生重啟，systemd會(huì)將其安置在另一個(gè)新的mnt命名空間內(nèi) 用戶刪除容器時(shí)，容器退出時(shí)，dockerd在清理容器讀寫層掛載時(shí)報(bào)錯(cuò)，因?yàn)閽燧d并非在當(dāng)前dockerd的mnt命名空間內(nèi)
后來(lái)，我們?cè)赿ocker issue中也發(fā)現(xiàn)了官方給出的說(shuō)明，MountFlags=slave 與 live-restore 確實(shí)不能同時(shí)使用。
2.5 一波又起
還沒(méi)當(dāng)我們沉浸在解決問(wèn)題的喜悅之中，另一個(gè)疑問(wèn)接踵而來(lái)。我們線上集群好多宿主同時(shí)配置了 MountFlags=slave 和 live-restore=true，為什么問(wèn)題直到最近才報(bào)出來(lái)呢？
當(dāng)我們分析了幾起 Pod Terminating 的涉事宿主后，發(fā)現(xiàn)它們的一個(gè)通性是docker版本為 18.06.3-ce，而我們當(dāng)前主流的版本仍然是 1.13.1。
難道是新版本中才引入的問(wèn)題？我們首先在測(cè)試環(huán)境中對(duì) 1.13.1 版本的docker進(jìn)行了驗(yàn)證，Pod確實(shí)沒(méi)有被阻塞在 Terminating 狀態(tài)，這是不是說(shuō)明低版本docker不存在掛載點(diǎn)泄漏的問(wèn)題呢？
事實(shí)并非如此。當(dāng)我們?cè)俅芜M(jìn)行驗(yàn)證時(shí)，在刪除Pod前記錄了測(cè)試容器的讀寫層，之后發(fā)送刪除Pod指令，Pod順利退出，但此時(shí)，我們登錄Pod之前所在宿主，發(fā)現(xiàn)docker日志中同樣也存在如下日志：
Oct 14 22:12:43 hostname2 dockerd: time="2020-10-14T22:12:43.730726978+08:00" level=debug msg="Failed to unmount fb41efa2cfcbfbb8d90bd1d8d77d299e17518829faf52af40f7a1552ec8aa165 overlay: /home/docker_rt/overlay2/fb41efa2cfcbfbb8d90bd1d8d77d299e17518829faf52af40f7a1552ec8aa165/merged - invalid argument"
同樣存在卸載問(wèn)題的情況下，高低版本的docker卻呈現(xiàn)出了不同的結(jié)果，這顯然是docker的處理邏輯發(fā)生了變更，這里我們對(duì)比源碼能夠很快得出結(jié)論：
// 1.13.1 版本處理邏輯
func (daemon *Daemon) cleanupContainer(container *container.Container, forceRemove, removeVolume bool) (err error) {
// If force removal is required, delete container from various
// indexes even if removal failed.
defer func() {
if err == nil || forceRemove {
daemon.nameIndex.Delete(container.ID)
daemon.linkIndex.delete(container)
selinuxFreeLxcContexts(container.ProcessLabel)
daemon.idIndex.Delete(container.ID)
daemon.containers.Delete(container.ID)
if e := daemon.removeMountPoints(container, removeVolume); e != nil {
logrus.Error(e)
}
daemon.LogContainerEvent(container, "destroy")
}
}()
if err = os.RemoveAll(container.Root); err != nil {
return fmt.Errorf("Unable to remove filesystem for %v: %v", container.ID, err)
}
// When container creation fails and `RWLayer` has not been created yet, we
// do not call `ReleaseRWLayer`
if container.RWLayer != nil {
metadata, err := daemon.layerStore.ReleaseRWLayer(container.RWLayer)
layer.LogReleaseMetadata(metadata)
if err != nil && err != layer.ErrMountDoesNotExist {
return fmt.Errorf("Driver %s failed to remove root filesystem %s: %s", daemon.GraphDriverName(), container.ID, err)
}
}
return nil
}
// 18.06.3-ce 版本處理邏輯
func (daemon *Daemon) cleanupContainer(container *container.Container, forceRemove, removeVolume bool) (err error) {
// When container creation fails and `RWLayer` has not been created yet, we
// do not call `ReleaseRWLayer`
if container.RWLayer != nil {
err := daemon.imageService.ReleaseLayer(container.RWLayer, container.OS)
if err != nil {
err = errors.Wrapf(err, "container %s", container.ID)
container.SetRemovalError(err)
return err
}
container.RWLayer = nil
}
if err := system.EnsureRemoveAll(container.Root); err != nil {
e := errors.Wrapf(err, "unable to remove filesystem for %s", container.ID)
container.SetRemovalError(e)
return e
}
linkNames := daemon.linkIndex.delete(container)
selinuxFreeLxcContexts(container.ProcessLabel)
daemon.idIndex.Delete(container.ID)
daemon.containers.Delete(container.ID)
daemon.containersReplica.Delete(container)
if e := daemon.removeMountPoints(container, removeVolume); e != nil {
logrus.Error(e)
}
for _, name := range linkNames {
daemon.releaseName(name)
}
container.SetRemoved()
stateCtr.del(container.ID)
return nil
}
改動(dòng)一目了然，官方在清理容器變更中給出了詳細(xì)的說(shuō)明。也即在低版本docker中，問(wèn)題并非不存在，僅僅是被隱藏了，并在高版本中被暴露出來(lái)。
3. 問(wèn)題影響
既然所有版本的docker都存在這個(gè)問(wèn)題，那么其影響是什么呢？
在高版本docker中，其影響是顯式的，會(huì)引起容器清理失敗，進(jìn)而造成Pod刪除失敗。
而在低版本docker中，其影響是隱式的，造成掛載點(diǎn)泄漏，進(jìn)而可能會(huì)造成的影響如下：
inode被打滿：由于掛載點(diǎn)泄漏，容器讀寫層不會(huì)被清理，長(zhǎng)時(shí)間累計(jì)可能會(huì)造成inode耗盡問(wèn)題，但是是小概率事件 容器ID復(fù)用：由于掛載點(diǎn)未被卸載，當(dāng)docker復(fù)用了原來(lái)已經(jīng)退出的容器ID時(shí)，在掛載容器init層與讀寫層時(shí)會(huì)失敗。由于docker生成容器ID是隨機(jī)的，因此也是小概率事件
4. 解決方案
問(wèn)題已然明確，如何解決問(wèn)題成了當(dāng)務(wù)之急。思路有二：
治標(biāo)：對(duì)標(biāo) 1.13.1版本的處理邏輯，修改18.06.3-ce處理代碼治本：既然官方也提及 MountFlags=slave與live-restore不能同時(shí)使用，那么我們修改兩個(gè)配置選項(xiàng)之一即可
考慮到 重啟docker不重啟容器 這樣一個(gè)強(qiáng)需求的存在，似乎我們唯一的解決方案就是關(guān)閉 MountFlags=slave 配置。關(guān)閉該配置后，與之而來(lái)的疑問(wèn)如下：
能夠解決本問(wèn)題？ 網(wǎng)傳其他systemd托管服務(wù)啟用PrivateTmp是否會(huì)造成掛載點(diǎn)泄漏？
欲知后事如何，且聽(tīng)下回分解！