CreateContainerError running lstat on namespace path

[steven-sheehy]

Description
I have a MongoDB StatefulSet running fine for awhile, then for unknown reasons the pod restarts. When it attempts to start back up, this error starts occurring. This occurs only rarely as most times it starts up fine. After restarting the crio.service, the error goes away and the container creates successfully.

Steps to reproduce the issue:
Not sure

Describe the results you received:
Pod is never re-created and shows an error like CreateContainerError in kubectl get pods. The restarts are not increasing, it's just that error permanently.

$ sudo journalctl -fu crio.service
Nov 22 21:50:06 fsprdce1c04 crio[77667]: time="2018-11-22 21:50:06.734886735Z" level=error msg="Container creation error: container_linux.go:330: creating new parent process caused "container_linux.go:1759: running lstat on namespace path \"/proc/134447/ns/ipc\" caused \"lstat /proc/134447/ns/ipc: no such file or directory\""
Nov 22 21:50:06 fsprdce1c04 crio[77667]: "
Nov 22 21:50:22 fsprdce1c04 crio[77667]: time="2018-11-22 21:50:22.738732429Z" level=error msg="Container creation error: container_linux.go:330: creating new parent process caused "container_linux.go:1759: running lstat on namespace path \"/proc/134447/ns/ipc\" caused \"lstat /proc/134447/ns/ipc: no such file or directory\""
Nov 22 21:50:22 fsprdce1c04 crio[77667]: "
Nov 22 21:50:33 fsprdce1c04 crio[77667]: time="2018-11-22 21:50:33.735476632Z" level=error msg="Container creation error: container_linux.go:330: creating new parent process caused "container_linux.go:1759: running lstat on namespace path \"/proc/134447/ns/ipc\" caused \"lstat /proc/134447/ns/ipc: no such file or directory\""
Nov 22 21:50:33 fsprdce1c04 crio[77667]: "
Nov 22 21:50:46 fsprdce1c04 crio[77667]: time="2018-11-22 21:50:46.734345766Z" level=error msg="Container creation error: container_linux.go:330: creating new parent process caused "container_linux.go:1759: running lstat on namespace path \"/proc/134447/ns/ipc\" caused \"lstat /proc/134447/ns/ipc: no such file or directory\""
Nov 22 21:50:46 fsprdce1c04 crio[77667]: "
Nov 22 21:51:00 fsprdce1c04 crio[77667]: time="2018-11-22 21:51:00.733602480Z" level=error msg="Container creation error: container_linux.go:330: creating new parent process caused "container_linux.go:1759: running lstat on namespace path \"/proc/134447/ns/ipc\" caused \"lstat /proc/134447/ns/ipc: no such file or directory\""
Nov 22 21:51:00 fsprdce1c04 crio[77667]: "
Nov 22 21:51:16 fsprdce1c04 crio[77667]: time="2018-11-22 21:51:16.735359304Z" level=error msg="Container creation error: container_linux.go:330: creating new parent process caused "container_linux.go:1759: running lstat on namespace path \"/proc/134447/ns/ipc\" caused \"lstat /proc/134447/ns/ipc: no such file or directory\""
Nov 22 21:51:16 fsprdce1c04 crio[77667]: "

