TestCustomPVC test timeout flake

[bparees]

seen in https://openshift-gce-devel.appspot.com/build/origin-ci-test/pr-logs/pull/openshift_cluster-image-registry-operator/222/pull-ci-openshift-cluster-image-registry-operator-master-e2e-aws-operator/1205/

=== RUN   TestCustomPVC
--- FAIL: TestCustomPVC (304.29s)
	pvc_test.go:79: PersistentVolume pv-q4sfdkgprvnr27pz25pfsrqgvfcqt66x766lk8m9z66qj7hczdvswfw4p6675j5j created
	pvc_test.go:79: PersistentVolume pv-qn842l7shqhwnrt6l57k7ckk7d44gkv92n6nzrthwjwmlpnl8j7wm6kl9bc9b9xb created
	pvc_test.go:224: timed out waiting for the condition
	framework.go:44: storageclasses:
		items:
		- metadata:
		    annotations:
		      storageclass.kubernetes.io/is-default-class: "true"
		    creationTimestamp: "2019-02-27T03:08:54Z"
		    labels:
		      cluster.storage.openshift.io/owner-name: cluster-config-v1
		      cluster.storage.openshift.io/owner-namespace: kube-system
		    name: gp2
		    resourceVersion: "12396"
		    selfLink: /apis/storage.k8s.io/v1/storageclasses/gp2
		    uid: 04235027-3a3d-11e9-a148-0a177483df06
		  parameters:
		    type: gp2
		  provisioner: kubernetes.io/aws-ebs
		  reclaimPolicy: Delete
		  volumeBindingMode: WaitForFirstConsumer
		metadata:
		  resourceVersion: "40806"
		  selfLink: /apis/storage.k8s.io/v1/storageclasses
	framework.go:44: persistentvolumes:
		items:
		- metadata:
		    annotations:
		      pv.kubernetes.io/bound-by-controller: "yes"
		    creationTimestamp: "2019-02-27T03:29:30Z"
		    finalizers:
		    - kubernetes.io/pv-protection
		    name: pv-jf95fgm2v5bbzp7z5jxm2mpn2fm8kxgj5pz5r8c66kzmz222v225nr78p5kcwtw4
		    resourceVersion: "37743"
		    selfLink: /api/v1/persistentvolumes/pv-jf95fgm2v5bbzp7z5jxm2mpn2fm8kxgj5pz5r8c66kzmz222v225nr78p5kcwtw4
		    uid: e4d85967-3a3f-11e9-a659-12bbbb61cb90
		  spec:
		    accessModes:
		    - ReadWriteOnce
		    - ReadOnlyMany
		    - ReadWriteMany
		    capacity:
		      storage: 100Gi
		    claimRef:
		      apiVersion: v1
		      kind: PersistentVolumeClaim
		      name: image-registry-storage
		      namespace: openshift-image-registry
		      resourceVersion: "36217"
		      uid: eb3bbf4c-3a3f-11e9-82b8-0a177483df06
		    hostPath:
		      path: /tmp/pv-jf95fgm2v5bbzp7z5jxm2mpn2fm8kxgj5pz5r8c66kzmz222v225nr78p5kcwtw4
		      type: ""
		    persistentVolumeReclaimPolicy: Retain
		    storageClassName: gp2
		  status:
		    phase: Released
		- metadata:
		    creationTimestamp: "2019-02-27T03:29:29Z"
		    finalizers:
		    - kubernetes.io/pv-protection
		    name: pv-k76bz94w9fbsz7n6h65s87c9cw8796h6dphq2rnft7nkwr69tq7qgm62l4ktqcdb
		    resourceVersion: "36055"
		    selfLink: /api/v1/persistentvolumes/pv-k76bz94w9fbsz7n6h65s87c9cw8796h6dphq2rnft7nkwr69tq7qgm62l4ktqcdb
		    uid: e4363455-3a3f-11e9-a659-12bbbb61cb90
		  spec:
		    accessModes:
		    - ReadWriteOnce
		    - ReadOnlyMany
		    - ReadWriteMany
		    capacity:
		      storage: 100Gi
		    hostPath:
		      path: /tmp/pv-k76bz94w9fbsz7n6h65s87c9cw8796h6dphq2rnft7nkwr69tq7qgm62l4ktqcdb
		      type: ""
		    persistentVolumeReclaimPolicy: Retain
		  status:
		    phase: Available
		- metadata:
		    creationTimestamp: "2019-02-27T03:31:07Z"
		    finalizers:
		    - kubernetes.io/pv-protection
		    name: pv-q4sfdkgprvnr27pz25pfsrqgvfcqt66x766lk8m9z66qj7hczdvswfw4p6675j5j
		    resourceVersion: "37818"
		    selfLink: /api/v1/persistentvolumes/pv-q4sfdkgprvnr27pz25pfsrqgvfcqt66x766lk8m9z66qj7hczdvswfw4p6675j5j
		    uid: 1e466d1c-3a40-11e9-a659-12bbbb61cb90
		  spec:
		    accessModes:
		    - ReadWriteOnce
		    - ReadOnlyMany
		    - ReadWriteMany
		    capacity:
		      storage: 100Gi
		    hostPath:
		      path: /tmp/pv-q4sfdkgprvnr27pz25pfsrqgvfcqt66x766lk8m9z66qj7hczdvswfw4p6675j5j
		      type: ""
		    persistentVolumeReclaimPolicy: Retain
		  status:
		    phase: Available
		- metadata:
		    creationTimestamp: "2019-02-27T03:31:08Z"
		    finalizers:
		    - kubernetes.io/pv-protection
		    name: pv-qn842l7shqhwnrt6l57k7ckk7d44gkv92n6nzrthwjwmlpnl8j7wm6kl9bc9b9xb
		    resourceVersion: "37832"
		    selfLink: /api/v1/persistentvolumes/pv-qn842l7shqhwnrt6l57k7ckk7d44gkv92n6nzrthwjwmlpnl8j7wm6kl9bc9b9xb
		    uid: 1ee7f556-3a40-11e9-a659-12bbbb61cb90
		  spec:
		    accessModes:
		    - ReadWriteOnce
		    - ReadOnlyMany
		    - ReadWriteMany
		    capacity:
		      storage: 100Gi
		    hostPath:
		      path: /tmp/pv-qn842l7shqhwnrt6l57k7ckk7d44gkv92n6nzrthwjwmlpnl8j7wm6kl9bc9b9xb
		      type: ""
		    persistentVolumeReclaimPolicy: Retain
		    storageClassName: gp2
		  status:
		    phase: Available
		metadata:
		  resourceVersion: "40806"
		  selfLink: /api/v1/persistentvolumes
	framework.go:44: persistentvolumeclaims:
		items:
		- metadata:
		    creationTimestamp: "2019-02-27T03:31:09Z"
		    finalizers:
		    - kubernetes.io/pvc-protection
		    name: test-custom-pvc
		    namespace: openshift-image-registry
		    resourceVersion: "37842"
		    selfLink: /api/v1/namespaces/openshift-image-registry/persistentvolumeclaims/test-custom-pvc
		    uid: 1f876dd3-3a40-11e9-a659-12bbbb61cb90
		  spec:
		    accessModes:
		    - ReadWriteMany
		    dataSource: null
		    resources:
		      requests:
		        storage: 1Gi
		    storageClassName: gp2
		  status:
		    phase: Pending
		metadata:
		  resourceVersion: "40806"
		  selfLink: /api/v1/namespaces/openshift-image-registry/persistentvolumeclaims
	imageregistry.go:146: uninstalling the image registry...
	imageregistry.go:150: stopping the operator...
	imageregistry.go:154: deleting the image registry resource...

