专栏首页腾讯云原生团队【Pod Terminating原因追踪系列之三】让docker事件处理罢工的cancel状态码

【Pod Terminating原因追踪系列之三】让docker事件处理罢工的cancel状态码

岳家瑞,腾讯云后台开发工程师,日常负责K8s生态和运行时相关工作,包括K8s插件开发和运行时问题排查。

本篇为Pod Terminating原因追踪系列的第三篇,前两篇【Pod Terminating原因追踪系列】之 containerd 中被漏掉的 runc 错误信息【Pod Terminating原因追踪系列之二】exec连接未关闭导致的事件阻塞,分别介绍了两种可能导致Pod Terminating的原因。在处理现网问题时,Pod Terminating属于比较常见的问题,而本系列的初衷便是记录导致Pod Terminating问题的原因,希望能够帮助大家在遇到此类问题时,开拓排查思路。

本篇将再介绍一种造成Pod Terminating的原因,即处理事件流的方法异常退出导致的Pod Terminating,当docker版本在19以下且containerd进程由于各种原因(比如OOM)频繁重启时,会有概率导致此问题产生对于本文中提到的问题,在docker19中已经得到解决,但由于docker18无法直接升级到docker19,且dockerd19修复的改动较大,难以cherry-pick到docker18,因此本文在结尾参考docker19的实现给出了一种简单的解决方案。

Pod Terminating

前一阵有客户反馈使用docker18版本的节点上Pod一直处在Terminating状态,客户通过查看kubelet日志怀疑是Volume卸载失败导致的。现象如下图:

Jul 31 09:53:52 VM_90_48_centos kubelet: E0731 09:53:52.860699     702 plugin_watcher.go:120] error could not find plugin for deleted file /var/lib/kubelet/plugins/kubernetes.io/qcloud-cbs/mounts/disk-o3yxvywa/WTEST.TMP when handling delete event: "/var/lib/kubelet/plugins/kubernetes.io/qcloud-cbs/mounts/disk-o3yxvywa/WTEST.TMP": REMOVEJul 31 09:53:52 VM_90_48_centos kubelet: E0731 09:53:52.860717     702 plugin_watcher.go:115] error stat file /var/lib/kubelet/plugins/kubernetes.io/qcloud-cbs/mounts/disk-o3yxvywa/WTEST.TMP failed: stat /var/lib/kubelet/plugins/kubernetes.io/qcloud-cbs/mounts/disk-o3yxvywa/WTEST.TMP: no such file or directory when handling create event: "/var/lib/kubelet/plugins/kubernetes.io/qcloud-cbs/mounts/disk-o3yxvywa/WTEST.TMP": CREATE

通过查看客户Pod的部署情况,发现客户同时使用了in-tree和out-tree的方式挂载cbs,kubelet中的报错是因为在in-tree中检测到了来自out-tree的旁路信息而报错,本质上并不会造成Pod Terminating不掉的问题,看来造成Pod Terminating的原因并非这么简单。

分析日志及源码

在排除了cbs卸载的问题后,我们首先想到会不会还是dockerd和containerd状态不一致的问题呢?通过下面两个指令查看了一下容器和task的状态,发现容器的状态是up而task的状态为STOPPED,果然又是状态不一致导致的问题。按照前两篇的经验来看应该是来自containerd的事件在dockerd中没有得到处理或处理的过程阻塞了。

#查看容器状态,看到容器状态为updocker ps | grep <container-id>#查看task状态,显示task的状态为STOPPEDdocker-container-ctr --namespace moby --address var/run/docker/containerd/docker-containerd.sock task ls | grep <container-id>

这里提供一种简单验证方法来验证是否为task事件没有得到处理造成的Pod Terminating,随便起一个容器(例如CentOS),并通过exec进入容器并退出,这时去查看docker的堆栈(发送SIGUSR1信号给dockerd),如果发现如下有一条堆栈信息:

goroutine 10717529 [select, 16 minutes]:github.com/docker/docker/daemon.(*Daemon).ContainerExecStart(0xc4202b2000, 0x25df8e0, 0xc42010e040, 0xc4347904f1, 0x40, 0x7f7ea8250648, 0xc43240a5c0, 0x7f7ea82505e0, 0xc43240a5c0, 0x0, ...)    /go/src/github.com/docker/docker/daemon/exec.go:264 +0xcb6github.com/docker/docker/api/server/router/container.(*containerRouter).postContainerExecStart(0xc421069b00, 0x25df960, 0xc464e089f0, 0x25dde20, 0xc446f3a1c0, 0xc42b704000, 0xc464e08960, 0x0, 0x0)    /go/src/github.com/docker/docker/api/server/router/container/exec.go:125 +0x34b