$ sudo journalctl -fu kubelet.service
Nov 22 21:52:26 fsprdce1c04 kubelet[77800]: I1122 21:52:26.572204   77800 kuberuntime_manager.go:513] Container {Name:mongodb Image:mongo:3.2 Command:[mongod] Args:[--config=/data/configdb/mongod.conf --dbpath=/data/db --replSet=rs0 --port=27017 --bind_ip=0.0.0.0 --auth --keyFile=/data/configdb/key.txt] WorkingDir: Ports:[{Name:mongodb HostPort:0 ContainerPort:27017 Protocol:TCP HostIP:}] EnvFrom:[] Env:[] Resources:{Limits:map[memory:{i:{value:2684354560 scale:0} d:{Dec:<nil>} s: Format:BinarySI} cpu:{i:{value:1500 scale:-3} d:{Dec:<nil>} s:1500m Format:DecimalSI}] Requests:map[cpu:{i:{value:1500 scale:-3} d:{Dec:<nil>} s:1500m Format:DecimalSI} memory:{i:{value:2684354560 scale:0} d:{Dec:<nil>} s: Format:BinarySI}]} VolumeMounts:[{Name:datadir ReadOnly:false MountPath:/data/db SubPath: MountPropagation:<nil>} {Name:configdir ReadOnly:false MountPath:/data/configdb SubPath: MountPropagation:<nil>} {Name:workdir ReadOnly:false MountPath:/work-dir SubPath: MountPropagation:<nil>} {Name:default-token-dxzpm ReadOnly:true MountPath:/var/run/secrets/kubernetes.io/serviceaccount SubPath: MountPropagation:<nil>}] VolumeDevices:[] LivenessProbe:&Probe{Handler:Handler{Exec:&ExecAction{Command:[mongo --eval db.adminCommand('ping')],},HTTPGet:nil,TCPSocket:nil,},InitialDelaySeconds:30,TimeoutSeconds:4,PeriodSeconds:10,SuccessThreshold:1,FailureThreshold:3,} ReadinessProbe:&Probe{Handler:Handler{Exec:&ExecAction{Command:[mongo --eval db.adminCommand('ping')],},HTTPGet:nil,TCPSocket:nil,},InitialDelaySeconds:5,TimeoutSeconds:1,PeriodSeconds:10,SuccessThreshold:1,FailureThreshold:3,} Lifecycle:nil TerminationMessagePath:/dev/termination-log TerminationMessagePolicy:File ImagePullPolicy:IfNotPresent SecurityContext:nil Stdin:false StdinOnce:false TTY:false} is dead, but RestartPolicy says that we should restart it.
Nov 22 21:52:26 fsprdce1c04 kubelet[77800]: E1122 21:52:26.572332   77800 dns.go:121] Search Line limits were exceeded, some search paths have been omitted, the applied search line is: production.svc.cluster.local svc.cluster.local cluster.local corp.kwiktrip.com kwiktrip.com dmz.kwiktrip.com
Nov 22 21:52:26 fsprdce1c04 kubelet[77800]: I1122 21:52:26.572416   77800 kuberuntime_manager.go:757] checking backoff for container "mongodb" in pod "edge-mongodb-2_production(d8627797-ee89-11e8-b96d-0050568593cc)"
Nov 22 21:52:26 fsprdce1c04 kubelet[77800]: W1122 21:52:26.728328   77800 container.go:406] Failed to get RecentStats("/libcontainer_235510_systemd_test_default.slice") while determining the next housekeeping: unable to find data for container /libcontainer_235510_systemd_test_default.slice
Nov 22 21:52:26 fsprdce1c04 kubelet[77800]: E1122 21:52:26.852610   77800 remote_runtime.go:187] CreateContainer in sandbox "43299b80a8de388a98e904f15893686e0ae4f1803bf61f4a706015c742a7248e" from runtime service failed: rpc error: code = Unknown desc = container create failed: container_linux.go:330: creating new parent process caused "container_linux.go:1759: running lstat on namespace path \"/proc/134447/ns/ipc\" caused \"lstat /proc/134447/ns/ipc: no such file or directory\""
Nov 22 21:52:26 fsprdce1c04 kubelet[77800]: E1122 21:52:26.852688   77800 kuberuntime_manager.go:733] container start failed: CreateContainerError: container create failed: container_linux.go:330: creating new parent process caused "container_linux.go:1759: running lstat on namespace path \"/proc/134447/ns/ipc\" caused \"lstat /proc/134447/ns/ipc: no such file or directory\""
Nov 22 21:52:26 fsprdce1c04 kubelet[77800]: E1122 21:52:26.852719   77800 pod_workers.go:186] Error syncing pod d8627797-ee89-11e8-b96d-0050568593cc ("edge-mongodb-2_production(d8627797-ee89-11e8-b96d-0050568593cc)"), skipping: failed to "StartContainer" for "mongodb" with CreateContainerError: "container create failed: container_linux.go:330: creating new parent process caused \"container_linux.go:1759: running lstat on namespace path \\\"/proc/134447/ns/ipc\\\" caused \\\"lstat /proc/134447/ns/ipc: no such file or directory\\\"\"\n"

