Bug 1657735

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