之后可以使用《【Pod Terminating原因追踪系列之二】exec连接未关闭导致的事件阻塞》中介绍的方法,确认一下该条堆栈信息是否是刚刚创建的CentOS容器产生的,当然从堆栈的时间上来看很容易看出来,也可以通过gdb判断ContainerExecStart参数(第二个参数的地址)中的execID是否和CentOS容器的execID相等的方式来确认,通过返回结果发现exexID相等,说明虽然我们的exec退出了,但是dockerd却没有正确处理来自containerd的exit事件。

在有了之前的排查经验后,我们很快猜到会不会是处理事件流的方法processEventStream在处理exit事件的时候发生了阻塞?验证方法很简单,只需要查看堆栈有没有goroutine卡在StreamConfig.Wait()即可,通过搜索processEventStream堆栈信息发现并没有goroutine卡在Wait方法上,甚至连processEventStream这个处理事件流的方法在堆栈都中也没有找到,说明事件处理的方法已经return了!自然也就无法处理来自containerd的所有事件了。

那么造成processEventStream方法return的具体原因是什么呢?通过查看源码发现,processEventStream中只有在一种情况下会return,即当gRPC连接返回的错误能够被解析(ok为true)且返回cancel状态码的时候proceEventStream会return,否则会另起协程递归调用proceEventStream:

case err = <-errC:    if err != nil {        errStatus, ok := status.FromError(err)        if !ok || errStatus.Code() != codes.Canceled {            c.logger.WithError(err).Error("failed to get event")            go c.processEventStream(ctx)        } else {            c.logger.WithError(ctx.Err()).Info("stopping event stream following graceful shutdown")        }    }    return

那么为什么gRPC连接会返回cancel状态码呢?

在查看客户docker日志时发现containerd在之前不断的被kill并重启,持续了大概11分钟左右:

#日志省略了部分内容Jul 29 19:23:09 VM_90_48_centos dockerd[11182]: time="2020-07-29T19:23:09.037480352+08:00" level=error msg="containerd did not exit successfully" error="signal: killed" module=libcontainerdJul 29 19:24:06 VM_90_48_centos dockerd[11182]: time="2020-07-29T19:24:06.972243079+08:00" level=info msg="starting containerd" revision=e6b3f5632f50dbc4e9cb6288d911bf4f5e95b18e version=v1.2.4Jul 29 19:24:52 VM_90_48_centos dockerd[11182]: time="2020-07-29T19:24:52.643738767+08:00" level=error msg="containerd did not exit successfully" error="signal: killed" module=libcontainerdJul 29 19:25:02 VM_90_48_centos dockerd[11182]: time="2020-07-29T19:25:02.116798771+08:00" level=info msg="starting containerd" revision=e6b3f5632f50dbc4e9cb6288d911bf4f5e95b18e version=v1.2.4

查看系统日志文件(/var/log/messages)看下为什么containerd会被不断地重启:

#日志省略了部分内容Jul 29 19:23:09 VM_90_48_centos kernel: Memory cgroup out of memory: Kill process 15069 (docker-containe) score 0 or sacrifice childJul 29 19:23:09 VM_90_48_centos kernel: Killed process 15069 (docker-containe) total-vm:51688kB, anon-rss:10068kB, file-rss:324kBJul 29 19:24:52 VM_90_48_centos kernel: Memory cgroup out of memory: Kill process 12411 (docker-containe) score 0 or sacrifice childJul 29 19:24:52 VM_90_48_centos kernel: Killed process 5836 (docker-containe) total-vm:1971688kB, anon-rss:22376kB, file-rss:0kB

可以发现containerd被kill是由于OOM导致的,那么会不会是因为containerd的不断重启导致gRPC返回cancel的状态码呢。先查看一下重启containerd这部分的逻辑:

在启动dockerd时,会创建一个独立的到containerd的gRPC连接,并启动一个monitor协程基于该gRPC连接对containerd的服务做健康检查,monitor每隔500ms会对到containerd的grpc连接做健康检查并记录失败的次数,如果发现gRPC连接返回状态码为UNKNOWN或者NOT_SERVING时对失败次数加1,当失败次数大于域值(域值为3)并且containerd进程已经down掉(通过向进程发送信号进行判断),则会重启containerd进程,并执行reconnect重置dockerd和containerd之间的gRPC连接,在reconnect的逻辑中,会先close旧的gRPC连接,之后新建一条新的gRPC连接:

// containerd/containerd/client.gofunc (c *Client) Reconnect() error {    ....    // close掉旧的连接    c.conn.Close()    // 建立新的连接    conn, err := c.connector()    ....    c.conn = conn    return nil}connector := func() (*grpc.ClientConn, error) {    ctx, cancel := context.WithTimeout(context.Background(), 60*time.Second)    defer cancel()    conn, err := grpc.DialContext(ctx, dialer.DialAddress(address), gopts...)    if err != nil {        return nil, errors.Wrapf(err, "failed to dial %q", address)    }    return conn, nil}