Describe the results you expected:
Container to be created

Additional information you deem important (e.g. issue happens only occasionally):

Output of crio --version:
v1.11.10

Additional environment details (AWS, VirtualBox, physical, etc.):
Ubuntu 18.04
Kubernetes v1.11.4
VMware VM

[mrunalp]

Thanks for the report. Were you able to find a reproducer or gather more data around when it fails leading to this path?

[steven-sheehy]

Nope, we have since switched to containerd due to this and other issues I've reported. You can close this if there's not enough information to investigate.

[steven-sheehy]

I did just reproduce this in an environment that was still on CRI-O. The pod in question OOMKilled and then would not restart with CreateContainerError. So most likely the mongo pod above OOMKilled. Another thing I noticed is that crictl pods shows duplicate pods for the same pod name:

POD ID              CREATED             STATE               NAME                                  NAMESPACE           ATTEMPT
8d3766f4fa05b       4 days ago          Ready               kube-apiserver-node1             kube-system         4
...
b26d8f861f68b       10 days ago         NotReady            kube-apiserver-node1             kube-system         3

If you attempt to crictl stopp any of those pods, they don't ever get removed and just say "Stopped sandbox". Some of them actually error when you attempt to crictl stopp them with an error like below:

stopping the pod sandbox \"9cc4ceb855380894dc9b533816c3e3a26f8ebc7d7dfed8094bdb2c27bccce9e6\" failed: rpc error: code = Unknown desc = failed to stop infra container k8s_POD_prometheus-adapter-98c478448-fgkwm_production_4108c907-d250-11e8-a6ff-00505691cd09_0 in pod sandbox 9cc4ceb855380894dc9b533816c3e3a26f8ebc7d7dfed8094bdb2c27bccce9e6: failed to stop container \"9cc4ceb855380894dc9b533816c3e3a26f8ebc7d7dfed8094bdb2c27bccce9e6\": failed to find process: os: process not initialized

[mrunalp]

Thanks for the info @steven-sheehy. I have an idea to try to reproduce it and see what's happening.

Does kubelet show the older not-ready pods? You should be able to crictl rmp it.

If it is ready, first stopp and then followed by rmp.

For the stopping pod error, it indicates that the pod process has already exited so it must be for one of the NotReady pods.

[steven-sheehy]

The NotReady pod above b26d8f861f68b shows up repeatedly in the kubelet logs. The kubelet log is filled with these type of errors for different pods:

Nov 29 15:38:01 node1 kubelet[171051]: E1129 15:38:01.728954  171051 manager.go:1130] Failed to create existing container: /kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod2f51c00348d8eda21ed2277aee3b213f.slice/crio-b26d8f861f68bcdc5c4f6c0e8ffa8f185ef41cc160d588ca5c34054993d4f2cd.scope: invalid character 'c' looking for beginning of value

[Bregor]

Similar behaviour here:

Output of crio --version:
crio version 1.12.3

Additional environment details (AWS, VirtualBox, physical, etc.):
Ubuntu 16.04.5
Kubernetes v1.12.4
Digital Ocean

Logs:

Dec 20 18:23:19 kube08 crio[27083]: time="2018-12-20 18:23:19.384647228+03:00" level=warning msg="logPath from relative path is now absolute: /var/log/pods/b586fcf2-03bb-11e9-96be-b60ec1ff1c27/worker/3.log"
Dec 20 18:23:19 kube08 crio[27083]: time="2018-12-20 18:23:19.469946112+03:00" level=error msg="Container creation error: container_linux.go:337: creating new parent process caused "container_linux.go:1781: running lstat on namespace path \"/proc/28352/ns/ipc\" caused \"lstat /proc/28352/ns/ipc: no such file or directory\""

