Kubernetes中内存资源限制引发的报错

一个 Pod 被创建后, 一直卡在ContainerCreating的状态, 执行describe命令查看该 Pod 详细信息后发现如下 Event

1
2
3
4
5
6
7
Events:
Type Reason Age From Message
---- ------ ---- ---- -------
Normal Scheduled 2m default-scheduler Successfully assigned 61f983b5-19ca-4b33-8647-6b279ae93812 to k8node3
Normal SuccessfulMountVolume 2m kubelet, k8node3 MountVolume.SetUp succeeded for volume "default-token-7r9jt"
Warning FailedCreatePodSandBox 2m (x12 over 2m) kubelet, k8node3 Failed create pod sandbox: rpc error: code = Unknown desc = failed to start sandbox container for pod "61f983b5-19ca-4b33-8647-6b279ae93812": Error response from daemon: oci runtime error: container_linux.go:247: starting container process caused "process_linux.go:286: decoding sync type from init pipe caused \"read parent: connection reset by peer\""
Normal SandboxChanged 2m (x12 over 2m) kubelet, k8node3 Pod sandbox changed, it will be killed and re-created.

以上 Event 信息中, 能解读到的信息极其有限

  • Failed create pod sandbox: Google 提供的 pause 容器启动失败
  • oci runtime error: 运行时接口出的问题, 我的环境中运行时环境为 docker
  • connection reset by peer: 连接被重置
  • Pod sandbox changed, it will be killed and re-created: pause 容器引导的 Pod 环境被改变, 重新创建 Pod 中的 pause 引导

看完上面的报错信息并不能准确定位到问题的根源, 只能大致了解到是因为创建SandBox失败导致的, 接下来查看 kubelet 的日志