由于reconnect会先close旧连接,那么会不会是close造成的gRPC返回cancel呢?可以写一个简单的demo验证一下,服务端和客户端之间通过unix socket连接,客户端订阅服务端的消息,服务端不断地publish消息给客户端,客户端每隔一段时间close一次gRPC连接,得到的结果如下:

从结果中发现在unix socket下客户端close连接是有概率导致grpc返回cancel状态码的,那么具体什么情况下会产生cancel状态码呢?通过查看gRPC源码发现,当服务端在发送事件过程中,客户端close了连接则会使服务端返回cancel状态码,若此时服务端没有发送事件,则会返回图中的transport is closing错误。

至此,问题已经基本定位了,很有可能是客户端close了gRPC连接导致服务端返回了cancel状态码,使processEventStream方法return,导致来自containerd的事件流无法得到处理,最终导致dockerd和containerd的状态不一致。但由于客户的日志级别较高,我们没法从中获得问题产生时的具体时序,因此希望通过调低日志级别复现问题来定位具体在什么情况下会产生这个问题。

问题复现

这个问题复现起来比较简单,只需要模仿客户产生问题时的情况,不断重启containerd进程即可。在docker18.06.3-ce版本集群下创建一个Pod,我们通过下面的脚本不断kill containerd进程:

#!/bin/bash  for i in $(seq 1 1000)doprocess=`ps -elf | grep  "docker-containerd --config /var/run/docker/containerd/containerd.toml"| grep -v "grep"|awk '{print $4}'`if [ ! -n "$process" ]; then  echo "containerd not running"  else  echo $process;  kill -9 $process;fisleep 1;done

运行上面的脚本便有几率复现该问题,之后删除Pod并查看Pod状态,发现Pod会一直卡在Terminating状态。

查看容器状态和task状态,发现和客户问题的现象完全一致:

由于我们调低了日志级别,查看日志发现下面这样一条日志,而这条日志只有processEventStream方法return时才会打印,且打印日志后processEventStream方法立即return,因此可以确定问题的根本原因就是processEventStream收到了gRPC返回的cancel状态码导致方法return,之后的来自containerd的事件无法得到处理,最终出现dockerd和containerd状态不一致的问题。

Aug 13 15:23:16 VM_1_6_centos dockerd[25650]: time="2020-08-13T15:23:16.686289836+08:00" level=info msg="stopping event stream following graceful shutdown" error="<nil>" module=libcontainerd namespace=moby

问题定位

通过分析docker日志,可以了解到docker18具体在什么情况下会产生processEventStream return的问题,下图是会导致processEventStream return的时序图:

通过该时序图能够看出问题所在,首先当containerd进程被kill后,monitor通过健康检查,发现containerd进程已经停止,便会通过cmd重新启动containerd进程,并重新连接到contaienrd,如果processEventStream在reconnect之前使用旧的gRPC连接成功,订阅到containerd的事件,那么在reconnect时会close这条旧连接,而如果恰好在这时containerd在传输事件,那么该gRPC连接就会返回一个cancel的状态码给processEventStream方法,导致processEventStream方法return。

修复与反思

此问题产生的根本原因在于reconnect的逻辑,在重启时无法保证reconnect一定在processEventStream的subscribe之前发生。由于processEventStream会递归调用自动重连,因此实际上并不需要reconnect,在docker19中也已经修复了这个问题,且没有reconnect,但是docker19这部分改动较大,无法cherry-pick到docker18,因此我们可以参考docker19的实现修改docker18代码,只需要将reconnect的逻辑去除即可。