[mcluseau]

hi, reporting the same as @steven-sheehy here with crio 1.13.0 and kubelet 1.13.1 (without systemd)

manager.go:1147] Failed to create existing container: /kubepods/burstable/pod8b35a2c2-0bb1-11e9-a7a6-0cc47abaca30/crio-4a3c478ec491e24b85b2f826a1e49671f56e2b3e469b46bfca451c8af13a7518: invalid character 'c' looking for beginning of value

[mrunalp]

@mcluseau Thanks! We are looking into a fix for this.

[giuseppe]

I've observed some races in the interaction between CRI-O and the Kubelet. I think 6703d85 might solve some of them. Another potential fix is kubernetes/kubernetes#72105

[rhatdan]

@steven-sheehy @giuseppe @mrunalp Is this still an issue?

[giuseppe]

the errors I could reproduce are fixed upstream, except for a Kubernetes patch that is still being discussed.

@steven-sheehy have you had a chance to try again with an updated CRI-O?

[steven-sheehy]

Sorry, I don't have the ability to test it. I can close it and we can reopen if needed.

[mrunalp]

Reopening as the upstream PR is not yet merged - kubernetes/kubernetes#72105

[mrunalp]

Turns out #1957 wasn't backported to 1.13. I just opened #2143. I will cut a new release once we merge that.

[mingzhu02]

I have same proble

docker log

