Fix devicePath is empty while WaitForAttach in StatefulSets

[wph95]

What this PR does / why we need it:
#67342
In some cases, the volumemanager is in an abnormal state, falling into a dead loop
Verify that the bug was fixed by unit testing #68169

Which issue(s) this PR fixes (optional, in fixes #<issue number>(, fixes #<issue_number>, ...) format, will close the issue(s) when PR gets merged):
Fixes #67342

Special notes for your reviewer:

Release note:
NONE

[k8s-ci-robot]

@wph95: Adding the "do-not-merge/release-note-label-needed" label because no release-note block was detected, please follow our release note process to remove it.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[ddebroy]

/ok-to-test

[ddebroy]

@wph95 can you please add the unit-test you wanted to add in #68169 as part of this PR so that both the unit-test and the proposed fix can go in together?

[ddebroy]

/retest

[ddebroy]

/retest

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: WPH95
To fully approve this pull request, please assign additional approvers.
We suggest the following additional approver: saad-ali

If they are not already assigned, you can assign the PR to them by writing /assign @saad-ali in a comment when ready.

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

• pkg/kubelet/volumemanager/OWNERS
• pkg/volume/testing/OWNERS

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

[wph95]

use this PR

=== RUN   Test_Run_DeviceUnMountDelay
E0921 20:59:39.824902   14530 reconciler.go:374] Cannot get volumes from disk open fake-dir: no such file or directory
E0921 20:59:39.824930   14530 actual_state_of_world.go:309] MarkVolumeAsAttached
E0921 20:59:40.325823   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 20:59:40.825801856 +0800 CST m=+10.527209102 (durationBeforeRetry 500ms). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:40.325864   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 20:59:41.325837721 +0800 CST m=+11.027244966 (durationBeforeRetry 1s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:40.825556   14530 actual_state_of_world.go:357] MarkDeviceAsMounted
E0921 20:59:40.827233   14530 actual_state_of_world.go:328] MarkVolumeAsMounted
E0921 20:59:41.325993   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 20:59:42.325971282 +0800 CST m=+12.027372609 (durationBeforeRetry 1s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:41.326019   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 20:59:43.326007382 +0800 CST m=+13.027408708 (durationBeforeRetry 2s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:41.827324   14530 actual_state_of_world.go:351] MarkVolumeAsUnmounted
E0921 20:59:42.326118   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 20:59:44.32609703 +0800 CST m=+14.027492438 (durationBeforeRetry 2s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:43.326811   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 20:59:47.326787776 +0800 CST m=+17.028177262 (durationBeforeRetry 4s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:44.326763   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 20:59:48.326742982 +0800 CST m=+18.028126550 (durationBeforeRetry 4s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:46.826328   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 20:59:47.326307229 +0800 CST m=+17.027676005 (durationBeforeRetry 500ms). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:47.327192   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 20:59:55.327168175 +0800 CST m=+25.028533987 (durationBeforeRetry 8s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:47.826753   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 20:59:48.826732132 +0800 CST m=+18.528094988 (durationBeforeRetry 1s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:48.328173   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 20:59:56.328148972 +0800 CST m=+26.029508860 (durationBeforeRetry 8s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:48.827522   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 20:59:50.827492225 +0800 CST m=+20.528849158 (durationBeforeRetry 2s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:50.827757   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 20:59:54.827734731 +0800 CST m=+24.529079827 (durationBeforeRetry 4s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:52.826158   14530 actual_state_of_world.go:363] MarkDeviceAsUnmounted
E0921 20:59:52.827976   14530 actual_state_of_world.go:315] MarkVolumeAsDetached
E0921 20:59:52.828052   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 20:59:53.328032956 +0800 CST m=+23.029366214 (durationBeforeRetry 500ms). Error: "MountVolume.WaitForAttach failed for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") : DevicePath is empty"
E0921 20:59:53.828197   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 20:59:54.828174463 +0800 CST m=+24.529501802 (durationBeforeRetry 1s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:54.828313   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 21:00:02.828292499 +0800 CST m=+32.529613920 (durationBeforeRetry 8s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:54.828351   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 20:59:56.828326181 +0800 CST m=+26.529647602 (durationBeforeRetry 2s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:55.330550   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 21:00:11.330528359 +0800 CST m=+41.031846808 (durationBeforeRetry 16s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:56.330764   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 21:00:12.330748363 +0800 CST m=+42.032060892 (durationBeforeRetry 16s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 20:59:56.828669   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 21:00:00.828647152 +0800 CST m=+30.529956735 (durationBeforeRetry 4s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 21:00:00.829715   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 21:00:08.829683104 +0800 CST m=+38.530969009 (durationBeforeRetry 8s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 21:00:02.830198   14530 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 21:00:18.830158896 +0800 CST m=+48.531432962 (durationBeforeRetry 16s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
--- PASS: Test_Run_DeviceUnMountDelay (26.00s)

without this PR

E0921 21:04:57.388900   15457 reconciler.go:373] Cannot get volumes from disk open fake-dir: no such file or directory
E0921 21:04:57.387957   15457 actual_state_of_world.go:309] MarkVolumeAsAttached
E0921 21:04:58.393853   15457 actual_state_of_world.go:357] MarkDeviceAsMounted
E0921 21:04:58.394009   15457 actual_state_of_world.go:328] MarkVolumeAsMounted
E0921 21:05:00.398466   15457 actual_state_of_world.go:351] MarkVolumeAsUnmounted
E0921 21:05:04.404383   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 21:05:04.904325269 +0800 CST m=+7.548110120 (durationBeforeRetry 500ms). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 21:05:05.404498   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 21:05:06.404473051 +0800 CST m=+9.048251983 (durationBeforeRetry 1s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 21:05:06.408189   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 21:05:08.408144969 +0800 CST m=+11.051917961 (durationBeforeRetry 2s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 21:05:08.414468   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 21:05:12.414449988 +0800 CST m=+15.058211107 (durationBeforeRetry 4s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 21:05:11.404756   15457 actual_state_of_world.go:363] MarkDeviceAsUnmounted
E0921 21:05:11.426244   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 21:05:11.926230075 +0800 CST m=+14.569973370 (durationBeforeRetry 500ms). Error: "MountVolume.WaitForAttach failed for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") : DevicePath is empty"
E0921 21:05:12.428221   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 21:05:20.428202157 +0800 CST m=+23.071939522 (durationBeforeRetry 8s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 21:05:12.428288   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 21:05:13.428279206 +0800 CST m=+16.072016571 (durationBeforeRetry 1s). Error: "MountVolume.WaitForAttach failed for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") : DevicePath is empty"
E0921 21:05:13.429873   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 21:05:15.429857202 +0800 CST m=+18.073588639 (durationBeforeRetry 2s). Error: "MountVolume.WaitForAttach failed for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") : DevicePath is empty"
E0921 21:05:15.433047   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 21:05:19.433024934 +0800 CST m=+22.076744517 (durationBeforeRetry 4s). Error: "MountVolume.WaitForAttach failed for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") : DevicePath is empty"
E0921 21:05:19.441365   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 21:05:27.441346452 +0800 CST m=+30.085042313 (durationBeforeRetry 8s). Error: "MountVolume.WaitForAttach failed for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") : DevicePath is empty"
E0921 21:05:20.445694   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 21:05:36.445665464 +0800 CST m=+39.089355382 (durationBeforeRetry 16s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 21:05:27.472873   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 21:05:43.472853431 +0800 CST m=+46.116501762 (durationBeforeRetry 16s). Error: "MountVolume.WaitForAttach failed for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") : DevicePath is empty"
E0921 21:05:36.501999   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/pv\"" failed. No retries permitted until 2018-09-21 21:06:08.501981304 +0800 CST m=+71.145576200 (durationBeforeRetry 32s). Error: "Volume has not been added to the list of VolumesInUse in the node's volume status for volume \"pv\" (UniqueName: \"fake-plugin/pv\") pod \"pod1\" (UID: \"pod1uid\") "
E0921 21:05:43.519032   15457 nestedpendingoperations.go:267] Operation for "\"fake-plugin/fake-device1\"" failed. No retries permitted until 2018-09-21 21:06:15.519005842 +0800 CST m=+78.162559212 (durationBeforeRetry 32s). Error: "MountVolume.WaitForAttach failed for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") pod \"pod1\" (UID: \"pod1uid\") : DevicePath is empty"
--- FAIL: Test_Run_DeviceUnMountDelay (66.52s)```

[ddebroy]

/retest

[ddebroy]

This PR seems to consistently trigger the above test failure which is a bit strange. They appear to be infra issues at first glance but a couple of PRs I am also tracking are passing the above fine.

[wph95]

/retest

[ddebroy]

/retest

[k8s-ci-robot]

@wph95: The following tests failed, say /retest to rerun them all:

Test name	Commit	Details	Rerun command
pull-kubernetes-local-e2e-containerized	7b1e632	link	/test pull-kubernetes-local-e2e-containerized
pull-kubernetes-e2e-kops-aws	7b1e632	link	/test pull-kubernetes-e2e-kops-aws
pull-kubernetes-e2e-gce	7b1e632	link	/test pull-kubernetes-e2e-gce
pull-kubernetes-e2e-gce-device-plugin-gpu	7b1e632	link	/test pull-kubernetes-e2e-gce-device-plugin-gpu
pull-kubernetes-node-e2e	7b1e632	link	/test pull-kubernetes-node-e2e
pull-kubernetes-kubemark-e2e-gce-big	7b1e632	link	/test pull-kubernetes-kubemark-e2e-gce-big
pull-kubernetes-e2e-gce-100-performance	7b1e632	link	/test pull-kubernetes-e2e-gce-100-performance

Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

[k8s-ci-robot]

@wph95: PR needs rebase.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[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

[fejta-bot]

Stale issues rot after 30d of inactivity.
Mark the issue as fresh with /remove-lifecycle rotten.
Rotten issues close after an additional 30d of inactivity.

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 rotten

[fejta-bot]

Rotten issues close after 30d of inactivity.
Reopen the issue with /reopen.
Mark the issue as fresh with /remove-lifecycle rotten.

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

[k8s-ci-robot]

Thanks for your pull request. Before we can look at your pull request, you'll need to sign a Contributor License Agreement (CLA).

📝 Please follow instructions at https://git.k8s.io/community/CLA.md#the-contributor-license-agreement to sign the CLA.

It may take a couple minutes for the CLA signature to be fully registered; after that, please reply here with a new comment and we'll verify. Thanks.

---

• If you've already signed a CLA, it's possible we don't have your GitHub username or you're using a different email address. Check your existing CLA data and verify that your email is set on your git commits.
• If you signed the CLA as a corporation, please sign in with your organization's credentials at https://identity.linuxfoundation.org/projects/cncf to be authorized.
• If you have done the above and are still having issues with the CLA being reported as unsigned, please email the CNCF helpdesk: helpdesk@rt.linuxfoundation.org

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

[k8s-ci-robot]

@fejta-bot: Closed this PR.

In response to this:

Rotten issues close after 30d of inactivity.
Reopen the issue with /reopen.
Mark the issue as fresh with /remove-lifecycle rotten.

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

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.