[bparees]

/assign @legionus

[bparees]

I am disabling this test in fe0ec94 so we can unblock our queue. Please fix+reenable the test asap.

[legionus]

@bparees I only can increase timeout. I can not fix it.

[bparees]

@bparees I only can increase timeout. I can not fix it.

can you elaborate on that? What happens when the test flakes? Anyway increasing the timeout is fine if it gets us to 99% passing instead of what we currently have which is around 50% passing.

[legionus]

@bparees We made the PersistentVolumeClaims and we have available PersistentVolume that fits the requirements. Sometimes kube binds them up while waiting, sometimes not. I can not guarantee that after an hour of waiting it will happen. This is out of my control.

[bparees]

@bparees We made the PersistentVolumeClaims and we have available PersistentVolume that fits the requirements. Sometimes kube binds them up while waiting, sometimes not. I can not guarantee that after an hour of waiting it will happen. This is out of my control.

Please talk to the storage team, because that does not make sense to me. If there is an available PV that fulfills the PVC, it should get bound. Why would it not, other than a bug in storage?

Also if you look at the run I pasted, the PVC is reported as "pending" (which i believe means claimed?), yet the test failed.

[legionus]

@bparees "pending" means it is waiting for PV.

[jsafrane]

Storage team here. I don't see anything wrong with your PV/PVC, it should bound in reasonable time (15-20 seconds max).

Can you reproduce it reliably? Can you get kubernetes controller-manager logs with log level 5?

[dmage]

We found the problem:

I0301 12:46:55.356919       1 event.go:221] Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"openshift-image-registry", Name:"test-custom-pvc", UID:"f77a3bf4-3c1f-11e9-a8b2-02f42a92ec4c", APIVersion:"v1", ResourceVersion:"885331", FieldPath:""}): type: 'Normal' reason: 'WaitForFirstConsumer' waiting for first consumer to be created before binding

[bparees]

Nice, any idea how it ever passed then?

[jsafrane]

We changed the default storage class to WaitForFirstConsumer just few days ago. And
ci/prow/e2e-aws tests passed there.