Closed edevil closed 7 years ago
possibly related #845
@edevil, are you using Kubernetes 1.6 with vagrant (either multi or single node) from this repo? If so, how?
I tried setting export K8S_VER=v1.6.1_coreos.0
, but the API server fails to stay up.
@jbw976 No, I'm not using Vagrant.
I run into the same issue with using a fresh cluster created with kubeadm:
# dpkg -l | grep kube
ii kubeadm 1.6.1-00 amd64 Kubernetes Cluster Bootstrapping Tool
ii kubectl 1.6.1-00 amd64 Kubernetes Command Line Tool
ii kubelet 1.6.1-00 amd64 Kubernetes Node Agent
ii kubernetes-cni 0.5.1-00 amd64 Kubernetes CNI
All is running on Ubuntu 16.04 (Linux k8s00 4.4.0-72-generic #93-Ubuntu SMP Fri Mar 31 14:07:41 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
) which itself is a VMware virtual machine.
I'm running into the same problem after upgrading to 1.6.1_coreos.0 on CoreOS stable 1298.7.0 with Calico v2.1.0. nsenter_fail.txt
Once the nsenter fails (in an attempt to get Pod IP?), Calico IPAM releases the IP from its datastore, but the Pod still starts with the previously assigned IP. I end up with a Pod/IP that has no associated iptables rules on host - no network access.
This is because the cni plugins required are not in hyperkube 1.6.1. Just need a v1.6.2-beta.0 hyperkube.
https://github.com/projectcalico/canal/issues/13 https://github.com/projectcalico/canal/issues/14
resolved:
https://github.com/projectcalico/cni-plugin/pull/211 and https://github.com/kubernetes/kubernetes/commit/f4d9bbc7d89f6a9ced4b98902b6c6e7d7be635e9 https://github.com/kubernetes/kubernetes/issues/43488#issuecomment-288525151
In the interim, you can either add these to your node:
https://github.com/heschlie/calico-cni/blob/72312b8be38408bcce792fc1a317a7d4c280cdad/Makefile#L94
Or use the gcr hyperkube, nuances described here:
FTR, I'm not using calico, just the kubenet plugin.
Check for the cni plugins in your container.
/opt/cni/bin/flannel /opt/cni/bin/loopback /opt/cni/bin/host-local
Also, the lines before the ones you pasted previously would help narrow it down.
Here is the log: nsenter.txt
@jsulinski v1.6.2-beta.0 is essentially no different than v1.6.1 (https://github.com/kubernetes/kubernetes/compare/v1.6.1...v1.6.2-beta.0) - the first beta gets cut immediately after the previous patch release. And there has been no new changes to the upstream hyperkube to bump the CNI version (in v1.6.x).
Also not sure why nsenter missing would be related to the CNI binary versions. nsenter should be part of the hyperkube image filesystem.
@edevil do you have reproduction steps to get this error?
@aaronlevy Sorry, it was late. The upstream CNI changes are in v1.7.0-alpha.1.
nsenter is not actually missing, and I haven't dug into the code but I presume something being passed to nsenter is (flannel?). Manually adding the cni plugins to the host resolved the issue for me.
@aaronlevy I just setup a 1.6 cluster and start deleting pods. Maybe what's missing is the namespace when nsenter is called? I don't use flannel, just kubenet with a promiscuous bridge.
I don't use kubenet, so I can't test this easily.
This is where you're encountering the issue, I think:
Notice the error isn’t going to fmt, it’s going to glog, so that might explain why there isn't a more helpful error message:
same for me
Plugin cni failed on the status hook for pod "kube-dns-2286869516-hd2lg_kube-system": Unexpected command output nsenter: cannot open : No such file or directory
I'm not familiar with using kubenet -- would anyone be able to provide reproduction steps to hit this error?
I have an additional log of an occurrence:
Apr 20 16:29:28 node-0-vm kubelet-wrapper[5381]: E0420 16:29:28.496443 5381 secret.go:201] Couldn't get secret /wrapped_default-token-n52dt.deleting~296290347
Apr 20 16:29:28 node-0-vm kubelet-wrapper[5381]: E0420 16:29:28.496514 5381 event.go:259] Could not construct reference to: '&v1.Pod{TypeMeta:v1.TypeMeta{Kind:"", APIVersion:""}, ObjectMeta:v1.ObjectMeta{Name:"", GenerateName:"", Namespace:"", SelfLink:"", UID:"38461635-24ed-11e7-a937-000d3a2709aa", ResourceVersion:"", Generation:0, CreationTimestamp:v1.Time{Time:time.Time{sec:0, nsec:0, loc:(*time.Location)(nil)}}, DeletionTimestamp:(*v1.Time)(nil), DeletionGracePeriodSeconds:(*int64)(nil), Labels:map[string]string(nil), Annotations:map[string]string(nil), OwnerReferences:[]v1.OwnerReference(nil), Finalizers:[]string(nil), ClusterName:""}, Spec:v1.PodSpec{Volumes:[]v1.Volume(nil), InitContainers:[]v1.Container(nil), Containers:[]v1.Container(nil), RestartPolicy:"", TerminationGracePeriodSeconds:(*int64)(nil), ActiveDeadlineSeconds:(*int64)(nil), DNSPolicy:"", NodeSelector:map[string]string(nil), ServiceAccountName:"", DeprecatedServiceAccount:"", AutomountServiceAccountToken:(*bool)(nil), NodeName:"", HostNetwork:false, HostPID:false, HostIPC:false, SecurityContext:(*v1.PodSecurityContext)(nil), ImagePullSecrets:[]v1.LocalObjectReference(nil), Hostname:"", Subdomain:"", Affinity:(*v1.Affinity)(nil), SchedulerName:"", Tolerations:[]v1.Toleration(nil)}, Status:v1.PodStatus{Phase:"", Conditions:[]v1.PodCondition(nil), Message:"", Reason:"", HostIP:"", PodIP:"", StartTime:(*v1.Time)(nil), InitContainerStatuses:[]v1.ContainerStatus(nil), ContainerStatuses:[]v1.ContainerStatus(nil), QOSClass:""}}' due to: 'selfLink was empty, can't make reference'. Will not report event: 'Warning' 'FailedMount' 'MountVolume.SetUp failed for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-wrapped_default-token-n52dt.deleting~296290347" (spec.Name: "wrapped_default-token-n52dt.deleting~296290347") pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa") with: secret ""/"wrapped_default-token-n52dt.deleting~296290347" not registered'
Apr 20 16:29:28 node-0-vm kubelet-wrapper[5381]: E0420 16:29:28.496619 5381 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-wrapped_default-token-n52dt.deleting~296290347\" (\"38461635-24ed-11e7-a937-000d3a2709aa\")" failed. No retries permitted until 2017-04-20 16:31:28.496593024 +0000 UTC (durationBeforeRetry 2m0s). Error: MountVolume.SetUp failed for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-wrapped_default-token-n52dt.deleting~296290347" (spec.Name: "wrapped_default-token-n52dt.deleting~296290347") pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa") with: secret ""/"wrapped_default-token-n52dt.deleting~296290347" not registered
Apr 20 16:29:36 node-0-vm kubelet-wrapper[5381]: I0420 16:29:36.458609 5381 operation_generator.go:597] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/8007d2e8-255e-11e7-b9a8-000d3a27013b-default-token-dcpt7" (spec.Name: "default-token-dcpt7") pod "8007d2e8-255e-11e7-b9a8-000d3a27013b" (UID: "8007d2e8-255e-11e7-b9a8-000d3a27013b").
Apr 20 16:29:37 node-0-vm kubelet-wrapper[5381]: I0420 16:29:37.385257 5381 operation_generator.go:597] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/7f990806-255e-11e7-b9a7-000d3a27013b-default-token-l1z8v" (spec.Name: "default-token-l1z8v") pod "7f990806-255e-11e7-b9a7-000d3a27013b" (UID: "7f990806-255e-11e7-b9a7-000d3a27013b").
Apr 20 16:29:47 node-0-vm kubelet-wrapper[5381]: W0420 16:29:47.556903 5381 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "publico-cidades-api-671885830-7g19v_publico-cidades-staging": Unexpected command output nsenter: cannot open : No such file or directory
Apr 20 16:29:47 node-0-vm kubelet-wrapper[5381]: with error: exit status 1
Apr 20 16:29:47 node-0-vm kubelet-wrapper[5381]: W0420 16:29:47.568738 5381 pod_container_deletor.go:77] Container "960d77c9e8f80b7d036a9b9453df9721741f70e460e96b5dbf8d837982981058" not found in pod's containers
Apr 20 16:29:47 node-0-vm kubelet-wrapper[5381]: W0420 16:29:47.593243 5381 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "publico-cidades-api-671885830-7g19v_publico-cidades-staging": Unexpected command output nsenter: cannot open : No such file or directory
Apr 20 16:29:47 node-0-vm kubelet-wrapper[5381]: with error: exit status 1
Apr 20 16:29:47 node-0-vm kubelet-wrapper[5381]: I0420 16:29:47.697364 5381 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt" (spec.Name: "default-token-n52dt") from pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa").
Apr 20 16:29:47 node-0-vm kubelet-wrapper[5381]: E0420 16:29:47.826523 5381 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt\" (\"38461635-24ed-11e7-a937-000d3a2709aa\")" failed. No retries permitted until 2017-04-20 16:29:48.32648022 +0000 UTC (durationBeforeRetry 500ms). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt" (volume.spec.Name: "default-token-n52dt") pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa") with: remove /var/lib/kubelet/pods/38461635-24ed-11e7-a937-000d3a2709aa/volumes/kubernetes.io~secret/default-token-n52dt: device or resource busy
Apr 20 16:29:48 node-0-vm kubelet-wrapper[5381]: I0420 16:29:48.401807 5381 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt" (spec.Name: "default-token-n52dt") from pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa").
Apr 20 16:29:48 node-0-vm kubelet-wrapper[5381]: E0420 16:29:48.402157 5381 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt\" (\"38461635-24ed-11e7-a937-000d3a2709aa\")" failed. No retries permitted until 2017-04-20 16:29:49.402122398 +0000 UTC (durationBeforeRetry 1s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt" (volume.spec.Name: "default-token-n52dt") pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa") with: rename /var/lib/kubelet/pods/38461635-24ed-11e7-a937-000d3a2709aa/volumes/kubernetes.io~secret/default-token-n52dt /var/lib/kubelet/pods/38461635-24ed-11e7-a937-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-n52dt.deleting~948530632: device or resource busy
Apr 20 16:29:48 node-0-vm kubelet-wrapper[5381]: W0420 16:29:48.613819 5381 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "publico-cidades-api-671885830-7g19v_publico-cidades-staging": Unexpected command output nsenter: cannot open : No such file or directory
Apr 20 16:29:48 node-0-vm kubelet-wrapper[5381]: with error: exit status 1
Apr 20 16:29:48 node-0-vm kubelet-wrapper[5381]: W0420 16:29:48.647758 5381 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "publico-cidades-api-671885830-7g19v_publico-cidades-staging": Unexpected command output nsenter: cannot open : No such file or directory
Apr 20 16:29:48 node-0-vm kubelet-wrapper[5381]: with error: exit status 1
Apr 20 16:29:49 node-0-vm kubelet-wrapper[5381]: I0420 16:29:49.423790 5381 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt" (spec.Name: "default-token-n52dt") from pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa").
Apr 20 16:29:49 node-0-vm kubelet-wrapper[5381]: E0420 16:29:49.424173 5381 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt\" (\"38461635-24ed-11e7-a937-000d3a2709aa\")" failed. No retries permitted until 2017-04-20 16:29:51.424140877 +0000 UTC (durationBeforeRetry 2s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt" (volume.spec.Name: "default-token-n52dt") pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa") with: rename /var/lib/kubelet/pods/38461635-24ed-11e7-a937-000d3a2709aa/volumes/kubernetes.io~secret/default-token-n52dt /var/lib/kubelet/pods/38461635-24ed-11e7-a937-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-n52dt.deleting~885321863: device or resource busy
Apr 20 16:29:51 node-0-vm kubelet-wrapper[5381]: I0420 16:29:51.438597 5381 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt" (spec.Name: "default-token-n52dt") from pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa").
Apr 20 16:29:51 node-0-vm kubelet-wrapper[5381]: E0420 16:29:51.439015 5381 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt\" (\"38461635-24ed-11e7-a937-000d3a2709aa\")" failed. No retries permitted until 2017-04-20 16:29:55.438992867 +0000 UTC (durationBeforeRetry 4s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt" (volume.spec.Name: "default-token-n52dt") pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa") with: rename /var/lib/kubelet/pods/38461635-24ed-11e7-a937-000d3a2709aa/volumes/kubernetes.io~secret/default-token-n52dt /var/lib/kubelet/pods/38461635-24ed-11e7-a937-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-n52dt.deleting~288451642: device or resource busy
Apr 20 16:29:54 node-0-vm kubelet-wrapper[5381]: I0420 16:29:54.064457 5381 operation_generator.go:597] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/8065fecb-255e-11e7-b9a8-000d3a27013b-default-token-dcpt7" (spec.Name: "default-token-dcpt7") pod "8065fecb-255e-11e7-b9a8-000d3a27013b" (UID: "8065fecb-255e-11e7-b9a8-000d3a27013b").
Apr 20 16:29:55 node-0-vm kubelet-wrapper[5381]: I0420 16:29:55.468609 5381 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt" (spec.Name: "default-token-n52dt") from pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa").
Apr 20 16:29:55 node-0-vm kubelet-wrapper[5381]: E0420 16:29:55.469537 5381 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt\" (\"38461635-24ed-11e7-a937-000d3a2709aa\")" failed. No retries permitted until 2017-04-20 16:30:03.469512645 +0000 UTC (durationBeforeRetry 8s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt" (volume.spec.Name: "default-token-n52dt") pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa") with: rename /var/lib/kubelet/pods/38461635-24ed-11e7-a937-000d3a2709aa/volumes/kubernetes.io~secret/default-token-n52dt /var/lib/kubelet/pods/38461635-24ed-11e7-a937-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-n52dt.deleting~423785041: device or resource busy
Apr 20 16:30:03 node-0-vm kubelet-wrapper[5381]: I0420 16:30:03.549321 5381 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt" (spec.Name: "default-token-n52dt") from pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa").
Apr 20 16:30:03 node-0-vm kubelet-wrapper[5381]: E0420 16:30:03.549658 5381 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt\" (\"38461635-24ed-11e7-a937-000d3a2709aa\")" failed. No retries permitted until 2017-04-20 16:30:19.549634162 +0000 UTC (durationBeforeRetry 16s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/38461635-24ed-11e7-a937-000d3a2709aa-default-token-n52dt" (volume.spec.Name: "default-token-n52dt") pod "38461635-24ed-11e7-a937-000d3a2709aa" (UID: "38461635-24ed-11e7-a937-000d3a2709aa") with: rename /var/lib/kubelet/pods/38461635-24ed-11e7-a937-000d3a2709aa/volumes/kubernetes.io~secret/default-token-n52dt /var/lib/kubelet/pods/38461635-24ed-11e7-a937-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-n52dt.deleting~884081532: device or resource busy
FTR, this was a 1.5 node that was upgraded to 1.6.
Another example of a log of a container that remains in "Terminating" state:
Apr 26 14:05:57 node-2-vm kubelet-wrapper[53469]: W0426 14:05:57.609218 53469 kuberuntime_container.go:436] No ref for container {"docker" "fc4cbfae10229719304461a50b033a3e79c56e2d22429930a96d606768cd325e"}
Apr 26 14:05:57 node-2-vm kubelet-wrapper[53469]: W0426 14:05:57.717962 53469 kuberuntime_container.go:436] No ref for container {"docker" "407e593084f37c26e221e214a152eb76bd75c0b98d4d325f3acf6e6cbc33174d"}
Apr 26 14:05:57 node-2-vm kubelet-wrapper[53469]: W0426 14:05:57.999098 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: W0426 14:05:58.289643 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: W0426 14:05:58.371146 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-97jj7_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: W0426 14:05:58.474087 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-97jj7_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: W0426 14:05:58.508943 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-97jj7_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: W0426 14:05:58.554761 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: W0426 14:05:58.680045 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-jbk0h_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: W0426 14:05:58.702436 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: W0426 14:05:58.760407 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-jbk0h_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: W0426 14:05:58.781314 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-jbk0h_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:58 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: W0426 14:05:59.826932 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-97jj7_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: W0426 14:05:59.847556 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-97jj7_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: W0426 14:05:59.851917 53469 pod_container_deletor.go:77] Container "fb22a69a4f999718bc59bf0c69f9924959e880c348722605f80edf0c40bed20f" not found in pod's containers
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: W0426 14:05:59.864203 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-97jj7_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: W0426 14:05:59.879957 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-jbk0h_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: W0426 14:05:59.899334 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: W0426 14:05:59.951402 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-jbk0h_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: W0426 14:05:59.964735 53469 pod_container_deletor.go:77] Container "d2236be6586a2a58830ac4f87a87a560d893be90210abf70c08b01470912ce5e" not found in pod's containers
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: W0426 14:05:59.966016 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-97jj7_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: I0426 14:05:59.977453 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: W0426 14:05:59.990754 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-jbk0h_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:05:59 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: E0426 14:06:00.018293 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f2977579-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:06:00.518262326 +0000 UTC (durationBeforeRetry 500ms). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa") with: remove /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1: device or resource busy
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: W0426 14:06:00.018585 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: W0426 14:06:00.053595 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: W0426 14:06:00.098859 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-jbk0h_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: W0426 14:06:00.112154 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: I0426 14:06:00.587161 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: E0426 14:06:00.587881 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f2977579-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:06:01.587861335 +0000 UTC (durationBeforeRetry 1s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa") with: rename /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1 /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~506253460: device or resource busy
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: W0426 14:06:00.864855 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-jbk0h_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: W0426 14:06:00.885136 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: W0426 14:06:00.925609 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-97jj7_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: W0426 14:06:00.937676 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: W0426 14:06:00.977469 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-jbk0h_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:06:00 node-2-vm kubelet-wrapper[53469]: W0426 14:06:00.996589 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:06:01 node-2-vm kubelet-wrapper[53469]: W0426 14:06:01.039060 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-97jj7_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:06:01 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:06:01 node-2-vm kubelet-wrapper[53469]: W0426 14:06:01.053790 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:06:01 node-2-vm kubelet-wrapper[53469]: I0426 14:06:01.467644 53469 operation_generator.go:597] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/30344757-2a5e-11e7-be9c-000d3a27013b-default-token-2bkr0" (spec.Name: "default-token-2bkr0") pod "30344757-2a5e-11e7-be9c-000d3a27013b" (UID: "30344757-2a5e-11e7-be9c-000d3a27013b").
Apr 26 14:06:01 node-2-vm kubelet-wrapper[53469]: I0426 14:06:01.666542 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:01 node-2-vm kubelet-wrapper[53469]: E0426 14:06:01.667410 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f2977579-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:06:03.667384507 +0000 UTC (durationBeforeRetry 2s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa") with: rename /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1 /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~639936739: device or resource busy
Apr 26 14:06:02 node-2-vm kubelet-wrapper[53469]: I0426 14:06:02.070497 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:02 node-2-vm kubelet-wrapper[53469]: E0426 14:06:02.088579 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f296a799-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:06:02.588534905 +0000 UTC (durationBeforeRetry 500ms). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa") with: remove /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1: device or resource busy
Apr 26 14:06:02 node-2-vm kubelet-wrapper[53469]: I0426 14:06:02.676233 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:02 node-2-vm kubelet-wrapper[53469]: E0426 14:06:02.676517 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f296a799-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:06:03.676489289 +0000 UTC (durationBeforeRetry 1s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa") with: rename /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1 /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~378809062: device or resource busy
Apr 26 14:06:03 node-2-vm kubelet-wrapper[53469]: I0426 14:06:03.690813 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:03 node-2-vm kubelet-wrapper[53469]: I0426 14:06:03.691426 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:03 node-2-vm kubelet-wrapper[53469]: E0426 14:06:03.691990 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f296a799-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:06:05.691962072 +0000 UTC (durationBeforeRetry 2s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa") with: rename /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1 /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~983072525: device or resource busy
Apr 26 14:06:03 node-2-vm kubelet-wrapper[53469]: E0426 14:06:03.693234 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f2977579-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:06:07.693217342 +0000 UTC (durationBeforeRetry 4s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa") with: rename /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1 /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~463042824: device or resource busy
Apr 26 14:06:04 node-2-vm kubelet-wrapper[53469]: I0426 14:06:04.496509 53469 operation_generator.go:597] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/dc408bab-28eb-11e7-83bd-000d3a2709aa-default-token-dv8hh" (spec.Name: "default-token-dv8hh") pod "dc408bab-28eb-11e7-83bd-000d3a2709aa" (UID: "dc408bab-28eb-11e7-83bd-000d3a2709aa").
Apr 26 14:06:05 node-2-vm kubelet-wrapper[53469]: I0426 14:06:05.769596 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:05 node-2-vm kubelet-wrapper[53469]: E0426 14:06:05.770241 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f296a799-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:06:09.770219759 +0000 UTC (durationBeforeRetry 4s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa") with: rename /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1 /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~812888263: device or resource busy
Apr 26 14:06:07 node-2-vm kubelet-wrapper[53469]: I0426 14:06:07.777913 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:07 node-2-vm kubelet-wrapper[53469]: E0426 14:06:07.778201 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f2977579-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:06:15.778180474 +0000 UTC (durationBeforeRetry 8s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa") with: rename /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1 /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~446378874: device or resource busy
Apr 26 14:06:09 node-2-vm kubelet-wrapper[53469]: I0426 14:06:09.798955 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:09 node-2-vm kubelet-wrapper[53469]: E0426 14:06:09.799227 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f296a799-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:06:17.799185921 +0000 UTC (durationBeforeRetry 8s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa") with: rename /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1 /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~776278161: device or resource busy
Apr 26 14:06:10 node-2-vm kubelet-wrapper[53469]: W0426 14:06:10.498590 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-97jj7_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:06:10 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:06:10 node-2-vm kubelet-wrapper[53469]: W0426 14:06:10.518367 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:06:10 node-2-vm kubelet-wrapper[53469]: W0426 14:06:10.581754 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-jbk0h_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:06:10 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:06:10 node-2-vm kubelet-wrapper[53469]: W0426 14:06:10.602964 53469 docker_service.go:304] Failed to retrieve checkpoint for sandbox "checkpoint is not found.": %!v(MISSING)
Apr 26 14:06:10 node-2-vm kubelet-wrapper[53469]: W0426 14:06:10.693040 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-97jj7_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:06:10 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:06:10 node-2-vm kubelet-wrapper[53469]: W0426 14:06:10.728784 53469 docker_sandbox.go:263] NetworkPlugin kubenet failed on the status hook for pod "trendex-1520046056-jbk0h_trendex": Unexpected command output nsenter: cannot open : No such file or directory
Apr 26 14:06:10 node-2-vm kubelet-wrapper[53469]: with error: exit status 1
Apr 26 14:06:13 node-2-vm kubelet-wrapper[53469]: I0426 14:06:13.237263 53469 operation_generator.go:597] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/30658401-2a5e-11e7-be9c-000d3a27013b-default-token-1v1rn" (spec.Name: "default-token-1v1rn") pod "30658401-2a5e-11e7-be9c-000d3a27013b" (UID: "30658401-2a5e-11e7-be9c-000d3a27013b").
Apr 26 14:06:15 node-2-vm kubelet-wrapper[53469]: I0426 14:06:15.145952 53469 operation_generator.go:597] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/30407fc7-2a5e-11e7-be9c-000d3a27013b-default-token-d34mp" (spec.Name: "default-token-d34mp") pod "30407fc7-2a5e-11e7-be9c-000d3a27013b" (UID: "30407fc7-2a5e-11e7-be9c-000d3a27013b").
Apr 26 14:06:15 node-2-vm kubelet-wrapper[53469]: I0426 14:06:15.816634 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:15 node-2-vm kubelet-wrapper[53469]: E0426 14:06:15.816984 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f2977579-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:06:31.8169603 +0000 UTC (durationBeforeRetry 16s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa") with: rename /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1 /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~012342972: device or resource busy
Apr 26 14:06:17 node-2-vm kubelet-wrapper[53469]: I0426 14:06:17.849777 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:17 node-2-vm kubelet-wrapper[53469]: E0426 14:06:17.850076 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f296a799-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:06:33.850052775 +0000 UTC (durationBeforeRetry 16s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa") with: rename /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1 /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~370795755: device or resource busy
Apr 26 14:06:22 node-2-vm kubelet-wrapper[53469]: I0426 14:06:22.963609 53469 operation_generator.go:597] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/dc409ba5-28eb-11e7-83bd-000d3a2709aa-default-token-dv8hh" (spec.Name: "default-token-dv8hh") pod "dc409ba5-28eb-11e7-83bd-000d3a2709aa" (UID: "dc409ba5-28eb-11e7-83bd-000d3a2709aa").
Apr 26 14:06:25 node-2-vm kubelet-wrapper[53469]: I0426 14:06:25.753841 53469 operation_generator.go:597] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/5c265d1f-2a62-11e7-be9c-000d3a27013b-default-token-d8bxp" (spec.Name: "default-token-d8bxp") pod "5c265d1f-2a62-11e7-be9c-000d3a27013b" (UID: "5c265d1f-2a62-11e7-be9c-000d3a27013b").
Apr 26 14:06:31 node-2-vm kubelet-wrapper[53469]: I0426 14:06:31.896960 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:31 node-2-vm kubelet-wrapper[53469]: E0426 14:06:31.897261 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f2977579-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:07:03.897236898 +0000 UTC (durationBeforeRetry 32s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f2977579-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f2977579-2910-11e7-83bd-000d3a2709aa" (UID: "f2977579-2910-11e7-83bd-000d3a2709aa") with: rename /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1 /var/lib/kubelet/pods/f2977579-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~341193038: device or resource busy
Apr 26 14:06:32 node-2-vm kubelet-wrapper[53469]: I0426 14:06:32.703434 53469 operation_generator.go:597] MountVolume.SetUp succeeded for volume "kubernetes.io/secret/e28a913d-28df-11e7-83bd-000d3a2709aa-default-token-7ffjg" (spec.Name: "default-token-7ffjg") pod "e28a913d-28df-11e7-83bd-000d3a2709aa" (UID: "e28a913d-28df-11e7-83bd-000d3a2709aa").
Apr 26 14:06:32 node-2-vm kubelet-wrapper[53469]: I0426 14:06:32.706144 53469 operation_generator.go:597] MountVolume.SetUp succeeded for volume "kubernetes.io/configmap/e28a913d-28df-11e7-83bd-000d3a2709aa-config-volume" (spec.Name: "config-volume") pod "e28a913d-28df-11e7-83bd-000d3a2709aa" (UID: "e28a913d-28df-11e7-83bd-000d3a2709aa").
Apr 26 14:06:33 node-2-vm kubelet-wrapper[53469]: I0426 14:06:33.907632 53469 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa").
Apr 26 14:06:33 node-2-vm kubelet-wrapper[53469]: E0426 14:06:33.908355 53469 nestedpendingoperations.go:262] Operation for "\"kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1\" (\"f296a799-2910-11e7-83bd-000d3a2709aa\")" failed. No retries permitted until 2017-04-26 14:07:05.908323707 +0000 UTC (durationBeforeRetry 32s). Error: UnmountVolume.TearDown failed for volume "kubernetes.io/secret/f296a799-2910-11e7-83bd-000d3a2709aa-default-token-5dzd1" (volume.spec.Name: "default-token-5dzd1") pod "f296a799-2910-11e7-83bd-000d3a2709aa" (UID: "f296a799-2910-11e7-83bd-000d3a2709aa") with: rename /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/default-token-5dzd1 /var/lib/kubelet/pods/f296a799-2910-11e7-83bd-000d3a2709aa/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~664431701: device or resource busy
As far as the network plugin error, it seems to be a non-critical warning that looks to happen because a container has been removed, but the kubelet can still try to inspect the network status. Opened a PR upstream to make this error message a little less worrying.
So I managed to investigate a bit more when a pod is kept in a "Terminated" state. When this happens these log lines appear every 10s on the kubelet log:
May 05 09:47:01 node-0-vm kubelet-wrapper[10360]: I0505 09:47:01.637670 10360 kubelet_pods.go:1543] Orphaned pod "99aa7a22-307c-11e7-8662-000d3a27013b" found, but volumes not yet removed. Reducing cpu to minimum
May 05 09:47:03 node-0-vm kubelet-wrapper[10360]: I0505 09:47:03.615016 10360 kubelet_pods.go:720] Pod "trendex-3550941154-z56lt_trendex(99aa7a22-307c-11e7-8662-000d3a27013b)" is terminated, but some volumes have not been cleaned up
So it seems it is because there are still mounted volumes on the terminating pod. I checked the mounted filesystems:
tmpfs on /var/lib/kubelet/pods/99aa7a22-307c-11e7-8662-000d3a27013b/volumes/kubernetes.io~secret/default-token-5dzd1 type tmpfs (rw,relatime,seclabel)
So there is in fact a mounted volume on this pod. It is strange, however, that it does not appear as mounted on the mirror dir in the stage2:
# ls -l /var/lib/rkt/pods/run/439fe49c-cbfe-4e0d-bc41-e292921b35c6/stage1/rootfs/opt/stage2/hyperkube/rootfs/var/lib/kubelet/pods/99aa7a22-307c-11e7-8662-000d3a27013b/volumes/kubernetes.io~secret/default-token-5dzd1/
total 0
# ls -l /var/lib/kubelet/pods/99aa7a22-307c-11e7-8662-000d3a27013b/volumes/kubernetes.io~secret/default-token-5dzd1/
total 0
lrwxrwxrwx. 1 root root 13 May 4 03:48 ca.crt -> ..data/ca.crt
lrwxrwxrwx. 1 root root 16 May 4 03:48 namespace -> ..data/namespace
lrwxrwxrwx. 1 root root 12 May 4 03:48 token -> ..data/token
These 2 dirs are almost the same except for this mount. Can it have anything to do with the problem?
Sure enough, after I unmounted the volume manually:
umount /var/lib/kubelet/pods/99aa7a22-307c-11e7-8662-000d3a27013b/volumes/kubernetes.io~secret/default-token-5dzd1
The pod terminated successfully:
May 05 13:35:55 node-0-vm kubelet-wrapper[10360]: I0505 13:35:55.407056 10360 reconciler.go:478] Reconciler sync states: could not find pod information in desired or actual states or pending operation, update it in both states: &{volumeName:kubernetes.io/secret/99aa7a22-307c-11e7-8662-000d3a27013b-wrapped_default-token-5dzd1.deleting~079593492 podName:99aa7a22-307c-11e7-8662-000d3a27013b volumeSpec:0xc423377d20 outerVolumeSpecName:wrapped_default-token-5dzd1.deleting~079593492 pod:0xc4228c4900 pluginIsAttachable:false volumeGidValue: devicePath: reportedInUse:false mounter:0xc421d84700}
May 05 13:35:55 node-0-vm kubelet-wrapper[10360]: I0505 13:35:55.612243 10360 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/99aa7a22-307c-11e7-8662-000d3a27013b-wrapped_default-token-5dzd1.deleting~079593492" (spec.Name: "wrapped_default-token-5dzd1.deleting~079593492") from pod "99aa7a22-307c-11e7-8662-000d3a27013b" (UID: "99aa7a22-307c-11e7-8662-000d3a27013b").
May 05 13:35:55 node-0-vm kubelet-wrapper[10360]: I0505 13:35:55.612301 10360 util.go:367] Tearing down volume wrapped_default-token-5dzd1.deleting~079593492 for pod 99aa7a22-307c-11e7-8662-000d3a27013b at /var/lib/kubelet/pods/99aa7a22-307c-11e7-8662-000d3a27013b/volumes/kubernetes.io~secret/wrapped_default-token-5dzd1.deleting~079593492
May 05 13:35:55 node-0-vm kubelet-wrapper[10360]: I0505 13:35:55.612513 10360 operation_generator.go:672] UnmountVolume.TearDown succeeded for volume "kubernetes.io/secret/99aa7a22-307c-11e7-8662-000d3a27013b-wrapped_default-token-5dzd1.deleting~079593492" (OuterVolumeSpecName: "wrapped_default-token-5dzd1.deleting~079593492") pod "99aa7a22-307c-11e7-8662-000d3a27013b" (UID: "99aa7a22-307c-11e7-8662-000d3a27013b"). InnerVolumeSpecName "wrapped_default-token-5dzd1.deleting~079593492". PluginName "kubernetes.io/secret", VolumeGidValue ""
May 05 13:35:55 node-0-vm kubelet-wrapper[10360]: I0505 13:35:55.612571 10360 reconciler.go:352] Detached volume "kubernetes.io/secret/99aa7a22-307c-11e7-8662-000d3a27013b-wrapped_default-token-5dzd1.deleting~079593492" (spec.Name: "wrapped_default-token-5dzd1.deleting~079593492") devicePath: ""
May 05 13:35:56 node-0-vm kubelet-wrapper[10360]: I0505 13:35:56.529235 10360 kubelet_pods.go:1543] Orphaned pod "99aa7a22-307c-11e7-8662-000d3a27013b" found, but volumes not yet removed. Reducing cpu to minimum
May 05 13:35:57 node-0-vm kubelet-wrapper[10360]: I0505 13:35:57.976322 10360 reconciler.go:190] UnmountVolume operation started for volume "kubernetes.io/secret/99aa7a22-307c-11e7-8662-000d3a27013b-default-token-5dzd1" (spec.Name: "default-token-5dzd1") from pod "99aa7a22-307c-11e7-8662-000d3a27013b" (UID: "99aa7a22-307c-11e7-8662-000d3a27013b").
May 05 13:35:57 node-0-vm kubelet-wrapper[10360]: I0505 13:35:57.976404 10360 util.go:367] Tearing down volume default-token-5dzd1 for pod 99aa7a22-307c-11e7-8662-000d3a27013b at /var/lib/kubelet/pods/99aa7a22-307c-11e7-8662-000d3a27013b/volumes/kubernetes.io~secret/default-token-5dzd1
May 05 13:35:57 node-0-vm kubelet-wrapper[10360]: I0505 13:35:57.976567 10360 operation_generator.go:672] UnmountVolume.TearDown succeeded for volume "kubernetes.io/secret/99aa7a22-307c-11e7-8662-000d3a27013b-default-token-5dzd1" (OuterVolumeSpecName: "default-token-5dzd1") pod "99aa7a22-307c-11e7-8662-000d3a27013b" (UID: "99aa7a22-307c-11e7-8662-000d3a27013b"). InnerVolumeSpecName "default-token-5dzd1". PluginName "kubernetes.io/secret", VolumeGidValue ""
May 05 13:35:58 node-0-vm kubelet-wrapper[10360]: I0505 13:35:58.076553 10360 reconciler.go:352] Detached volume "kubernetes.io/secret/99aa7a22-307c-11e7-8662-000d3a27013b-default-token-5dzd1" (spec.Name: "default-token-5dzd1") devicePath: ""
May 05 13:35:58 node-0-vm kubelet-wrapper[10360]: I0505 13:35:58.612574 10360 kubelet_pods.go:1549] Orphaned pod "99aa7a22-307c-11e7-8662-000d3a27013b" found, removing pod cgroups
May 05 13:35:58 node-0-vm kubelet-wrapper[10360]: I0505 13:35:58.615200 10360 manager.go:955] Destroyed container: "/kubepods/burstable/pod99aa7a22-307c-11e7-8662-000d3a27013b" (aliases: [], namespace: "")
May 05 13:35:58 node-0-vm kubelet-wrapper[10360]: I0505 13:35:58.615451 10360 handler.go:325] Added event &{/kubepods/burstable/pod99aa7a22-307c-11e7-8662-000d3a27013b 2017-05-05 13:35:58.615443269 +0000 UTC containerDeletion {<nil>}}
May 05 13:36:02 node-0-vm kubelet-wrapper[10360]: I0505 13:36:02.614484 10360 status_manager.go:444] Status for pod "trendex-3550941154-z56lt_trendex(99aa7a22-307c-11e7-8662-000d3a27013b)" updated successfully: {status:{Phase:Running Conditions:[{Type:Initialized Status:True LastProbeTime:{Time:{sec:0 nsec:0 loc:0x6c64580}} LastTransitionTime:{Time:{sec:63629466537 nsec:0 loc:0x6c64580}} Reason: Message:} {Type:Ready Status:False LastProbeTime:{Time:{sec:0 nsec:0 loc:0x6c64580}} LastTransitionTime:{Time:{sec:63629497508 nsec:0 loc:0x6c64580}} Reason:ContainersNotReady Message:containers with unready status: [trendex]} {Type:PodScheduled Status:True LastProbeTime:{Time:{sec:0 nsec:0 loc:0x6c64580}} LastTransitionTime:{Time:{sec:63629466537 nsec:0 loc:0x6c64580}} Reason: Message:}] Message: Reason: HostIP:10.0.3.10 PodIP: StartTime:0xc4210adb80 InitContainerStatuses:[] ContainerStatuses:[{Name:trendex State:{Waiting:<nil> Running:<nil> Terminated:0xc4218b6f50} LastTerminationState:{Waiting:<nil> Running:<nil> Terminated:<nil>} Ready:false RestartCount:0 Image:brpxregistry-andrecabine.azurecr.io/trendex:master.05f28833 ImageID:docker-pullable://brpxregistry-andrecabine.azurecr.io/trendex@sha256:3c6c64782533fb9e3f658e73240878e3137c91e612b443b13dcc2c8ec9e868be ContainerID:docker://8a4c021f7b34d11f61ec4a125688dd25ca35ee20e008e73e031572d3dcb8511f}] QOSClass:Burstable} version:6 podName:trendex-3550941154-z56lt podNamespace:trendex}
May 05 13:36:02 node-0-vm kubelet-wrapper[10360]: I0505 13:36:02.657951 10360 kubelet.go:1824] SyncLoop (DELETE, "api"): "trendex-3550941154-z56lt_trendex(99aa7a22-307c-11e7-8662-000d3a27013b)"
May 05 13:36:02 node-0-vm kubelet-wrapper[10360]: I0505 13:36:02.686536 10360 status_manager.go:457] Pod "trendex-3550941154-z56lt_trendex(99aa7a22-307c-11e7-8662-000d3a27013b)" fully terminated and removed from etcd
May 05 13:36:02 node-0-vm kubelet-wrapper[10360]: I0505 13:36:02.688559 10360 kubelet.go:1818] SyncLoop (REMOVE, "api"): "trendex-3550941154-z56lt_trendex(99aa7a22-307c-11e7-8662-000d3a27013b)"
May 05 13:36:02 node-0-vm kubelet-wrapper[10360]: I0505 13:36:02.688591 10360 kubelet.go:2002] Failed to delete pod "trendex-3550941154-z56lt_trendex(99aa7a22-307c-11e7-8662-000d3a27013b)", err: pod not found
May 05 13:36:02 node-0-vm kubelet-wrapper[10360]: I0505 13:36:02.695928 10360 status_manager.go:425] Pod "trendex-3550941154-z56lt" (99aa7a22-307c-11e7-8662-000d3a27013b) does not exist on the server
May 05 13:36:04 node-0-vm kubelet-wrapper[10360]: I0505 13:36:04.652233 10360 kubelet_volumes.go:117] Orphaned pod "99aa7a22-307c-11e7-8662-000d3a27013b" found, removing
FTR, I had restarted the kubelet with already running pods, so that can explain the differences in the mountpoints perhaps.
So it seems it is because there are still mounted volumes on the terminating pod. I checked the mounted filesystems
We are experiencing that behavior in our cluster, and it makes using EBS volumes damn near impossible because the mounts are not cleaned up correctly, resulting in a lot of Orphaned pod
messages, the EBS volume still mounted, and when the Pod gets assigned to a different Node then the container times out waiting for the EBS to detach from the old Node.
Don't get me wrong, there are what feels like hundreds of EBS related issues in the kubernetes repo, but this "Orphaned pod" behavior strikes a chord with me, specifically.
I think we fixed the issue matching the current title via adding recursive
to the kubelet-wrapper script. See https://github.com/coreos/coreos-overlay/pull/2508 and linked issues.
This should have hit all Container Linux channels at this point.
If that wasn't the root cause of this issue, please do reopen or refile.
I've setup a new 1.6 cluster and have found that sometimes pods end up in the Terminating state forever (at least some hours).
When this happens I see these messages in the kubelet log:
OS Version: