Fix NodeStageVolume returning prematurely

[dkoshkin]

Is this a bug fix or adding new feature?
Bug fix

What is this PR about? / Why do we need it?
PR #163 introduced a bug where NodeStageVolume would return prematurely.
This was only evident when using HDD volumes because the formatting takes longer than the default 15 seconds, unfortunately when I tested the change for #163 (comment) I only ran the sample app with a SSD and did not catch this bug :(.

When I ran the remaining e2e tests, all HDD volume tests were failing to delete EBS volumes because they were still being formatted.

Below log, shows that NodeStageVolume: volume="vol-0504e2cf8285d7bcc" operation is already in progress after 15 seconds(default retry period) but because it doesn't return an error the next operation NodePublishVolume is called.

I0109 21:47:06.265099       1 node.go:55] NodeStageVolume: called with args {VolumeId:vol-0504e2cf8285d7bcc PublishContext:map[devicePath:/dev/xvdbb] StagingTargetPath:/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-03a7e5f0-1458-11e9-8557-2acd0797fa41/globalmount VolumeCapability:mount:<fs_type:"ext2" > access_mode:<mode:SINGLE_NODE_WRITER >  Secrets:map[] VolumeContext:map[storage.kubernetes.io/csiProvisionerIdentity:1547070289563-8081-ebs.csi.aws.com fsType:ext2] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0109 21:47:06.265186       1 node.go:77] NodeStageVolume: volume="vol-0504e2cf8285d7bcc" operation is already in progress
I0109 21:47:06.267684       1 node.go:248] NodeGetCapabilities: called with args {XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0109 21:47:06.273550       1 node.go:162] NodePublishVolume: called with args {VolumeId:vol-0504e2cf8285d7bcc PublishContext:map[devicePath:/dev/xvdbb] StagingTargetPath:/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-03a7e5f0-1458-11e9-8557-2acd0797fa41/globalmount TargetPath:/var/lib/kubelet/pods/08d7000f-1458-11e9-8557-2acd0797fa41/volumes/kubernetes.io~csi/pvc-03a7e5f0-1458-11e9-8557-2acd0797fa41/mount VolumeCapability:mount:<fs_type:"ext2" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[fsType:ext2 storage.kubernetes.io/csiProvisionerIdentity:1547070289563-8081-ebs.csi.aws.com] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}
I0109 21:47:06.273600       1 node.go:208] NodePublishVolume: creating dir /var/lib/kubelet/pods/08d7000f-1458-11e9-8557-2acd0797fa41/volumes/kubernetes.io~csi/pvc-03a7e5f0-1458-11e9-8557-2acd0797fa41/mount
I0109 21:47:06.273632       1 node.go:213] NodePublishVolume: mounting /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-03a7e5f0-1458-11e9-8557-2acd0797fa41/globalmount at /var/lib/kubelet/pods/08d7000f-1458-11e9-8557-2acd0797fa41/volumes/kubernetes.io~csi/pvc-03a7e5f0-1458-11e9-8557-2acd0797fa41/mount
I0109 21:47:06.273666       1 mount_linux.go:146] Mounting cmd (mount) with arguments ([-t ext4 -o bind /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-03a7e5f0-1458-11e9-8557-2acd0797fa41/globalmount /var/lib/kubelet/pods/08d7000f-1458-11e9-8557-2acd0797fa41/volumes/kubernetes.io~csi/pvc-03a7e5f0-1458-11e9-8557-2acd0797fa41/mount])
I0109 21:47:06.283116       1 mount_linux.go:146] Mounting cmd (mount) with arguments ([-t ext4 -o bind,remount /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-03a7e5f0-1458-11e9-8557-2acd0797fa41/globalmount /var/lib/kubelet/pods/08d7000f-1458-11e9-8557-2acd0797fa41/volumes/kubernetes.io~csi/pvc-03a7e5f0-1458-11e9-8557-2acd0797fa41/mount])
I0109 21:48:26.498530       1 mount_linux.go:492] Disk successfully formatted (mkfs): ext2 - /dev/xvdbb /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-03a7e5f0-1458-11e9-8557-2acd0797fa41/globalmount
I0109 21:48:26.498575       1 mount_linux.go:146] Mounting cmd (mount) with arguments ([-t ext2 -o defaults /dev/xvdbb /var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-03a7e5f0-1458-11e9-8557-2acd0797fa41/globalmount])
I0109 21:48:26.527167       1 node.go:81] NodeStageVolume: volume="vol-0504e2cf8285d7bcc" operation finished

What testing is done?
Locally ran all e2e tests

[k8s-ci-robot]

Hi @dkoshkin. Thanks for your PR.

I'm waiting for a kubernetes-sigs or kubernetes member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

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.

[coveralls]

Pull Request Test Coverage Report for Build 324

• 0 of 2 (0.0%) changed or added relevant lines in 1 file are covered.
• No unchanged relevant lines lost coverage.
• Overall coverage remained the same at 50.931%

---

Changes Missing Coverage	Covered Lines	Changed/Added Lines	%
pkg/driver/node.go	0	2	0.0%

Totals
Change from base Build 323:	0.0%
Covered Lines:	602
Relevant Lines:	1182

---

💛 - Coveralls

[leakingtapan]

/ok-to-test

[dkoshkin]

It would be great to get this merged in and have a new latest image built with this change, I want to do some more manual/automated testing.

[leakingtapan]

Good catch.

/lgtm
/approve

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: dkoshkin, leakingtapan

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:

• OWNERS [leakingtapan]

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