1
2
3
4
5
6
7
8
9
10
Oct 31 16:33:57 k8node3 kubelet[1865]: E1031 16:33:57.551282    1865 remote_runtime.go:92] RunPodSandbox from runtime service failed: rpc error: code = Unknown desc = failed to start sandbox container for pod "61f983b5-19ca-4b33-8647-6b279ae93812": Error response from daemon: oci runtime error: container_linux.go:247: starting container process caused "process_linux.go:286: decoding sync type from init pipe caused \"read parent: connection reset by peer\""
Oct 31 16:33:57 k8node3 kubelet[1865]: E1031 16:33:57.551415 1865 kuberuntime_sandbox.go:54] CreatePodSandbox for pod "61f983b5-19ca-4b33-8647-6b279ae93812_default(77b2b948-dce4-11e8-afec-b82a72cf3061)" failed: rpc error: code = Unknown desc = failed to start sandbox container for pod "61f983b5-19ca-4b33-8647-6b279ae93812": Error response from daemon: oci runtime error: container_linux.go:247: starting container process caused "process_linux.go:286: decoding sync type from init pipe caused \"read parent: connection reset by peer\""
Oct 31 16:33:57 k8node3 kubelet[1865]: E1031 16:33:57.551459 1865 kuberuntime_manager.go:646] createPodSandbox for pod "61f983b5-19ca-4b33-8647-6b279ae93812_default(77b2b948-dce4-11e8-afec-b82a72cf3061)" failed: rpc error: code = Unknown desc = failed to start sandbox container for pod "61f983b5-19ca-4b33-8647-6b279ae93812": Error response from daemon: oci runtime error: container_linux.go:247: starting container process caused "process_linux.go:286: decoding sync type from init pipe caused \"read parent: connection reset by peer\""
Oct 31 16:33:57 k8node3 kubelet[1865]: E1031 16:33:57.551581 1865 pod_workers.go:186] Error syncing pod 77b2b948-dce4-11e8-afec-b82a72cf3061 ("61f983b5-19ca-4b33-8647-6b279ae93812_default(77b2b948-dce4-11e8-afec-b82a72cf3061)"), skipping: failed to "CreatePodSandbox" for "61f983b5-19ca-4b33-8647-6b279ae93812_default(77b2b948-dce4-11e8-afec-b82a72cf3061)" with CreatePodSandboxError: "CreatePodSandbox for pod \"61f983b5-19ca-4b33-8647-6b279ae93812_default(77b2b948-dce4-11e8-afec-b82a72cf3061)\" failed: rpc error: code = Unknown desc = failed to start sandbox container for pod \"61f983b5-19ca-4b33-8647-6b279ae93812\": Error response from daemon: oci runtime error: container_linux.go:247: starting container process caused \"process_linux.go:286: decoding sync type from init pipe caused \\\"read parent: connection reset by peer\\\"\""
Oct 31 16:33:58 k8node3 kubelet[1865]: E1031 16:33:58.718255 1865 remote_runtime.go:92] RunPodSandbox from runtime service failed: rpc error: code = Unknown desc = failed to start sandbox container for pod "61f983b5-19ca-4b33-8647-6b279ae93812": Error response from daemon: oci runtime error: container_linux.go:247: starting container process caused "process_linux.go:286: decoding sync type from init pipe caused \"read parent: connection reset by peer\""
Oct 31 16:33:58 k8node3 kubelet[1865]: E1031 16:33:58.718406 1865 kuberuntime_sandbox.go:54] CreatePodSandbox for pod "61f983b5-19ca-4b33-8647-6b279ae93812_default(77b2b948-dce4-11e8-afec-b82a72cf3061)" failed: rpc error: code = Unknown desc = failed to start sandbox container for pod "61f983b5-19ca-4b33-8647-6b279ae93812": Error response from daemon: oci runtime error: container_linux.go:247: starting container process caused "process_linux.go:286: decoding sync type from init pipe caused \"read parent: connection reset by peer\""
Oct 31 16:33:58 k8node3 kubelet[1865]: E1031 16:33:58.718443 1865 kuberuntime_manager.go:646] createPodSandbox for pod "61f983b5-19ca-4b33-8647-6b279ae93812_default(77b2b948-dce4-11e8-afec-b82a72cf3061)" failed: rpc error: code = Unknown desc = failed to start sandbox container for pod "61f983b5-19ca-4b33-8647-6b279ae93812": Error response from daemon: oci runtime error: container_linux.go:247: starting container process caused "process_linux.go:286: decoding sync type from init pipe caused \"read parent: connection reset by peer\""
Oct 31 16:33:58 k8node3 kubelet[1865]: E1031 16:33:58.718597 1865 pod_workers.go:186] Error syncing pod 77b2b948-dce4-11e8-afec-b82a72cf3061 ("61f983b5-19ca-4b33-8647-6b279ae93812_default(77b2b948-dce4-11e8-afec-b82a72cf3061)"), skipping: failed to "CreatePodSandbox" for "61f983b5-19ca-4b33-8647-6b279ae93812_default(77b2b948-dce4-11e8-afec-b82a72cf3061)" with CreatePodSandboxError: "CreatePodSandbox for pod \"61f983b5-19ca-4b33-8647-6b279ae93812_default(77b2b948-dce4-11e8-afec-b82a72cf3061)\" failed: rpc error: code = Unknown desc = failed to start sandbox container for pod \"61f983b5-19ca-4b33-8647-6b279ae93812\": Error response from daemon: oci runtime error: container_linux.go:247: starting container process caused \"process_linux.go:286: decoding sync type from init pipe caused \\\"read parent: connection reset by peer\\\"\""
Oct 31 16:36:02 k8node3 kubelet[1865]: E1031 16:36:02.114171 1865 kubelet.go:1644] Unable to mount volumes for pod "61f983b5-19ca-4b33-8647-6b279ae93812_default(77b2b948-dce4-11e8-afec-b82a72cf3061)": timeout expired waiting for volumes to attach or mount for pod "default"/"61f983b5-19ca-4b33-8647-6b279ae93812". list of unmounted volumes=[default-token-7r9jt]. list of unattached volumes=[default-token-7r9jt]; skipping pod
Oct 31 16:36:02 k8node3 kubelet[1865]: E1031 16:36:02.114262 1865 pod_workers.go:186] Error syncing pod 77b2b948-dce4-11e8-afec-b82a72cf3061 ("61f983b5-19ca-4b33-8647-6b279ae93812_default(77b2b948-dce4-11e8-afec-b82a72cf3061)"), skipping: timeout expired waiting for volumes to attach or mount for pod "default"/"61f983b5-19ca-4b33-8647-6b279ae93812". list of unmounted volumes=[default-token-7r9jt]. list of unattached volumes=[default-token-7r9jt]

