Description of problem: Pod failed to start with subpath Version-Release number of selected component (if applicable): openshift v3.10.83 kubernetes v1.10.0+b81c8f8 How reproducible: Always Steps to Reproduce: 1. Create a pod with subpath volume mounts with emptyDir Actual results: The pod failed to start with error "Error: failed to prepare subPath for volumeMount" Tried with emptydir, cinder volume, all failed # oc get pods NAME READY STATUS RESTARTS AGE emptypod 0/1 CreateContainerConfigError 0 15m # oc describe po emptypod Events: Type Reason Age From Message ---- ------ ---- ---- ------- Normal Scheduled 16m default-scheduler Successfully assigned emptypod to preserve-ah310stage4--node-infra-1 Normal Pulling 16m kubelet, preserve-ah310stage4--node-infra-1 pulling image "aosqe/hello-openshift" Normal Pulled 16m kubelet, preserve-ah310stage4--node-infra-1 Successfully pulled image "aosqe/hello-openshift" Normal Created 16m kubelet, preserve-ah310stage4--node-infra-1 Created container Normal Started 16m kubelet, preserve-ah310stage4--node-infra-1 Started container Normal Pulled 14m (x7 over 16m) kubelet, preserve-ah310stage4--node-infra-1 Successfully pulled image "aosqe/hello-openshift" Warning Failed 14m (x7 over 16m) kubelet, preserve-ah310stage4--node-infra-1 Error: failed to prepare subPath for volumeMount "dynamic" of container "testpod" Normal Pulling 1m (x58 over 16m) kubelet, preserve-ah310stage4--node-infra-1 pulling image "aosqe/hello-openshift" Expected results: Pod could be started Master Log: Did not find any useful info Node Log (of failed PODs): Dec 10 10:26:20 preserve-ah310stage4--node-infra-1 atomic-openshift-node[19418]: I1210 10:26:20.754226 19428 kuberuntime_manager.go:570] computePodActions got {KillPod:false CreateSandbox:false SandboxID:df0bc615d7646432928f56818aea5f7c9b316ffa2a426a7e0f37a9ff4840ce66 Attempt:0 NextInitContainerToStart:nil ContainersToStart:[0] ContainersToKill:map[]} for pod "subpathpod_default(a8ebb857-fc61-11e8-a5bb-fa163edff5fc)" Dec 10 10:26:20 preserve-ah310stage4--node-infra-1 atomic-openshift-node[19418]: I1210 10:26:20.754342 19428 kuberuntime_manager.go:724] Creating container &Container{Name:testpod,Image:aosqe/hello-openshift,Command:[],Args:[],WorkingDir:,Ports:[{http-server 0 80 TCP }],Env:[],Resources:ResourceRequirements{Limits:ResourceList{},Requests:ResourceList{},},VolumeMounts:[{dynamic false /mnt/iaas subpath <nil>} {default-token-ts4zs true /var/run/secrets/kubernetes.io/serviceaccount <nil>}],LivenessProbe:nil,ReadinessProbe:nil,Lifecycle:nil,TerminationMessagePath:/dev/termination-log,ImagePullPolicy:Always,SecurityContext:&SecurityContext{Capabilities:&Capabilities{Add:[],Drop:[MKNOD],},Privileged:nil,SELinuxOptions:nil,RunAsUser:nil,RunAsNonRoot:nil,ReadOnlyRootFilesystem:nil,AllowPrivilegeEscalation:nil,RunAsGroup:nil,},Stdin:false,StdinOnce:false,TTY:false,EnvFrom:[],TerminationMessagePolicy:File,VolumeDevices:[],} in pod subpathpod_default(a8ebb857-fc61-11e8-a5bb-fa163edff5fc) Dec 10 10:26:20 preserve-ah310stage4--node-infra-1 atomic-openshift-node[19418]: I1210 10:26:20.756972 19428 server.go:440] Event(v1.ObjectReference{Kind:"Pod", Namespace:"default", Name:"subpathpod", UID:"a8ebb857-fc61-11e8-a5bb-fa163edff5fc", APIVersion:"v1", ResourceVersion:"67521", FieldPath:"spec.containers{testpod}"}): type: 'Normal' reason: 'Pulling' pulling image "aosqe/hello-openshift" Dec 10 10:26:22 preserve-ah310stage4--node-infra-1 atomic-openshift-node[19418]: I1210 10:26:22.318986 19428 kuberuntime_container.go:100] Generating ref for container testpod: &v1.ObjectReference{Kind:"Pod", Namespace:"default", Name:"subpathpod", UID:"a8ebb857-fc61-11e8-a5bb-fa163edff5fc", APIVersion:"v1", ResourceVersion:"67521", FieldPath:"spec.containers{testpod}"} Dec 10 10:26:22 preserve-ah310stage4--node-infra-1 atomic-openshift-node[19418]: I1210 10:26:22.319103 19428 kubelet_pods.go:172] container: default/subpathpod/testpod podIP: "10.130.0.24" creating hosts mount: true Dec 10 10:26:22 preserve-ah310stage4--node-infra-1 atomic-openshift-node[19418]: I1210 10:26:22.319878 19428 server.go:440] Event(v1.ObjectReference{Kind:"Pod", Namespace:"default", Name:"subpathpod", UID:"a8ebb857-fc61-11e8-a5bb-fa163edff5fc", APIVersion:"v1", ResourceVersion:"67521", FieldPath:"spec.containers{testpod}"}): type: 'Normal' reason: 'Pulled' Successfully pulled image "aosqe/hello-openshift" Dec 10 10:26:22 preserve-ah310stage4--node-infra-1 atomic-openshift-node[19418]: E1210 10:26:22.323632 19428 pod_workers.go:186] Error syncing pod a8ebb857-fc61-11e8-a5bb-fa163edff5fc ("subpathpod_default(a8ebb857-fc61-11e8-a5bb-fa163edff5fc)"), skipping: failed to "StartContainer" for "testpod" with CreateContainerConfigError: "failed to prepare subPath for volumeMount \"dynamic\" of container \"testpod\"" Dec 10 10:26:22 preserve-ah310stage4--node-infra-1 atomic-openshift-node[19418]: I1210 10:26:22.323812 19428 server.go:440] Event(v1.ObjectReference{Kind:"Pod", Namespace:"default", Name:"subpathpod", UID:"a8ebb857-fc61-11e8-a5bb-fa163edff5fc", APIVersion:"v1", ResourceVersion:"67521", FieldPath:"spec.containers{testpod}"}): type: 'Warning' reason: 'Failed' Error: failed to prepare subPath for volumeMount "dynamic" of container "testpod" Additional info: We install system container OCP in atomic host
Adding the atomic host info # cat /etc/redhat-release Red Hat Enterprise Linux Atomic Host release 7.6 # uname -a Linux preserve-ah310stage4--master-etcd-1 3.10.0-957.el7.x86_64 #1 SMP Thu Oct 4 20:48:51 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux And I double confirmed on a rpm OCP today, it works well and with subPath volume. # cat /etc/redhat-release Red Hat Enterprise Linux Server release 7.6 (Maipo) # oc get pods NAME READY STATUS RESTARTS AGE emptypod 1/1 Running 0 4m # cat empty.yaml kind: Pod apiVersion: v1 metadata: name: emptypod spec: initContainers: - name: init image: aosqe/hello-openshift command: ["sh", "-c", "mkdir /mnt/iaas/subpath; cp /hello /mnt/iaas/subpath/hello"] volumeMounts: - mountPath: "/mnt/iaas" name: dynamic containers: - name: testpod image: aosqe/hello-openshift ports: - containerPort: 80 name: "http-server" volumeMounts: - mountPath: "/mnt/iaas" subPath: "subpath" name: dynamic volumes: - name: dynamic emptyDir:
I failed to reproduce this with v3.10.86 on OpenStack. And seeing the comment #2... Can we close this as NOTABUG or is there still something to be fixed here?
(In reply to Tomas Smetana from comment #3) > I failed to reproduce this with v3.10.86 on OpenStack. And seeing the > comment #2... Can we close this as NOTABUG or is there still something to be > fixed here? Hi Tomas, this bug I found in system container OCP, which was installed on Atomic host. I have sent you a separated mail to share you the env. Thanks
Thanks. I've looked around your cluster and there is really something broken. I suspect the init container fails to prepare the directory for the "testpod" container. I can see some image pull errors but I'm not sure those are related yet.
Yes, the problem is specific to Atomic Host -- nsenter mount is trying to access nonexisting path (/var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/volume-subpaths/dynamic/testpod/0): Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.715327 19505 kubelet_pods.go:172] container: default/emptypod/testpod podIP: "10.130.0.2" creating hosts mount: true Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.715340 19505 server.go:440] Event(v1.ObjectReference{Kind:"Pod", Namespace:"default", Name:"emptypod", UID:"378f2f7b-fe02-11e8-bcca-fa163edf5d52", APIVersion:"v1", ResourceVersion:"4338", FieldPath:"spec.containers{testpod}"}): type: 'Normal' reason: 'Pulled' Successfully pull Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.715498 19505 nsenter_mount.go:323] Kubelet's PID on the host is 19505 Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.715538 19505 mount_linux.go:747] doBindSubPath "/var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/volumes/kubernetes.io~empty-dir/dynamic/subpath", full subpath "/var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/v Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.715817 19505 nsenter_mount.go:167] findmnt: directory /var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/volume-subpaths/dynamic/testpod/0 does not exist Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.715841 19505 nsenter.go:107] Running nsenter command: nsenter [--mount=/rootfs/proc/1/ns/mnt -- realpath -e /var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/volume-subpaths/dynamic/testpod/0] Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.718299 19505 nsenter.go:151] failed to resolve symbolic links on /var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/volume-subpaths/dynamic/testpod/0: exit status 1 Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.718328 19505 mount_linux.go:767] doBindSubPath() failed for "/var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/volume-subpaths/dynamic/testpod/0", cleaning up subpath Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.718340 19505 mount_linux.go:890] Cleaning up subpath mounts for subpath 0 Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.718353 19505 nsenter_mount.go:167] findmnt: directory /var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/volume-subpaths/dynamic/testpod/0 does not exist Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.718360 19505 nsenter.go:107] Running nsenter command: nsenter [--mount=/rootfs/proc/1/ns/mnt -- realpath -e /var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/volume-subpaths/dynamic/testpod/0] Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.720241 19505 nsenter.go:151] failed to resolve symbolic links on /var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/volume-subpaths/dynamic/testpod/0: exit status 1 Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: E1212 11:36:58.720261 19505 mount_linux.go:769] Failed to clean subpath "/var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/volume-subpaths/dynamic/testpod/0": error checking /var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/volu Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: E1212 11:36:58.720273 19505 kubelet_pods.go:245] failed to prepare subPath for volumeMount "dynamic" of container "testpod": error checking path /var/lib/origin/openshift.local.volumes/pods/378f2f7b-fe02-11e8-bcca-fa163edf5d52/volume-subpaths/dynamic/testpod/0 for mount: exit status 1 Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: E1212 11:36:58.720331 19505 kuberuntime_manager.go:733] container start failed: CreateContainerConfigError: failed to prepare subPath for volumeMount "dynamic" of container "testpod" Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: E1212 11:36:58.720415 19505 pod_workers.go:186] Error syncing pod 378f2f7b-fe02-11e8-bcca-fa163edf5d52 ("emptypod_default(378f2f7b-fe02-11e8-bcca-fa163edf5d52)"), skipping: failed to "StartContainer" for "testpod" with CreateContainerConfigError: "failed to prepare subPath for volumeMount \" Dec 12 11:36:58 preserve-wehe310--node-1 atomic-openshift-node[19495]: I1212 11:36:58.720432 19505 server.go:440] Event(v1.ObjectReference{Kind:"Pod", Namespace:"default", Name:"emptypod", UID:"378f2f7b-fe02-11e8-bcca-fa163edf5d52", APIVersion:"v1", ResourceVersion:"4338", FieldPath:"spec.containers{testpod}"}): type: 'Warning' reason: 'Failed' Error: failed to
Origin PR: https://github.com/openshift/origin/pull/21672
Tested on below version: openshift v3.10.89 kubernetes v1.10.0+b81c8f8 # uname -a Linux qe-wehe-master-etcd-1 3.10.0-957.el7.x86_64 #1 SMP Thu Oct 4 20:48:51 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux # cat /etc/redhat-release Red Hat Enterprise Linux Atomic Host release 7.6 The pod is running well with subPath volume mount on system container installation on Atomic host # oc get pods emptypod -o yaml apiVersion: v1 kind: Pod metadata: annotations: openshift.io/scc: anyuid creationTimestamp: 2018-12-19T05:58:47Z name: emptypod namespace: default resourceVersion: "21118" selfLink: /api/v1/namespaces/default/pods/emptypod uid: 26bce23f-0353-11e9-ae8a-fa163e9415bd spec: containers: - image: aosqe/hello-openshift imagePullPolicy: Always name: testpod ports: - containerPort: 80 name: http-server protocol: TCP resources: {} securityContext: capabilities: drop: - MKNOD terminationMessagePath: /dev/termination-log terminationMessagePolicy: File volumeMounts: - mountPath: /mnt/iaas name: dynamic subPath: subpath - mountPath: /var/run/secrets/kubernetes.io/serviceaccount name: default-token-z5hp5 readOnly: true dnsPolicy: ClusterFirst imagePullSecrets: - name: default-dockercfg-rw7c2 initContainers: - command: - sh - -c - mkdir /mnt/iaas/subpath; cp /hello /mnt/iaas/subpath/hello image: aosqe/hello-openshift imagePullPolicy: Always name: init resources: {} securityContext: capabilities: drop: - MKNOD terminationMessagePath: /dev/termination-log terminationMessagePolicy: File volumeMounts: - mountPath: /mnt/iaas name: dynamic - mountPath: /var/run/secrets/kubernetes.io/serviceaccount name: default-token-z5hp5 readOnly: true nodeName: qe-wehe-node-infra-1 restartPolicy: Always schedulerName: default-scheduler securityContext: seLinuxOptions: level: s0:c1,c0 serviceAccount: default serviceAccountName: default terminationGracePeriodSeconds: 30 volumes: - emptyDir: {} name: dynamic - name: default-token-z5hp5 secret: defaultMode: 420 secretName: default-token-z5hp5 status: conditions: - lastProbeTime: null lastTransitionTime: 2018-12-19T05:58:55Z status: "True" type: Initialized - lastProbeTime: null lastTransitionTime: 2018-12-19T05:58:59Z status: "True" type: Ready - lastProbeTime: null lastTransitionTime: 2018-12-19T05:58:47Z status: "True" type: PodScheduled containerStatuses: - containerID: docker://441daf160c1b236a68d5cc3f5ee4c16ec6b7190dc70be01355f93ec2e2392f5e image: docker.io/aosqe/hello-openshift:latest imageID: docker-pullable://docker.io/aosqe/hello-openshift@sha256:a2d509d3d5164f54a2406287405b2d114f952dca877cc465129f78afa858b31a lastState: {} name: testpod ready: true restartCount: 0 state: running: startedAt: 2018-12-19T05:58:59Z hostIP: 172.16.122.56 initContainerStatuses: - containerID: docker://fcc9913ba8c3b0080681c61c0e5e0f2e52af59adc784de2c6447f3dc06b22f70 image: docker.io/aosqe/hello-openshift:latest imageID: docker-pullable://docker.io/aosqe/hello-openshift@sha256:a2d509d3d5164f54a2406287405b2d114f952dca877cc465129f78afa858b31a lastState: {} name: init ready: true restartCount: 0 state: terminated: containerID: docker://fcc9913ba8c3b0080681c61c0e5e0f2e52af59adc784de2c6447f3dc06b22f70 exitCode: 0 finishedAt: 2018-12-19T05:58:55Z reason: Completed startedAt: 2018-12-19T05:58:55Z phase: Running podIP: 10.130.0.7 qosClass: BestEffort startTime: 2018-12-19T05:58:48Z
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2019:0026