gce pd WaitForAttach never returned

[msau42]

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")
...

[saad-ali]

Weird. MountVolume should not start unless WaitForAttach returns without error.

But it does appear to be triggered multiple times:

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")

And there is no Successfully found attached GCE PD message indicating WaitForAttach completed successfully nor any message indicating it errored. Curious indeed.

Log: https://storage.googleapis.com/kubernetes-jenkins/pr-logs/pull/63045/pull-kubernetes-e2e-gce/32404/artifacts/e2e-63045-674b9-minion-group-rcbf/kubelet.log

[saad-ali]

This flake only appears to happen on Subpath [Volume type: gcePDPVC] should support existing single file test. It would be interesting to compare a good run with a bad run to determine if this is a real issue or a red herring (possible logging issue).

[msau42]

I don't think a logging issue would cause the test to fail due to Mount not happening.

I do see other gce pd tests flaking, but I haven't looked into the others to see if they're the same issue: https://k8s-testgrid.appspot.com/sig-storage#gce

[jingxu97]

I checked a couple of failed tests. Both of them has the log of "MountVolume.WaitForAttach entering for volume ....", but after that, there is no fail or succeed message. It seems like WaitForAttach was hanging. All the following operationExecutor.MountVolume will fail to start because the first operation still exist.
I checked WaitForAttach function in GCE PD attacher, there are some file system calls including filepath.Glob(), maybe this call takes very long time?

[msau42]

Another suspicious operation I see that could block is invoking udevadm here.

I think we probably need to manually try to stress and reproduce this, so we have a chance to login and see where it's stuck.

[saad-ali]

I ran the test [sig-storage] Subpath [Volume type: gcePDPVC] should support existing single file test back to back in a loop for 18 hours without failure.

@msau42 suggests the flake may repro if we run multiple volume tests in parallel. Will try that when I have some time.

[verult]

Ran the tests with the following command:
for i in $(seq 1 500); do GINKGO_PARALLEL=y go run hack/e2e.go -- --test --test_args="--ginkgo.skip=\[Serial\]|\[Disruptive\] --ginkgo.focus=Pod\sDisks|PD --delete-namespace-on-failure=false"; done

A good number of iterations have failed tests, and all of the failures I've seen so far are from Subpath [Volume type: gcePDPVC].

[jingxu97]

@verult thanks for the test. Maybe we can try to add some logs into WaitForAttach() function since that's where we suspect to have problems.

[fejta-bot]

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

[msau42]

/remove-lifecycle stale

We should at least add some logs. Currently we cannot tell the difference between waitForAttach hanged, or the device path never appeared.

[fejta-bot]

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

[msau42]

Logs are being added here: #68022

We also know of an instance where format could hang if the disk got detached during the operation: #71145.

[msau42]

/remove-lifecycle stale
/lifecycle frozen