kubelet 的日志中, 与 describe 出来的信息差不多, tail 的时候更直观的感觉到频繁的Sandbox创建的过程, 既然是 OCI 运行时报错, 只能去 docker 的日志中找找看了

1
2
3
4
5
6
7
8
9
10
Oct 31 16:33:58 k8node3 dockerd[1715]: time="2018-10-31T16:33:58.671146675+08:00" level=error msg="containerd: start container" error="oci runtime error: container_linux.go:247: starting container process caused \"process_linux.go:286: decoding sync type from init pipe caused \\\"read parent: connection reset by peer\\\"\"\n" id=029d9e843eedb822370c285b5abf1f37556461083d3bda2c7af38b3b00695b0f
Oct 31 16:33:58 k8node3 dockerd[1715]: time="2018-10-31T16:33:58.671871096+08:00" level=error msg="Create container failed with error: oci runtime error: container_linux.go:247: starting container process caused \"process_linux.go:286: decoding sync type from init pipe caused \\\"read parent: connection reset by peer\\\"\"\n"
Oct 31 16:33:58 k8node3 dockerd[1715]: time="2018-10-31T16:33:58.717553371+08:00" level=error msg="Handler for POST /v1.27/containers/029d9e843eedb822370c285b5abf1f37556461083d3bda2c7af38b3b00695b0f/start returned error: oci runtime error: container_linux.go:247: starting container process caused \"process_linux.go:286: decoding sync type from init pipe caused \\\"read parent: connection reset by peer\\\"\"\n"
Oct 31 16:34:22 k8node3 dockerd[1715]: time="2018-10-31T16:34:22.759631102+08:00" level=error msg="Handler for POST /v1.27/containers/207f0ffb4b5ecc5f8261af40cd7a2c4c2800a2c30b027c4fb95648f8c1b00274/stop returned error: Container 207f0ffb4b5ecc5f8261af40cd7a2c4c2800a2c30b027c4fb95648f8c1b00274 is already stopped"
Oct 31 16:34:22 k8node3 dockerd[1715]: time="2018-10-31T16:34:22.768603351+08:00" level=error msg="Handler for POST /v1.27/containers/03bf9bfcf4e3f66655b0124d6779ff649b2b00219b83645ca18b4bb08d1cc573/stop returned error: Container 03bf9bfcf4e3f66655b0124d6779ff649b2b00219b83645ca18b4bb08d1cc573 is already stopped"
Oct 31 16:34:22 k8node3 dockerd[1715]: time="2018-10-31T16:34:22.777073508+08:00" level=error msg="Handler for POST /v1.27/containers/7b37f5aee7afe01f209bcdc6b3568b522fb0bbda5cb4b322e10b05ec603f5728/stop returned error: Container 7b37f5aee7afe01f209bcdc6b3568b522fb0bbda5cb4b322e10b05ec603f5728 is already stopped"
Oct 31 16:34:22 k8node3 dockerd[1715]: time="2018-10-31T16:34:22.785774443+08:00" level=error msg="Handler for POST /v1.27/containers/1a01419973e4701b231556d74c619c30e0966889948e810b46567f08475ec431/stop returned error: Container 1a01419973e4701b231556d74c619c30e0966889948e810b46567f08475ec431 is already stopped"
Oct 31 16:34:22 k8node3 dockerd[1715]: time="2018-10-31T16:34:22.794198279+08:00" level=error msg="Handler for POST /v1.27/containers/c3c4049e7b1942395b3cc3a45cf0cc69b34bab6271cb940a70c7d9aed3ba6176/stop returned error: Container c3c4049e7b1942395b3cc3a45cf0cc69b34bab6271cb940a70c7d9aed3ba6176 is already stopped"
Oct 31 16:34:22 k8node3 dockerd[1715]: time="2018-10-31T16:34:22.802698120+08:00" level=error msg="Handler for POST /v1.27/containers/8d2c8a4cd5b43b071a9976251932955937d5b1f0f34dca1482cde4195df4747d/stop returned error: Container 8d2c8a4cd5b43b071a9976251932955937d5b1f0f34dca1482cde4195df4747d is already stopped"
Oct 31 16:34:22 k8node3 dockerd[1715]: time="2018-10-31T16:34:22.811103238+08:00" level=error msg="Handler for POST /v1.27/containers/7fdb697e251cec249c0a17f1fdcc6d76fbec13a60929eb0217c744c181702c1f/stop returned error: Container 7fdb697e251cec249c0a17f1fdcc6d76fbec13a60929eb0217c744c181702c1f is already stopped"