Apr 03 19:53:05 bjlt-rs277.sy dockerd[1928]: time="2019-04-03T19:53:05.436089294+08:00" level=error msg="Error running exec in container: rpc error: code = 2 desc = oci runtime error: exec failed: container_linux.go:255: creating new parent process caused \"container_linux.go:1462: running lstat on namespace path \\\"/proc/3865/ns/ipc\\\" caused \\\"lstat /proc/3865/ns/ipc: no such file or directory\\\"\"\n"
Apr 03 19:53:06 bjlt-rs277.sy dockerd[1928]: time="2019-04-03T19:53:06.516203002+08:00" level=error msg="Error running exec in container: rpc error: code = 2 desc = oci runtime error: exec failed: container_linux.go:255: creating new parent process caused \"container_linux.go:1462: running lstat on namespace path \\\"/proc/3865/ns/ipc\\\" caused \\\"lstat /proc/3865/ns/ipc: no such file or directory\\\"\"\n"
Apr 03 19:53:07 bjlt-rs277.sy dockerd[1928]: time="2019-04-03T19:53:07.718370824+08:00" level=error msg="Error running exec in container: rpc error: code = 2 desc = oci runtime error: exec failed: container_linux.go:255: creating new parent process caused \"container_linux.go:1462: running lstat on namespace path \\\"/proc/3865/ns/ipc\\\" caused \\\"lstat /proc/3865/ns/ipc: no such file or directory\\\"\"\n"
Apr 03 19:53:37 bjlt-rs277.sy dockerd[1928]: time="2019-04-03T19:53:37.104508687+08:00" level=error msg="Error running exec in container: rpc error: code = 2 desc = oci runtime error: exec failed: container_linux.go:255: creating new parent process caused \"container_linux.go:1462: running lstat on namespace path \\\"/proc/3865/ns/ipc\\\" caused \\\"lstat /proc/3865/ns/ipc: no such file or directory\\\"\"\n"
Apr 03 19:54:28 bjlt-rs277.sy dockerd[1928]: time="2019-04-03T19:54:28.998753522+08:00" level=error msg="Error running exec in container: rpc error: code = 2 desc = oci runtime error: exec failed: container_linux.go:255: creating new parent process caused \"container_linux.go:1462: running lstat on namespace path \\\"/proc/3865/ns/ipc\\\" caused \\\"lstat /proc/3865/ns/ipc: no such file or directory\\\"\"\n"
Apr 03 19:55:10 bjlt-rs277.sy dockerd[1928]: time="2019-04-03T19:55:10.822910429+08:00" level=error msg="Error running exec in container: rpc error: code = 2 desc = oci runtime error: exec failed: container_linux.go:255: creating new parent process caused \"container_linux.go:1462: running lstat on namespace path \\\"/proc/3865/ns/ipc\\\" caused \\\"lstat /proc/3865/ns/ipc: no such file or directory\\\"\"\n"
Apr 03 19:55:10 bjlt-rs277.sy dockerd[1928]: time="2019-04-03T19:55:10.883501531+08:00" level=error msg="Error running exec in container: rpc error: code = 2 desc = oci runtime error: exec failed: container_linux.go:255: creating new parent process caused \"container_linux.go:1462: running lstat on namespace path \\\"/proc/3865/ns/ipc\\\" caused \\\"lstat /proc/3865/ns/ipc: no such file or directory\\\"\"\n"
Apr 03 19:55:28 bjlt-rs277.sy dockerd[1928]: time="2019-04-03T19:55:28.418526592+08:00" level=error msg="Error running exec in container: rpc error: code = 2 desc = oci runtime error: exec failed: container_linux.go:255: creating new parent process caused \"container_linux.go:1462: running lstat on namespace path \\\"/proc/3865/ns/ipc\\\" caused \\\"lstat /proc/3865/ns/ipc: no such file or directory\\\"\"\n"
Apr 03 19:55:29 bjlt-rs277.sy dockerd[1928]: time="2019-04-03T19:55:29.916646813+08:00" level=error msg="Error running exec in container: rpc error: code = 2 desc = oci runtime error: exec failed: container_linux.go:255: creating new parent process caused \"container_linux.go:1462: running lstat on namespace path \\\"/proc/3865/ns/ipc\\\" caused \\\"lstat /proc/3865/ns/ipc: no such file or directory\\\"\"\n"
Apr 03 19:55:34 bjlt-rs277.sy dockerd[1928]: time="2019-04-03T19:55:34.621417137+08:00" level=error msg="Error running exec in container: rpc error: code = 2 desc = oci runtime error: exec failed: container_linux.go:255: creating new parent process caused \"container_linux.go:1462: running lstat on namespace path \\\"/proc/3865/ns/ipc\\\" caused \\\"lstat /proc/3865/ns/ipc: no such file or directory\\\"\"\n"

kubelet log

