Repository: kubernetes
Issue: gce pd WaitForAttach never returned
Labels: kind/bug,sig/storage,lifecycle/frozen

<!-- This form is for bug reports and feature requests ONLY!

If you're looking for help check [Stack Overflow](https://stackoverflow.com/questions/tagged/kubernetes) and the [troubleshooting guide](https://kubernetes.io/docs/tasks/debug-application-cluster/troubleshooting/).

If this may be security issue, please disclose it privately via https://kubernetes.io/security/.
-->

**Is this a BUG REPORT or FEATURE REQUEST?**:
@kubernetes/sig-storage-bugs 

**What happened**:
Encountered a strange test failure, where WaitForAttach never returned

Test logs: https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/pr-logs/pull/63045/pull-kubernetes-e2e-gce/32404/

The volume got successfully attached to the node:

```
I0425 00:03:50.491024       1 pv_controller.go:1432] volume "pvc-1f70b335-481c-11e8-a540-42010a280002" for claim "e2e-tests-subpath-bhnsz/pvc-c66qg" created
I0425 00:03:50.491047       1 pv_controller.go:1449] provisionClaimOperation [e2e-tests-subpath-bhnsz/pvc-c66qg]: trying to save volume pvc-1f70b335-481c-11e8-a540-42010a280002

I0425 00:03:53.196916       1 reconciler.go:285] attacherDetacher.AttachVolume started for volume "pvc-1f70b335-481c-11e8-a540-42010a280002" (UniqueName: "kubernetes.io/gce-pd/e2e-63045-674b9-dynami-pvc-1f70b335-481c-11e8-a540-42010a280002") from node "e2e-63045-674b9-minion-group-rcbf" 
0425 00:03:58.170436       1 operation_generator.go:332] AttachVolume.Attach succeeded for volume "pvc-1f70b335-481c-11e8-a540-42010a280002" (UniqueName: "kubernetes.io/gce-pd/e2e-63045-674b9-dynami-pvc-1f70b335-481c-11e8-a540-42010a280002") from node "e2e-63045-674b9-minion-group-rcbf" 
I0425 00:03:58.170499       1 actual_state_of_world.go:464] Report volume "kubernetes.io/gce-pd/e2e-63045-674b9-dynami-pvc-1f70b335-481c-11e8-a540-42010a280002" as attached to node "e2e-63045-674b9-minion-group-rcbf"
I0425 00:03:58.172518       1 event.go:218] Event(v1.ObjectReference{Kind:"Pod", Namespace:"e2e-tests-subpath-bhnsz", Name:"pod-subpath-test-gcepdpvc-j2v7", UID:"1f71bc74-481c-11e8-a540-42010a280002", APIVersion:"v1", ResourceVersion:"6789", FieldPath:""}): type: 'Normal' reason: 'SuccessfulAttachVolume' AttachVolume.Attach succeeded for volume "pvc-1f70b335-481c-11e8-a540-42010a280002"
```

Kubelet logs show it detected the attached volume, however WaitForAttach never returned:
```
I0425 00:04:01.880943    1163 operation_generator.go:1170] Controller attach succeeded for volume "pvc-1f70b335-481c-11e8-a540-42010a280002" (UniqueName: "kubernetes.io/gce-pd/e2e-63045-674b9-dynami-pvc-1f70b335-481c-11e8-a540-42010a280002") pod "pod-subpath-test-gcepdpvc-j2v7" (UID: "1f71bc74-481c-11e8-a540-42010a280002") device path: "/dev/disk/by-id/google-e2e-63045-674b9-dynami-pvc-1f70b335-481c-11e8-a540-42010a280002"
I0425 00:04:01.895746    1163 reconciler.go:237] Starting operationExecutor.MountVolume for volume "pvc-1f70b335-481c-11e8-a540-42010a280002" (UniqueName: "kubernetes.io/gce-pd/e2e-63045-674b9-dynami-pvc-1f70b335-481c-11e8-a540-42010a280002") pod "pod-subpath-test-gcepdpvc-j2v7" (UID: "1f71bc74-481c-11e8-a540-42010a280002")
I0425 00:04:01.895856    1163 reconciler.go:252] operationExecutor.MountVolume started for volume "pvc-1f70b335-481c-11e8-a540-42010a280002" (UniqueName: "kubernetes.io/gce-pd/e2e-63045-674b9-dynami-pvc-1f70b335-481c-11e8-a540-42010a280002") pod "pod-subpath-test-gcepdpvc-j2v7" (UID: "1f71bc74-481c-11e8-a540-42010a280002")

0425 00:04:01.895978    1163 operation_generator.go:486] MountVolume.WaitForAttach entering for volume "pvc-1f70b335-481c-11e8-a540-42010a280002" (UniqueName: "kubernetes.io/gce-pd/e2e-63045-674b9-dynami-pvc-1f70b335-481c-11e8-a540-42010a280002") pod "pod-subpath-test-gcepdpvc-j2v7" (UID: "1f71bc74-481c-11e8-a540-42010a280002") DevicePath "/dev/disk/by-id/google-e2e-63045-674b9-dynami-pvc-1f70b335-481c-11e8-a540-42010a280002"


I0425 00:04:01.996191    1163 reconciler.go:237] Starting operationExecutor.MountVolume for volume "pvc-1f70b335-481c-11e8-a540-42010a280002" (UniqueName: "kubernetes.io/gce-pd/e2e-63045-674b9-dynami-pvc-1f70b335-481c-11e8-a540-42010a280002") pod "pod-subpath-test-gcepdpvc-j2v7" (UID: "1f71bc74-481c-11e8-a540-42010a280002")
I0425 00:04:02.096800    1163 reconciler.go:237] Starting operationExecutor.MountVolume for volume "pvc-1f70b335-481c-11e8-a540-42010a280002" (UniqueName: "kubernetes.io/gce-pd/e2e-63045-674b9-dynami-pvc-1f70b335-481c-11e8-a540-42010a280002") pod "pod-subpath-test-gcepdpvc-j2v7" (UID: "1f71bc74-481c-11e8-a540-42010a280002")
...
```