另外在修复时顺便修复了processEventStream方法不断递归导致瞬间产生大量日志的问题,由于subscribe失败以后会不断地启动协程递归调用,因此会在瞬间产生大量日志,在社区也有人已经提交过PR解决这个问题。(https://github.com/moby/moby/pull/39513

解决办法也很简单,在每次递归调用之前sleep 1秒即可,该改动也已经合进了docker19的代码中。

在后续我们将推出产品化运行时版本升级修复本篇中提到的bug,用户可以在控制台看到升级提醒并方便的进行一键升级。

希望本篇文章对您有帮助,谢谢观看!

扫描二维码,添加小助手(微信号:TKEplatform) ,拉你入技术交流群,和更多小伙伴一起交流云原生!

文章分享自微信公众号:
腾讯云原生

本文参与 腾讯云自媒体分享计划 ,欢迎热爱写作的你一起参与!

如有侵权,请联系 cloudcommunity@tencent.com 删除。
登录 后参与评论
0 条评论

相关文章

  • 开工必备!50+篇超实用云原生技术干货合集

    kai 开 gong 工 da 大 ji 吉 新年新气象,更要1G棒 2020年没写完的代码,现在还有思路吗? 2021年开始使用云原生技术了吗? 一开工就遇...

    腾讯云原生
  • 转发有礼 | 50篇+云原生系列干货文章汇总,请查收!

    云原生技术干货文章合集,来咯~ 2020 年,要说咱们技术圈子里什么最火? 云原生肯定是那 NO.1 截止目前,我们不难看出,K8s 容器、服务网格、...

    腾讯云原生
  • 【Pod Terminating原因追踪系列之二】exec连接未关闭导致的事件阻塞

    岳家瑞,腾讯云后台开发工程师,日常负责K8s生态和运行时相关工作,包括K8s插件开发和运行时问题排查。

    腾讯云原生
  • 中秋福利 | 15个系列100+篇超实用云原生原创干货合集(内含腾讯彩蛋)

    还有2天,就要迎来中秋小长假啦 这个中秋节你打算怎么过? 小云选择把这篇干货全部拿下! 云原生技术干货文章合集,来咯~ 2021 年,要说咱们技术圈子里什...

    腾讯云原生
  • Kubernetes 实践:勿让 Docker Volume 引发 Terminating Pod

    问卷链接(https://www.wjx.cn/jq/97146486.aspx)

    CNCF
  • 聊聊 Kubernetes Pod or Namespace 卡在 Terminating 状态的场景

    一句话,本质是API Server虽然标记了对象的删除,但是作为实际清理的控制器kubelet, 并不能关停Pod或相关资源, 因而没能通知API Server...

    冬夜先生
  • Node工作负载异常,一部分pod状态为Terminating

    在节点处于“NotReady”状态时,deployment控制器会迁移节点上的容器实例,并将节点上运行的pod置为“Terminating”状态。待节点恢复后,...

    没有故事的陈师傅
  • 人生苦短,我用k8s--------------k8s实战排障思路

    K8S是一个开源的,用于管理云平台中多个主机上的容器化应用,Kubernetes的目标是让部署容器化变得简单并且高效

    不吃小白菜
  • Kubernetes之Pod生命周期

    简括:首先kubectl向 API 接口发送指令,随后kube-api 会调度到我们的kubelet,这个调度过程是由我们的etcd完成的存储,随后kubele...

    用户4877748
  • Kubernetes Pod 故障归类与排查方法

    Docker 是 Kubernetes Pod 中最常用的容器运行时,但 Pod 也能支持其他的容器运行,比如 rkt、podman等。

    YP小站
  • Pod 一直停留在 Terminating 状态,我等得花儿都谢了~

    近期,弹性云线上集群发生了几起特殊的容器漂移失败事件,其特殊之处在于容器处于 Pod Terminating 状态,而宿主则处于 Ready 状态。

    米开朗基杨
  • 在大规模 Kubernetes 集群上实现高 SLO 的方法

    导读:随着 Kubernetes 集群规模和复杂性的增加,集群越来越难以保证高效率、低延迟的交付 pod。本文将分享蚂蚁金服在设计 SLO 架构和实现高 SLO...

    CNCF
  • 腾讯云CIS入门——Kubernetes部署

    容器实例服务(Container Instance Service , CIS)可以帮您在云上快捷、灵活的部署容器,让您专注于构建程序和使用容器而非管理设备上。...

    林岑影
  • 重新加载故障节点上的 Ceph 卷

    在 Kubernetes 节点发生故障时,在 40 秒内(由 Controller Manager 的 --node-monitor-grace-period ...

    崔秀龙
  • 5.深入k8s:StatefulSet控制器及源码分析

    在上一篇中,讲解了容器持久化存储,从中我们知道什么是PV和PVC,这一篇我们讲通过StatefulSet来使用它们。

    luozhiyun
  • 06 . Kubernetes之Pod控制器详细介绍及应用

    除了deployment是v1的升级版,其他的基本都是v1。 # kubectl api-versions

    常见_youmen
  • kubernetes系列教程(三)kubernetes快速入门

    kubernetes中涉及很多概念,包含云生态社区中各类技术,学习成本比较高,k8s中通常以编写yaml文件完成资源的部署,对于较多入门的人来说是个较高的门坎,...

    HappyLau谈云计算
  • k8s——针对有状态服务实现数据持久化

    对服务器程序来说,究竟是有状态服务,还是无状态服务,其判断依旧是指两个来自相同发起者的请求在服务器端是否具备上下文关系。如果是状态化请求,那么服务器端一般都要保...

    小手冰凉
  • Awesome Kubernetes 系列:第一期

    Kuberhealthy 是对 Prometheus 的一种补充监控方案,通过 Operator 来控制状态,你可以对 Kubernetes 的资源进行聚合监控...

    米开朗基杨

扫码关注云+社区

领取腾讯云代金券