Apr 03 18:58:49 bjlt-rs277.sy kubelet[2836]: E0403 18:58:49.834682    2836 pod_workers.go:186] Error syncing pod 912cc052-430b-11e9-aabd-246e96a2ecd4 ("dmo-hdp-jupyter-12-deploy-8457f4d87-f8w7c_default(912cc052-430b-11e9-aabd-246e96a2ecd4)"), skipping: failed to "StartContainer" for "hdp-jupyter-12-0" with ErrImagePull: "rpc error: code = Unknown desc = Error response from daemon: received unexpected HTTP status: 500 Internal Server Error"
Apr 03 18:59:00 bjlt-rs277.sy kubelet[2836]: I0403 18:59:00.413944    2836 reconciler.go:191] operationExecutor.UnmountVolume started for volume "hadoop" (UniqueName: "kubernetes.io/host-path/912cc052-430b-11e9-aabd-246e96a2ecd4-hadoop") pod "912cc052-430b-11e9-aabd-246e96a2ecd4" (UID: "912cc052-430b-11e9-aabd-246e96a2ecd4")
Apr 03 18:59:00 bjlt-rs277.sy kubelet[2836]: I0403 18:59:00.413976    2836 operation_generator.go:643] UnmountVolume.TearDown succeeded for volume "kubernetes.io/host-path/912cc052-430b-11e9-aabd-246e96a2ecd4-hadoop" (OuterVolumeSpecName: "hadoop") pod "912cc052-430b-11e9-aabd-246e96a2ecd4" (UID: "912cc052-430b-11e9-aabd-246e96a2ecd4"). InnerVolumeSpecName "hadoop". PluginName "kubernetes.io/host-path", VolumeGidValue ""
Apr 03 18:59:00 bjlt-rs277.sy kubelet[2836]: I0403 18:59:00.414000    2836 reconciler.go:191] operationExecutor.UnmountVolume started for volume "home" (UniqueName: "kubernetes.io/cephfs/912cc052-430b-11e9-aabd-246e96a2ecd4-dmo-jupyter-users") pod "912cc052-430b-11e9-aabd-246e96a2ecd4" (UID: "912cc052-430b-11e9-aabd-246e96a2ecd4")
Apr 03 18:59:00 bjlt-rs277.sy kubelet[2836]: I0403 18:59:00.414038    2836 reconciler.go:297] Volume detached for volume "hadoop" (UniqueName: "kubernetes.io/host-path/912cc052-430b-11e9-aabd-246e96a2ecd4-hadoop") on node "bjlt-rs277.sy" DevicePath ""
Apr 03 18:59:00 bjlt-rs277.sy kubelet[2836]: I0403 18:59:00.470572    2836 operation_generator.go:643] UnmountVolume.TearDown succeeded for volume "kubernetes.io/cephfs/912cc052-430b-11e9-aabd-246e96a2ecd4-dmo-jupyter-users" (OuterVolumeSpecName: "home") pod "912cc052-430b-11e9-aabd-246e96a2ecd4" (UID: "912cc052-430b-11e9-aabd-246e96a2ecd4"). InnerVolumeSpecName "dmo-jupyter-users". PluginName "kubernetes.io/cephfs", VolumeGidValue ""
Apr 03 18:59:00 bjlt-rs277.sy kubelet[2836]: I0403 18:59:00.514165    2836 reconciler.go:297] Volume detached for volume "dmo-jupyter-users" (UniqueName: "kubernetes.io/cephfs/912cc052-430b-11e9-aabd-246e96a2ecd4-dmo-jupyter-users") on node "bjlt-rs277.sy" DevicePath ""
Apr 03 18:59:00 bjlt-rs277.sy kubelet[2836]: W0403 18:59:00.949713    2836 pod_container_deletor.go:77] Container "8058d6c86f22b62f18dc6835872a3611aa7ff2a34d0c1433b604be0d48b87f71" not found in pod's containers
Apr 03 19:31:35 bjlt-rs277.sy kubelet[2836]: W0403 19:31:35.356460    2836 docker_sandbox.go:340] failed to read pod IP from plugin/docker: Couldn't find network status for default/dmo-hdp-jupyter-30-deploy-b9666668d-6w92b through plugin: invalid network status for
Apr 03 19:31:35 bjlt-rs277.sy kubelet[2836]: W0403 19:31:35.369843    2836 pod_container_deletor.go:77] Container "87b011e9caa6b0150a1adf013d7980673ad7ddd60c9f1b21bfe575206f3d520f" not found in pod's containers

[benceszikora]

We are seeing the same problem now with cri-o 1.16.0

[mnaser]

Indeed, I'm running into this with cri-o 1.16 too :(

[mnaser]

FWIW, this started occurring after a DaemonSet that had no limits had limited added (but really low ones). We bumped up the limits for it and it started working. Perhaps when the resources are so low in the container, you have those issues?

[giuseppe]

FWIW, this started occurring after a DaemonSet that had no limits had limited added (but really low ones). We bumped up the limits for it and it started working. Perhaps when the resources are so low in the container, you have those issues?

I think it is still the issue in the Kubelet. I have used a static pod to reproduce it: kubernetes/kubernetes#72105 (comment)

Do you easily reproduce the issue if you try something like I've done in the comment above?

[github-actions]

A friendly reminder that this issue had no activity for 30 days.

[github-actions]

Closing this issue since it had no activity in the past 90 days.