Docker 的日志中, 除了已经看了很多遍的connection reset by peer之外, 还有一些新的发现

  • xxx is already stopped: 看日志, 感觉是向容器接口发送了 POST 请求以 stop 容器, 但是该容器已经被 stop 掉了

Docker 的日志和 kubelet 的日志的共同点就是, kubelet 频繁 recreate Sandbox

执行 docker container ls -a 命令发现存在大量 create 状态的 pause 容器

查看 demesg -T 信息, 发现了大量 oom-killer 的字眼的日志, 初步判断是由于内存溢出, 导致系统主动 kill 进程.

发生这样的情况的概率并不高, 一般情况下有两种类型的 oom kill

  • 由于 pod 内进程超出了 pod 指定 Limit 限制的值, 将导致 oom kill, 此时 pod 退出的 Reason 会显示 OOMKilled
  • 另一种情况是 pod 内的进程给自己设置了可用内存, 比如 jvm 内存限制设置为2G, pod Limit 设置为6G, 此时由于程序的原因导致内存使用超过2G 时, 也会引发 oom kill

这两种内存溢出的 kill 区别是第一种原因直接显示在 pod 的 Event 里; 第二种你在 Event 里找不到, 在宿主机的 dmesg 里面可以找到 invoked oom-killer 的日志

这次的情况看起来像属于第二种情况, 于是赶紧再次 describe pod, 查看 Limit 限制

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
Containers:
61f983b5-19ca-4b33-8647-6b279ae93812:
Container ID:
Image: reg.lvrui.io/public/testpublish:latest
Image ID:
Port: <none>
Host Port: <none>
State: Waiting
Reason: ContainerCreating
Ready: False
Restart Count: 0
Limits:
cpu: 1
memory: 2k
Requests:
cpu: 1
memory: 2k
Environment:
key: value
Mounts:
/var/run/secrets/kubernetes.io/serviceaccount from default-token-7r9jt (ro)

终于找到了原因, 就是因为对内存的 Limit 导致的. 这里显示内存 Limit 为2k, 实际上是因为在创建资源时, 写的是 2000(不加单位时, 默认单位为 bytes), k8s 自动转成了以小写 k 的单位表示方式, 所以就变成了2k

理论上来说, 按照之前的经验, 此种情况(实际使用内存超过 Limit 内存的情况)应该属于第一种, 会在 Event 里显示的由于 OOMkilled 原因导致 Terminated 状态. 但实际情况却是在 Event 里找不到 oom kill 的日志, 且 pod 状态处于 ContainerCreating 状态.

  • 由于 OOMkilled 处于 Terminated 的状态是因为 pod 已经正常被引导创建后, 导致的内存溢出
  • 由于系统 invoked oom-killer 导致的处于 ContainerCreating 状态的 pod 是因为 pod 还没正常被创建, pod 中的 pause 容器都没有被正常引导就已经被 cgroup 的内存限制而招来杀身之祸