Description of problem: When creating a PV-backed app such as cakephp-mysql-example, 'oc get events -w' output is truncated unexpectedly after the app experiences a mount error. # 'oc get events -w' output ends with the following message: FailedMount {kubelet ip-172-31-12-71.ec2.internal} MountVolume.SetUp failed for volume "kubernetes.io/aws-ebs/f046c97c-a150-11e6-ab91-0a7e599be118-pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc" (spec.Name: "pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc") pod "f046c97c-a150-11e6-ab91-0a7e599be118" (UID: "f046c97c-a150-11e6-ab91-0a7e599be118") with: mount failed: exit status 32 Mounting arguments: /var/lib/origin/openshift.local.volumes/plugins/kubernetes.io/aws-ebs/mounts/aws/us-east-1c/vol-811d9a1d /var/lib/origin/openshift.local.volumes/pods/f046c97c-a150-11e6-ab91-0a7e599be118/volumes/kubernetes.io~aws-ebs/pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc [bind]error: unable to output the provided object: short write # 'oc describe pods' for the affected pod shows this error: /var/lib/origin/openshift.local.volumes/plugins/kubernetes.io/aws-ebs/mounts/aws/us-east-1c/vol-811d9a1d does not exist Version-Release number of selected component (if applicable): How reproducible: 100% Steps to Reproduce: 1. oc new-app cakephp-mysql-example -n <project> 2. oc get events -n <project> -w 3. oc describe pods mysql-1-<uuid> -n <project> Actual results: Mysql pod never starts because the container never mounts the PV. 'oc get events' stops outputting log info. Expected results: PV should get mounted. Pod should start up. And 'oc get events -w' should continue outputting logs. Additional info: # here's what I saw when I experienced the problem [root@dev-preview-int-master-284c5 ~]# oadm new-project dakinitest1 Created project dakinitest1 [root@dev-preview-int-master-284c5 ~]# oc new-app cakephp-mysql-example -n dakinitest1 --> Deploying template "openshift/cakephp-mysql-example" to project dakinitest1 cakephp-mysql-example --------- An example CakePHP application with a MySQL database * With parameters: * Memory Limit=512Mi * Memory Limit (MySQL)=512Mi * Volume Capacity=1Gi * Git Repository URL=https://github.com/openshift/cakephp-ex.git * Git Reference= * Context Directory= * Application Hostname= * GitHub Webhook Secret=WJ8iUb7XWsJnsvUOfSFG5mvsoMUY4mG6xxmwuD8K # generated * Database Service Name=mysql * Database Engine=mysql * Database Name=default * Database User=cakephp * Database Password=hoSnRwI7N32S15xr # generated * CakePHP secret token=k_gwDKuFo9Vx1WQAMGrQR0eu6UmRJ0UAfkYZUv31SEpHRCtqwI # generated * CakePHP Security Salt=kYNjyDfH1VkBpJI4p8evk17CSNTQR1w2lA1UFXI5 # generated * CakePHP Security Cipher Seed=688212277450486116676037070367 # generated * OPcache Revalidation Frequency=2 --> Creating resources ... service "cakephp-mysql-example" created route "cakephp-mysql-example" created imagestream "cakephp-mysql-example" created buildconfig "cakephp-mysql-example" created persistentvolumeclaim "mysql" created deploymentconfig "cakephp-mysql-example" created service "mysql" created deploymentconfig "mysql" created --> Success Build scheduled, use 'oc logs -f bc/cakephp-mysql-example' to track its progress. Run 'oc status' to view your app. [root@dev-preview-int-master-284c5 ~]# oc get pods -n dakinitest1 NAME READY STATUS RESTARTS AGE cakephp-mysql-example-1-build 1/1 Running 0 9s mysql-1-6jn6q 0/1 ContainerCreating 0 6s mysql-1-deploy 1/1 Running 0 9s [root@dev-preview-int-master-284c5 ~]# oc get pvc -n dakinitest1 NAME STATUS VOLUME CAPACITY ACCESSMODES AGE mysql Bound pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc 1Gi RWO 14s [root@dev-preview-int-master-284c5 ~]# oc get pvc -n dakinitest1 -o yaml apiVersion: v1 items: - apiVersion: v1 kind: PersistentVolumeClaim metadata: annotations: openshift.io/generated-by: OpenShiftNewApp pv.kubernetes.io/bind-completed: "yes" pv.kubernetes.io/bound-by-controller: "yes" volume.beta.kubernetes.io/storage-class: ebs creationTimestamp: 2016-11-02T23:06:05Z labels: app: cakephp-mysql-example template: cakephp-mysql-example name: mysql namespace: dakinitest1 resourceVersion: "10145077" selfLink: /api/v1/namespaces/dakinitest1/persistentvolumeclaims/mysql uid: eea17ddb-a150-11e6-9f67-0a30d6fc46dc spec: accessModes: - ReadWriteOnce resources: requests: storage: 1Gi volumeName: pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc status: accessModes: - ReadWriteOnce capacity: storage: 1Gi phase: Bound kind: List metadata: {} [root@dev-preview-int-master-284c5 ~]# oc describe pv pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc Name: pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc Labels: failure-domain.beta.kubernetes.io/region=us-east-1 failure-domain.beta.kubernetes.io/zone=us-east-1c StorageClass: ebs Status: Bound Claim: dakinitest1/mysql Reclaim Policy: Delete Access Modes: RWO Capacity: 1Gi Message: Source: Type: AWSElasticBlockStore (a Persistent Disk resource in AWS) VolumeID: aws://us-east-1c/vol-811d9a1d FSType: ext4 Partition: 0 ReadOnly: false No events. [root@dev-preview-int-master-284c5 ~]# oc get pods -n dakinitest1 NAME READY STATUS RESTARTS AGE cakephp-mysql-example-1-build 0/1 Completed 0 46s cakephp-mysql-example-1-deploy 1/1 Running 0 25s cakephp-mysql-example-1-hook-pre 0/1 Error 1 23s mysql-1-6jn6q 0/1 ContainerCreating 0 43s mysql-1-deploy 1/1 Running 0 46s [root@dev-preview-int-master-284c5 ~]# oc get events -w -n dakinitest1 LASTSEEN FIRSTSEEN COUNT NAME KIND SUBOBJECT TYPE REASON SOURCE MESSAGE 2016-11-02 23:06:05 +0000 UTC 2016-11-02 23:06:05 +0000 UTC 1 cakephp-mysql-example-1-build Pod Normal Scheduled {default-scheduler } Successfully assigned cakephp-mysql-example-1-build to ip-172-31-12-70.ec2.internal 2016-11-02 23:06:05 +0000 UTC 2016-11-02 23:06:05 +0000 UTC 1 mysql-1-deploy Pod Normal Scheduled {default-scheduler } Successfully assigned mysql-1-deploy to ip-172-31-12-69.ec2.internal 2016-11-02 23:06:05 +0000 UTC 2016-11-02 23:06:05 +0000 UTC 1 mysql DeploymentConfig Normal DeploymentCreated {deploymentconfig-controller } Created new replication controller "mysql-1" for version 1 2016-11-02 23:06:06 +0000 UTC 2016-11-02 23:06:06 +0000 UTC 1 cakephp-mysql-example-1-build Pod spec.containers{sti-build} Normal Pulling {kubelet ip-172-31-12-70.ec2.internal} pulling image "registry.ops.openshift.com/openshift3/ose-sti-builder:v3.4.0.18" 2016-11-02 23:06:06 +0000 UTC 2016-11-02 23:06:06 +0000 UTC 1 cakephp-mysql-example-1-build Pod spec.containers{sti-build} Normal Pulled {kubelet ip-172-31-12-70.ec2.internal} Successfully pulled image "registry.ops.openshift.com/openshift3/ose-sti-builder:v3.4.0.18" 2016-11-02 23:06:06 +0000 UTC 2016-11-02 23:06:06 +0000 UTC 1 mysql-1-deploy Pod spec.containers{deployment} Normal Pulling {kubelet ip-172-31-12-69.ec2.internal} pulling image "registry.ops.openshift.com/openshift3/ose-deployer:v3.4.0.18" 2016-11-02 23:06:07 +0000 UTC 2016-11-02 23:06:07 +0000 UTC 1 mysql-1-deploy Pod spec.containers{deployment} Normal Pulled {kubelet ip-172-31-12-69.ec2.internal} Successfully pulled image "registry.ops.openshift.com/openshift3/ose-deployer:v3.4.0.18" 2016-11-02 23:06:07 +0000 UTC 2016-11-02 23:06:07 +0000 UTC 1 cakephp-mysql-example-1-build Pod spec.containers{sti-build} Normal Started {kubelet ip-172-31-12-70.ec2.internal} Started container with docker id e95741bab170 2016-11-02 23:06:07 +0000 UTC 2016-11-02 23:06:07 +0000 UTC 1 mysql-1-deploy Pod spec.containers{deployment} Normal Started {kubelet ip-172-31-12-69.ec2.internal} Started container with docker id 29d0e3b2f055 2016-11-02 23:06:07 +0000 UTC 2016-11-02 23:06:07 +0000 UTC 1 cakephp-mysql-example-1-build Pod spec.containers{sti-build} Normal Created {kubelet ip-172-31-12-70.ec2.internal} Created container with docker id e95741bab170; Security:[seccomp=unconfined] 2016-11-02 23:06:07 +0000 UTC 2016-11-02 23:06:07 +0000 UTC 1 mysql-1-deploy Pod spec.containers{deployment} Normal Created {kubelet ip-172-31-12-69.ec2.internal} Created container with docker id 29d0e3b2f055; Security:[seccomp=unconfined] 2016-11-02 23:06:08 +0000 UTC 2016-11-02 23:06:08 +0000 UTC 1 mysql-1 ReplicationController Normal SuccessfulCreate {replication-controller } Created pod: mysql-1-6jn6q 2016-11-02 23:06:08 +0000 UTC 2016-11-02 23:06:08 +0000 UTC 1 mysql-1-6jn6q Pod Normal Scheduled {default-scheduler } Successfully assigned mysql-1-6jn6q to ip-172-31-12-71.ec2.internal 2016-11-02 23:06:26 +0000 UTC 2016-11-02 23:06:26 +0000 UTC 1 cakephp-mysql-example DeploymentConfig Normal DeploymentCreated {deploymentconfig-controller } Created new replication controller "cakephp-mysql-example-1" for version 1 2016-11-02 23:06:26 +0000 UTC 2016-11-02 23:06:26 +0000 UTC 1 cakephp-mysql-example-1-deploy Pod Normal Scheduled {default-scheduler } Successfully assigned cakephp-mysql-example-1-deploy to ip-172-31-12-70.ec2.internal 2016-11-02 23:06:27 +0000 UTC 2016-11-02 23:06:27 +0000 UTC 1 cakephp-mysql-example-1-deploy Pod spec.containers{deployment} Normal Pulling {kubelet ip-172-31-12-70.ec2.internal} pulling image "registry.ops.openshift.com/openshift3/ose-deployer:v3.4.0.18" 2016-11-02 23:06:27 +0000 UTC 2016-11-02 23:06:27 +0000 UTC 1 cakephp-mysql-example-1-deploy Pod spec.containers{deployment} Normal Pulled {kubelet ip-172-31-12-70.ec2.internal} Successfully pulled image "registry.ops.openshift.com/openshift3/ose-deployer:v3.4.0.18" 2016-11-02 23:06:28 +0000 UTC 2016-11-02 23:06:28 +0000 UTC 1 cakephp-mysql-example DeploymentConfig Normal Started {cakephp-mysql-example-1-deploy } Running pre-hook ("./migrate-database.sh") for deployment dakinitest1/cakephp-mysql-example-1 2016-11-02 23:06:28 +0000 UTC 2016-11-02 23:06:28 +0000 UTC 1 cakephp-mysql-example-1-hook-pre Pod Normal Scheduled {default-scheduler } Successfully assigned cakephp-mysql-example-1-hook-pre to ip-172-31-12-71.ec2.internal 2016-11-02 23:06:28 +0000 UTC 2016-11-02 23:06:28 +0000 UTC 1 cakephp-mysql-example-1-deploy Pod spec.containers{deployment} Normal Started {kubelet ip-172-31-12-70.ec2.internal} Started container with docker id 9bb6f21d3848 2016-11-02 23:06:28 +0000 UTC 2016-11-02 23:06:28 +0000 UTC 1 cakephp-mysql-example-1-deploy Pod spec.containers{deployment} Normal Created {kubelet ip-172-31-12-70.ec2.internal} Created container with docker id 9bb6f21d3848; Security:[seccomp=unconfined] 2016-11-02 23:06:31 +0000 UTC 2016-11-02 23:06:31 +0000 UTC 1 cakephp-mysql-example-1-hook-pre Pod spec.containers{lifecycle} Normal Created {kubelet ip-172-31-12-71.ec2.internal} Created container with docker id 4f073b6a74d4; Security:[seccomp=unconfined] 2016-11-02 23:06:32 +0000 UTC 2016-11-02 23:06:32 +0000 UTC 1 cakephp-mysql-example-1-hook-pre Pod spec.containers{lifecycle} Normal Started {kubelet ip-172-31-12-71.ec2.internal} Started container with docker id 4f073b6a74d4 2016-11-02 23:06:36 +0000 UTC 2016-11-02 23:06:36 +0000 UTC 1 cakephp-mysql-example-1-hook-pre Pod spec.containers{lifecycle} Normal Created {kubelet ip-172-31-12-71.ec2.internal} Created container with docker id 5ad7245c6223; Security:[seccomp=unconfined] 2016-11-02 23:06:36 +0000 UTC 2016-11-02 23:06:36 +0000 UTC 1 cakephp-mysql-example-1-hook-pre Pod spec.containers{lifecycle} Normal Started {kubelet ip-172-31-12-71.ec2.internal} Started container with docker id 5ad7245c6223 2016-11-02 23:06:40 +0000 UTC 2016-11-02 23:06:08 +0000 UTC 7 mysql-1-6jn6q Pod Warning FailedMount {kubelet ip-172-31-12-71.ec2.internal} MountVolume.SetUp failed for volume "kubernetes.io/aws-ebs/f046c97c-a150-11e6-ab91-0a7e599be118-pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc" (spec.Name: "pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc") pod "f046c97c-a150-11e6-ab91-0a7e599be118" (UID: "f046c97c-a150-11e6-ab91-0a7e599be118") with: mount failed: exit status 32 Mounting arguments: /var/lib/origin/openshift.local.volumes/plugins/kubernetes.io/aws-ebs/mounts/aws/us-east-1c/vol-811d9a1d /var/lib/origin/openshift.local.volumes/pods/f046c97c-a150-11e6-ab91-0a7e599be118/volumes/kubernetes.io~aws-ebs/pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc [bind]error: unable to output the provided object: short write [root@dev-preview-int-master-284c5 ~]# [root@dev-preview-int-master-284c5 ~]# oc get pods -n dakinitest1 NAME READY STATUS RESTARTS AGE cakephp-mysql-example-1-build 0/1 Completed 0 2m cakephp-mysql-example-1-deploy 1/1 Running 0 1m cakephp-mysql-example-1-hook-pre 0/1 Error 4 1m mysql-1-6jn6q 0/1 ContainerCreating 0 2m mysql-1-deploy 1/1 Running 0 2m [root@dev-preview-int-master-284c5 ~]# oc describe pod mysql-1-6jn6q -n dakinitest1 Name: mysql-1-6jn6q Namespace: dakinitest1 Security Policy: restricted Node: ip-172-31-12-71.ec2.internal/172.31.12.71 Start Time: Wed, 02 Nov 2016 23:06:08 +0000 Labels: app=cakephp-mysql-example deployment=mysql-1 deploymentconfig=mysql name=mysql Status: Pending IP: Controllers: ReplicationController/mysql-1 Containers: mysql: Container ID: Image: registry.ops.openshift.com/rhscl/mysql-56-rhel7@sha256:b4f3ea7c53188a73622bed0fd2832cfb2653630c6991ac889526f23aef4f0c5e Image ID: Port: 3306/TCP Limits: cpu: 1 memory: 512Mi Requests: cpu: 60m memory: 307Mi State: Waiting Reason: ContainerCreating Ready: False Restart Count: 0 Liveness: tcp-socket :3306 delay=30s timeout=1s period=10s #success=1 #failure=3 Readiness: exec [/bin/sh -i -c MYSQL_PWD='hoSnRwI7N32S15xr' mysql -h 127.0.0.1 -u cakephp -D default -e 'SELECT 1'] delay=5s timeout=1s period=10s #success=1 #failure=3 Volume Mounts: /var/lib/mysql/data from mysql-data (rw) /var/run/secrets/kubernetes.io/serviceaccount from default-token-gq6pc (ro) Environment Variables: MYSQL_USER: cakephp MYSQL_PASSWORD: hoSnRwI7N32S15xr MYSQL_DATABASE: default Conditions: Type Status Initialized True Ready False PodScheduled True Volumes: mysql-data: Type: PersistentVolumeClaim (a reference to a PersistentVolumeClaim in the same namespace) ClaimName: mysql ReadOnly: false default-token-gq6pc: Type: Secret (a volume populated by a Secret) SecretName: default-token-gq6pc QoS Class: Burstable Tolerations: <none> Events: FirstSeen LastSeen Count From SubobjectPath Type Reason Message --------- -------- ----- ---- ------------- -------- ------ ------- 2m 2m 1 {default-scheduler } Normal Scheduled Successfully assigned mysql-1-6jn6q to ip-172-31-12-71.ec2.internal 24s 24s 1 {kubelet ip-172-31-12-71.ec2.internal} Warning FailedMount Unable to mount volumes for pod "mysql-1-6jn6q_dakinitest1(f046c97c-a150-11e6-ab91-0a7e599be118)": timeout expired waiting for volumes to attach/mount for pod "mysql-1-6jn6q"/"dakinitest1". list of unattached/unmounted volumes=[mysql-data] 24s 24s 1 {kubelet ip-172-31-12-71.ec2.internal} Warning FailedSync Error syncing pod, skipping: timeout expired waiting for volumes to attach/mount for pod "mysql-1-6jn6q"/"dakinitest1". list of unattached/unmounted volumes=[mysql-data] 2m 16s 9 {kubelet ip-172-31-12-71.ec2.internal} Warning FailedMount MountVolume.SetUp failed for volume "kubernetes.io/aws-ebs/f046c97c-a150-11e6-ab91-0a7e599be118-pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc" (spec.Name: "pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc") pod "f046c97c-a150-11e6-ab91-0a7e599be118" (UID: "f046c97c-a150-11e6-ab91-0a7e599be118") with: mount failed: exit status 32 Mounting arguments: /var/lib/origin/openshift.local.volumes/plugins/kubernetes.io/aws-ebs/mounts/aws/us-east-1c/vol-811d9a1d /var/lib/origin/openshift.local.volumes/pods/f046c97c-a150-11e6-ab91-0a7e599be118/volumes/kubernetes.io~aws-ebs/pvc-eea17ddb-a150-11e6-9f67-0a30d6fc46dc [bind] Output: mount: special device /var/lib/origin/openshift.local.volumes/plugins/kubernetes.io/aws-ebs/mounts/aws/us-east-1c/vol-811d9a1d does not exist
I forgot to mention this cluster is running version atomic-openshift-3.4.0.18-1.git.0.ada983f.el7.x86_64
The failure to mount the volume on the node is the same bug here https://bugzilla.redhat.com/show_bug.cgi?id=1379600, it is fixed by https://github.com/openshift/origin/pull/11620 in v3.4.0.19. Please verify. I don't know why 'oc get events -w' stops outputting at that particular place and I could not reproduce. It could be pure coincidence that the output of 'oc get events -w' errors in the middle of that event. I don't see anything special about the event and regardless, it being a storage-related/mount event shouldn't matter, the 'short write' error appears to be a bug in kubectl/oc command.
*** This bug has been marked as a duplicate of bug 1379600 ***