This job view page is being replaced by Spyglass soon. Check out the new job view.
ResultFAILURE
Tests 3 failed / 1938 succeeded
Started2021-06-24 08:48
Elapsed30m38s
Revisionrelease-1.20

Test Failures


//pkg/controller/volume/attachdetach/go_default_test:run_1_of_2 0.00s

bazel test //pkg/controller/volume/attachdetach/go_default_test:run_1_of_2
exec ${PAGER:-/usr/bin/less} "$0" || exit 1
Executing tests from //pkg/controller/volume/attachdetach:go_default_test
-----------------------------------------------------------------------------
I0624 09:06:24.071372  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:24.172506  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:24.183483  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:24.183857  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:24.183986  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:24.184955  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:24.185037  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:24.185148  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:24.186322  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:24.186428  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:24.186508  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:24.187857  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:24.187921  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:24.187995  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:24.189283  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:24.189374  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:24.189453  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:24.189667  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:24.190530  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:24.191017  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:24.191165  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:24.191268  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:24.191390  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:24.191494  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:26.178382  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:26.283681  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:26.290294  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:26.290482  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:26.290616  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:26.296397  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:26.297905  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:26.299244  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:26.300636  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:26.300934  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:26.301178  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:06:26.301580  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:06:26.301887  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:26.301976  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:26.302215  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:26.302311  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:26.302509  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:26.302598  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:26.302815  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:26.302904  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:26.303627  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:26.304273  174704 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0624 09:06:26.304509  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:26.304822  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:26.305103  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:26.305596  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:26.305775  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:28.288649  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:28.396161  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:28.403792  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:28.404006  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:28.404167  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:28.405513  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:28.405633  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:28.405823  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:28.407319  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:28.407422  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:28.407594  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:28.409120  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:28.409265  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:28.408954  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:28.412359  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:28.412527  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:28.412681  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:28.412972  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:06:28.413540  174704 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0624 09:06:28.413698  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:06:28.414010  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:28.415106  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:28.415514  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:28.415720  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:28.415919  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:28.416114  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:28.416283  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:30.401630  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:30.504178  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:30.511670  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:30.511880  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:30.512010  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:30.512990  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:30.514389  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:30.515711  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:30.517345  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:30.517654  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:30.517900  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName3" (UniqueName: "kubernetes.io/testPlugin/volumeName3") from node "mynode-1" 
I0624 09:06:30.518152  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:06:30.518563  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:06:30.518835  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:30.518931  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:30.519590  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:30.519729  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:30.520056  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:30.520168  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:30.520281  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName3" (UniqueName: "kubernetes.io/testPlugin/volumeName3") from node "mynode-1" 
I0624 09:06:30.520428  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:30.520555  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:30.520944  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:30.521133  174704 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0624 09:06:30.521290  174704 event.go:291] "Event occurred" object="mynamespace/newpod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName3\" "
I0624 09:06:30.521439  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:30.521609  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:30.524838  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:30.525745  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:30.526046  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:32.510717  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:32.614521  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:32.622166  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:32.622300  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:32.622502  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:32.623990  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:32.624103  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:32.624343  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:32.625685  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:32.625785  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:32.626078  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:32.627480  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:32.628689  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:32.628816  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:32.628904  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:32.628951  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:32.629088  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "vol1" (UniqueName: "kubernetes.io/testPlugin/vol1") from node "mynode-1" 
I0624 09:06:32.629459  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "vol1" (UniqueName: "kubernetes.io/testPlugin/vol1") from node "mynode-1" 
I0624 09:06:32.629717  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:32.629854  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:32.629922  174704 event.go:291] "Event occurred" object="mynamespace/pod1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"vol1\" "
I0624 09:06:32.630125  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:32.630269  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:32.630330  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:32.630375  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:32.630528  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:32.630721  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:33.623986  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:33.724589  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:33.731296  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:33.731479  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:33.731616  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:33.732596  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:33.732755  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:33.732869  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:33.733814  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:33.733913  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:33.734029  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:33.735055  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:33.735193  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:33.735323  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:33.736374  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:33.736463  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:33.736602  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:33.736665  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:33.737547  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:33.737733  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:33.737915  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:33.738153  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:33.738337  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:33.738504  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:34.644603  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:06:34.645014  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:06:34.645132  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:06:34.729903  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:34.830488  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:34.836058  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:34.836342  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:34.836490  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:34.836950  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:34.837142  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:34.837270  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:34.837847  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:34.838064  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:34.838198  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:34.838846  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:34.838943  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:34.839077  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:34.843121  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:34.843278  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:34.843448  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:34.843550  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:34.844746  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:34.845640  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:34.845865  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:34.846048  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:34.846238  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:34.846411  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:35.748312  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:06:35.748523  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:06:35.748655  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:06:35.836098  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:35.936654  174704 shared_informer.go:247] Caches are synced for attach detach 
W0624 09:06:35.942130  174704 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.VolumeAttachment ended with: very short watch: k8s.io/client-go/informers/factory.go:134: Unexpected watch close - watch lasted less than a second and no items received
I0624 09:06:35.945375  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
E0624 09:06:35.947409  174704 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" : no volume plugin matched name: kubernetes.io/testPlugin
E0624 09:06:35.948674  174704 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" : no volume plugin matched name: kubernetes.io/testPlugin
E0624 09:06:35.949943  174704 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" : no volume plugin matched name: kubernetes.io/testPlugin
E0624 09:06:35.951191  174704 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" : no volume plugin matched name: kubernetes.io/testPlugin
I0624 09:06:35.952476  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/vol1") on node "mynode-1" 
I0624 09:06:35.952683  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/vol1") on node "mynode-1" 
E0624 09:06:35.952989  174704 csi_attacher.go:455] [attachment.ID=csi-77bd5b88d32d48e5a31f0073211a7dd54ed0066f008e12364f4b6ecb61dc7370] watch channel had been closed
E0624 09:06:35.953503  174704 csi_attacher.go:455] [attachment.ID=csi-4ff6fd4b10c02f804e7435dffeb62054338b590749cdaacf18e198ee0ab6dd66] watch channel had been closed
==================
WARNING: DATA RACE
Read at 0x00c00052c3d8 by goroutine 82:
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/testing.CreateTestClient.func6()
      pkg/controller/volume/attachdetach/testing/testvolumespec.go:179 +0x104
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*SimpleReactor).React()
      staging/src/k8s.io/client-go/testing/fixture.go:521 +0x68
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*Fake).Invokes()
      staging/src/k8s.io/client-go/testing/fake.go:141 +0x327
  k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes/typed/storage/v1/fake.(*FakeVolumeAttachments).List()
      staging/src/k8s.io/client-go/kubernetes/typed/storage/v1/fake/fake_volumeattachment.go:55 +0x273
  k8s.io/kubernetes/vendor/k8s.io/client-go/informers/storage/v1.NewFilteredVolumeAttachmentInformer.func1()
      staging/src/k8s.io/client-go/informers/storage/v1/volumeattachment.go:64 +0x23c
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*ListWatch).List()
      staging/src/k8s.io/client-go/tools/cache/listwatch.go:106 +0x97
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func1.1.2()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:277 +0xf4
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/pager.SimplePageFunc.func1()
      staging/src/k8s.io/client-go/tools/pager/pager.go:40 +0x97
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/pager.(*ListPager).List()
      staging/src/k8s.io/client-go/tools/pager/pager.go:91 +0x1e2
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func1.1()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:302 +0x2b7

Previous write at 0x00c00052c3d8 by goroutine 182:
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/testing.CreateTestClient.func7()
      pkg/controller/volume/attachdetach/testing/testvolumespec.go:185 +0x207
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*SimpleReactor).React()
      staging/src/k8s.io/client-go/testing/fixture.go:521 +0x68
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*Fake).Invokes()
      staging/src/k8s.io/client-go/testing/fake.go:141 +0x327
I0624 09:06:35.954305  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" : volume attachment watch channel had been closed"
  k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes/typed/storage/v1/fake.(*FakeVolumeAttachments).Create()
      staging/src/k8s.io/client-go/kubernetes/typed/storage/v1/fake/fake_volumeattachment.go:82 +0x246
  k8s.io/kubernetes/pkg/volume/csi.(*csiAttacher).Attach()
      pkg/volume/csi/csi_attacher.go:109 +0x5f3
  k8s.io/kubernetes/pkg/volume/util/operationexecutor.(*operationGenerator).GenerateAttachVolumeFunc.func1()
      pkg/volume/util/operationexecutor/operation_generator.go:335 +0x275
  k8s.io/kubernetes/pkg/volume/util/types.(*GeneratedOperations).Run()
      pkg/volume/util/types/types.go:54 +0x142
  k8s.io/kubernetes/pkg/volume/util/nestedpendingoperations.(*nestedPendingOperations).Run.func1()
      pkg/volume/util/nestedpendingoperations/nestedpendingoperations.go:183 +0x159

Goroutine 82 (running) created at:
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func1()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:268 +0x36f
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:360 +0x2e4
I0624 09:06:35.954367  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "pd.csi.storage.gke.io-pdName" (UniqueName: "kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/pdName") from node "mynode" 
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).Run.func1()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:221 +0x53
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:155 +0x75
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:156 +0xba
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).Run()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:220 +0x2c4
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).Run-fm()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:218 +0x4b
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.(*Group).StartWithChannel.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:56 +0x45
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:73 +0x6d

Goroutine 182 (running) created at:
  k8s.io/kubernetes/pkg/volume/util/nestedpendingoperations.(*nestedPendingOperations).Run()
      pkg/volume/util/nestedpendingoperations/nestedpendingoperations.go:178 +0x5b2
  k8s.io/kubernetes/pkg/volume/util/operationexecutor.(*operationExecutor).AttachVolume()
      pkg/volume/util/operationexecutor/operation_executor.go:675 +0x348
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).attachDesiredVolumes()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:293 +0x639
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).reconcile()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:233 +0x1b9
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).reconciliationLoopFunc.func1()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:110 +0x5e
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:155 +0x75
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:156 +0xba
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:133 +0x114
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.Until()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:90 +0x89
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).Run()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:101 +0x2f
==================
I0624 09:06:35.954651  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" : volume attachment watch channel had been closed"
E0624 09:06:35.954678  174704 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/vol1 podName: nodeName:mynode-1}" failed. No retries permitted until 2021-06-24 09:06:36.454277904 +0000 UTC m=+12.533888394 (durationBeforeRetry 500ms). Error: "DetachVolume.Detach failed for volume \"nil\" (UniqueName: \"kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/vol1\") on node \"mynode-1\" : volume attachment watch channel had been closed"
I0624 09:06:35.955041  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" : volume attachment watch channel had been closed"
I0624 09:06:35.955286  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" : volume attachment watch channel had been closed"
E0624 09:06:35.955361  174704 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/pdName podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:06:36.455105986 +0000 UTC m=+12.534716487 (durationBeforeRetry 500ms). Error: "AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" (UniqueName: \"kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/pdName\") from node \"mynode\" : volume attachment watch channel had been closed"
==================
WARNING: DATA RACE
Read at 0x00c00099f368 by I0624 09:06:35.955488  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" : volume attachment watch channel had been closed"
goroutine 82:
  runtime.slicecopy()
      GOROOT/src/runtime/slice.go:246 +0x0
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/testing.CreateTestClient.func6()
      pkg/controller/volume/attachdetach/testing/testvolumespec.go:179 +0x184
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*SimpleReactor).React()
      staging/src/k8s.io/client-go/testing/fixture.go:521 +0x68
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*Fake).Invokes()
      staging/src/k8s.io/client-go/testing/fake.go:141 +0x327
  k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes/typed/storage/v1/fake.(*FakeVolumeAttachments).List()
      staging/src/k8s.io/client-go/kubernetes/typed/storage/v1/fake/fake_volumeattachment.go:55 +0x273
  k8s.io/kubernetes/vendor/k8s.io/client-go/informers/storage/v1.NewFilteredVolumeAttachmentInformer.func1()
      staging/src/k8s.io/client-go/informers/storage/v1/volumeattachment.go:64 +0x23c
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*ListWatch).List()
      staging/src/k8s.io/client-go/tools/cache/listwatch.go:106 +0x97
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func1.1.2()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:277 +0xf4
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/pager.SimplePageFunc.func1()
      staging/src/k8s.io/client-go/tools/pager/pager.go:40 +0x97
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/pager.(*ListPager).List()
      staging/src/k8s.io/client-go/tools/pager/pager.go:91 +0x1e2
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func1.1()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:302 +0x2b7

Previous write at 0x00c00099f368 by goroutine 182:
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/testing.CreateTestClient.func7()
      pkg/controller/volume/attachdetach/testing/testvolumespec.go:185 +0x184
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*SimpleReactor).React()
      staging/src/k8s.io/client-go/testing/fixture.go:521 +0x68
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*Fake).Invokes()
      staging/src/k8s.io/client-go/testing/fake.go:141 +0x327
  k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes/typed/storage/v1/fake.(*FakeVolumeAttachments).Create()
      staging/src/k8s.io/client-go/kubernetes/typed/storage/v1/fake/fake_volumeattachment.go:82 +0x246
  k8s.io/kubernetes/pkg/volume/csi.(*csiAttacher).Attach()
      pkg/volume/csi/csi_attacher.go:109 +0x5f3
  k8s.io/kubernetes/pkg/volume/util/operationexecutor.(*operationGenerator).GenerateAttachVolumeFunc.func1()
      pkg/volume/util/operationexecutor/operation_generator.go:335 +0x275
  k8s.io/kubernetes/pkg/volume/util/types.(*GeneratedOperations).Run()
      pkg/volume/util/types/types.go:54 +0x142
  k8s.io/kubernetes/pkg/volume/util/nestedpendingoperations.(*nestedPendingOperations).Run.func1()
      pkg/volume/util/nestedpendingoperations/nestedpendingoperations.go:183 +0x159

Goroutine 82 (running) created at:
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func1()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:268 +0x36f
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:360 +0x2e4
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).Run.func1()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:221 +0x53
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:155 +0x75
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:156 +0xba
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).Run()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:220 +0x2c4
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).Run-fm()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:218 +0x4b
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.(*Group).StartWithChannel.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:56 +0x45
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:73 +0x6d

Goroutine 182 (running) created at:
  k8s.io/kubernetes/pkg/volume/util/nestedpendingoperations.(*nestedPendingOperations).Run()
      pkg/volume/util/nestedpendingoperations/nestedpendingoperations.go:178 +0x5b2
  k8s.io/kubernetes/pkg/volume/util/operationexecutor.(*operationExecutor).AttachVolume()
      pkg/volume/util/operationexecutor/operation_executor.go:675 +0x348
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).attachDesiredVolumes()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:293 +0x639
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).reconcile()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:233 +0x1b9
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).reconciliationLoopFunc.func1()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:110 +0x5e
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:155 +0x75
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:156 +0xba
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:133 +0x114
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.Until()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:90 +0x89
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).Run()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:101 +0x2f
==================
I0624 09:06:36.045945  174704 shared_informer.go:247] Caches are synced for attach detach 
W0624 09:06:36.046287  174704 attach_detach_controller.go:710] Skipping the va as its pvName is nil, va.Name: "csi-4ff6fd4b10c02f804e7435dffeb62054338b590749cdaacf18e198ee0ab6dd66", nodeName: "mynode"
W0624 09:06:36.048112  174704 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.Node ended with: very short watch: k8s.io/client-go/informers/factory.go:134: Unexpected watch close - watch lasted less than a second and no items received
--- FAIL: Test_ADC_VolumeAttachmentRecovery (3.54s)
    --- FAIL: Test_ADC_VolumeAttachmentRecovery/Deleted_Pod_with_migrated_PV (0.11s)
        testing.go:1038: race detected during execution of test
    testing.go:1038: race detected during execution of test
FAIL

				from junit_bazel.xml

Filter through log files | View test history on testgrid


//pkg/controller/volume/attachdetach/go_default_test:run_1_of_2 0.00s

bazel test //pkg/controller/volume/attachdetach/go_default_test:run_1_of_2
exec ${PAGER:-/usr/bin/less} "$0" || exit 1
Executing tests from //pkg/controller/volume/attachdetach:go_default_test
-----------------------------------------------------------------------------
I0624 09:06:24.071372  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:24.172506  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:24.183483  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:24.183857  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:24.183986  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:24.184955  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:24.185037  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:24.185148  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:24.186322  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:24.186428  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:24.186508  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:24.187857  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:24.187921  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:24.187995  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:24.189283  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:24.189374  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:24.189453  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:24.189667  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:24.190530  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:24.191017  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:24.191165  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:24.191268  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:24.191390  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:24.191494  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:26.178382  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:26.283681  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:26.290294  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:26.290482  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:26.290616  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:26.296397  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:26.297905  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:26.299244  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:26.300636  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:26.300934  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:26.301178  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:06:26.301580  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:06:26.301887  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:26.301976  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:26.302215  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:26.302311  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:26.302509  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:26.302598  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:26.302815  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:26.302904  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:26.303627  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:26.304273  174704 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0624 09:06:26.304509  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:26.304822  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:26.305103  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:26.305596  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:26.305775  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:28.288649  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:28.396161  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:28.403792  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:28.404006  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:28.404167  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:28.405513  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:28.405633  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:28.405823  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:28.407319  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:28.407422  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:28.407594  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:28.409120  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:28.409265  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:28.408954  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:28.412359  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:28.412527  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:28.412681  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:28.412972  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:06:28.413540  174704 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0624 09:06:28.413698  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:06:28.414010  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:28.415106  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:28.415514  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:28.415720  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:28.415919  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:28.416114  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:28.416283  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:30.401630  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:30.504178  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:30.511670  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:30.511880  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:30.512010  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:30.512990  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:30.514389  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:30.515711  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:30.517345  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:30.517654  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:30.517900  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName3" (UniqueName: "kubernetes.io/testPlugin/volumeName3") from node "mynode-1" 
I0624 09:06:30.518152  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:06:30.518563  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:06:30.518835  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:30.518931  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:30.519590  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:30.519729  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:30.520056  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:30.520168  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:30.520281  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName3" (UniqueName: "kubernetes.io/testPlugin/volumeName3") from node "mynode-1" 
I0624 09:06:30.520428  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:30.520555  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:30.520944  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:30.521133  174704 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0624 09:06:30.521290  174704 event.go:291] "Event occurred" object="mynamespace/newpod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName3\" "
I0624 09:06:30.521439  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:30.521609  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:30.524838  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:30.525745  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:30.526046  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:32.510717  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:32.614521  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:32.622166  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:32.622300  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:32.622502  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:32.623990  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:32.624103  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:32.624343  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:32.625685  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:32.625785  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:32.626078  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:32.627480  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:32.628689  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:32.628816  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:32.628904  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:32.628951  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:32.629088  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "vol1" (UniqueName: "kubernetes.io/testPlugin/vol1") from node "mynode-1" 
I0624 09:06:32.629459  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "vol1" (UniqueName: "kubernetes.io/testPlugin/vol1") from node "mynode-1" 
I0624 09:06:32.629717  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:32.629854  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:32.629922  174704 event.go:291] "Event occurred" object="mynamespace/pod1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"vol1\" "
I0624 09:06:32.630125  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:32.630269  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:32.630330  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:32.630375  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:32.630528  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:32.630721  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:33.623986  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:33.724589  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:33.731296  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:33.731479  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:33.731616  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:33.732596  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:33.732755  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:33.732869  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:33.733814  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:33.733913  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:33.734029  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:33.735055  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:33.735193  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:33.735323  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:33.736374  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:33.736463  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:33.736602  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:33.736665  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:33.737547  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:33.737733  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:33.737915  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:33.738153  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:33.738337  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:33.738504  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:34.644603  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:06:34.645014  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:06:34.645132  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:06:34.729903  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:34.830488  174704 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:06:34.836058  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:34.836342  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:34.836490  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:06:34.836950  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:34.837142  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:34.837270  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:06:34.837847  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:34.838064  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:34.838198  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:06:34.838846  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:34.838943  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:34.839077  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:06:34.843121  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:34.843278  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:34.843448  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:06:34.843550  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:34.844746  174704 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:06:34.845640  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:34.845865  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:34.846048  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:34.846238  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:34.846411  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:06:35.748312  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:06:35.748523  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:06:35.748655  174704 operation_generator.go:470] DetachVolume.Detach succeeded for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:06:35.836098  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:06:35.936654  174704 shared_informer.go:247] Caches are synced for attach detach 
W0624 09:06:35.942130  174704 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.VolumeAttachment ended with: very short watch: k8s.io/client-go/informers/factory.go:134: Unexpected watch close - watch lasted less than a second and no items received
I0624 09:06:35.945375  174704 shared_informer.go:240] Waiting for caches to sync for attach detach
E0624 09:06:35.947409  174704 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" : no volume plugin matched name: kubernetes.io/testPlugin
E0624 09:06:35.948674  174704 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" : no volume plugin matched name: kubernetes.io/testPlugin
E0624 09:06:35.949943  174704 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" : no volume plugin matched name: kubernetes.io/testPlugin
E0624 09:06:35.951191  174704 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" : no volume plugin matched name: kubernetes.io/testPlugin
I0624 09:06:35.952476  174704 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/vol1") on node "mynode-1" 
I0624 09:06:35.952683  174704 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/vol1") on node "mynode-1" 
E0624 09:06:35.952989  174704 csi_attacher.go:455] [attachment.ID=csi-77bd5b88d32d48e5a31f0073211a7dd54ed0066f008e12364f4b6ecb61dc7370] watch channel had been closed
E0624 09:06:35.953503  174704 csi_attacher.go:455] [attachment.ID=csi-4ff6fd4b10c02f804e7435dffeb62054338b590749cdaacf18e198ee0ab6dd66] watch channel had been closed
==================
WARNING: DATA RACE
Read at 0x00c00052c3d8 by goroutine 82:
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/testing.CreateTestClient.func6()
      pkg/controller/volume/attachdetach/testing/testvolumespec.go:179 +0x104
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*SimpleReactor).React()
      staging/src/k8s.io/client-go/testing/fixture.go:521 +0x68
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*Fake).Invokes()
      staging/src/k8s.io/client-go/testing/fake.go:141 +0x327
  k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes/typed/storage/v1/fake.(*FakeVolumeAttachments).List()
      staging/src/k8s.io/client-go/kubernetes/typed/storage/v1/fake/fake_volumeattachment.go:55 +0x273
  k8s.io/kubernetes/vendor/k8s.io/client-go/informers/storage/v1.NewFilteredVolumeAttachmentInformer.func1()
      staging/src/k8s.io/client-go/informers/storage/v1/volumeattachment.go:64 +0x23c
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*ListWatch).List()
      staging/src/k8s.io/client-go/tools/cache/listwatch.go:106 +0x97
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func1.1.2()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:277 +0xf4
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/pager.SimplePageFunc.func1()
      staging/src/k8s.io/client-go/tools/pager/pager.go:40 +0x97
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/pager.(*ListPager).List()
      staging/src/k8s.io/client-go/tools/pager/pager.go:91 +0x1e2
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func1.1()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:302 +0x2b7

Previous write at 0x00c00052c3d8 by goroutine 182:
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/testing.CreateTestClient.func7()
      pkg/controller/volume/attachdetach/testing/testvolumespec.go:185 +0x207
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*SimpleReactor).React()
      staging/src/k8s.io/client-go/testing/fixture.go:521 +0x68
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*Fake).Invokes()
      staging/src/k8s.io/client-go/testing/fake.go:141 +0x327
I0624 09:06:35.954305  174704 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" : volume attachment watch channel had been closed"
  k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes/typed/storage/v1/fake.(*FakeVolumeAttachments).Create()
      staging/src/k8s.io/client-go/kubernetes/typed/storage/v1/fake/fake_volumeattachment.go:82 +0x246
  k8s.io/kubernetes/pkg/volume/csi.(*csiAttacher).Attach()
      pkg/volume/csi/csi_attacher.go:109 +0x5f3
  k8s.io/kubernetes/pkg/volume/util/operationexecutor.(*operationGenerator).GenerateAttachVolumeFunc.func1()
      pkg/volume/util/operationexecutor/operation_generator.go:335 +0x275
  k8s.io/kubernetes/pkg/volume/util/types.(*GeneratedOperations).Run()
      pkg/volume/util/types/types.go:54 +0x142
  k8s.io/kubernetes/pkg/volume/util/nestedpendingoperations.(*nestedPendingOperations).Run.func1()
      pkg/volume/util/nestedpendingoperations/nestedpendingoperations.go:183 +0x159

Goroutine 82 (running) created at:
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func1()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:268 +0x36f
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:360 +0x2e4
I0624 09:06:35.954367  174704 reconciler.go:295] attacherDetacher.AttachVolume started for volume "pd.csi.storage.gke.io-pdName" (UniqueName: "kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/pdName") from node "mynode" 
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).Run.func1()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:221 +0x53
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:155 +0x75
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:156 +0xba
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).Run()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:220 +0x2c4
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).Run-fm()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:218 +0x4b
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.(*Group).StartWithChannel.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:56 +0x45
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:73 +0x6d

Goroutine 182 (running) created at:
  k8s.io/kubernetes/pkg/volume/util/nestedpendingoperations.(*nestedPendingOperations).Run()
      pkg/volume/util/nestedpendingoperations/nestedpendingoperations.go:178 +0x5b2
  k8s.io/kubernetes/pkg/volume/util/operationexecutor.(*operationExecutor).AttachVolume()
      pkg/volume/util/operationexecutor/operation_executor.go:675 +0x348
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).attachDesiredVolumes()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:293 +0x639
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).reconcile()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:233 +0x1b9
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).reconciliationLoopFunc.func1()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:110 +0x5e
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:155 +0x75
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:156 +0xba
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:133 +0x114
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.Until()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:90 +0x89
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).Run()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:101 +0x2f
==================
I0624 09:06:35.954651  174704 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" : volume attachment watch channel had been closed"
E0624 09:06:35.954678  174704 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/vol1 podName: nodeName:mynode-1}" failed. No retries permitted until 2021-06-24 09:06:36.454277904 +0000 UTC m=+12.533888394 (durationBeforeRetry 500ms). Error: "DetachVolume.Detach failed for volume \"nil\" (UniqueName: \"kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/vol1\") on node \"mynode-1\" : volume attachment watch channel had been closed"
I0624 09:06:35.955041  174704 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" : volume attachment watch channel had been closed"
I0624 09:06:35.955286  174704 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" : volume attachment watch channel had been closed"
E0624 09:06:35.955361  174704 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/pdName podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:06:36.455105986 +0000 UTC m=+12.534716487 (durationBeforeRetry 500ms). Error: "AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" (UniqueName: \"kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/pdName\") from node \"mynode\" : volume attachment watch channel had been closed"
==================
WARNING: DATA RACE
Read at 0x00c00099f368 by I0624 09:06:35.955488  174704 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" : volume attachment watch channel had been closed"
goroutine 82:
  runtime.slicecopy()
      GOROOT/src/runtime/slice.go:246 +0x0
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/testing.CreateTestClient.func6()
      pkg/controller/volume/attachdetach/testing/testvolumespec.go:179 +0x184
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*SimpleReactor).React()
      staging/src/k8s.io/client-go/testing/fixture.go:521 +0x68
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*Fake).Invokes()
      staging/src/k8s.io/client-go/testing/fake.go:141 +0x327
  k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes/typed/storage/v1/fake.(*FakeVolumeAttachments).List()
      staging/src/k8s.io/client-go/kubernetes/typed/storage/v1/fake/fake_volumeattachment.go:55 +0x273
  k8s.io/kubernetes/vendor/k8s.io/client-go/informers/storage/v1.NewFilteredVolumeAttachmentInformer.func1()
      staging/src/k8s.io/client-go/informers/storage/v1/volumeattachment.go:64 +0x23c
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*ListWatch).List()
      staging/src/k8s.io/client-go/tools/cache/listwatch.go:106 +0x97
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func1.1.2()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:277 +0xf4
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/pager.SimplePageFunc.func1()
      staging/src/k8s.io/client-go/tools/pager/pager.go:40 +0x97
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/pager.(*ListPager).List()
      staging/src/k8s.io/client-go/tools/pager/pager.go:91 +0x1e2
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func1.1()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:302 +0x2b7

Previous write at 0x00c00099f368 by goroutine 182:
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/testing.CreateTestClient.func7()
      pkg/controller/volume/attachdetach/testing/testvolumespec.go:185 +0x184
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*SimpleReactor).React()
      staging/src/k8s.io/client-go/testing/fixture.go:521 +0x68
  k8s.io/kubernetes/vendor/k8s.io/client-go/testing.(*Fake).Invokes()
      staging/src/k8s.io/client-go/testing/fake.go:141 +0x327
  k8s.io/kubernetes/vendor/k8s.io/client-go/kubernetes/typed/storage/v1/fake.(*FakeVolumeAttachments).Create()
      staging/src/k8s.io/client-go/kubernetes/typed/storage/v1/fake/fake_volumeattachment.go:82 +0x246
  k8s.io/kubernetes/pkg/volume/csi.(*csiAttacher).Attach()
      pkg/volume/csi/csi_attacher.go:109 +0x5f3
  k8s.io/kubernetes/pkg/volume/util/operationexecutor.(*operationGenerator).GenerateAttachVolumeFunc.func1()
      pkg/volume/util/operationexecutor/operation_generator.go:335 +0x275
  k8s.io/kubernetes/pkg/volume/util/types.(*GeneratedOperations).Run()
      pkg/volume/util/types/types.go:54 +0x142
  k8s.io/kubernetes/pkg/volume/util/nestedpendingoperations.(*nestedPendingOperations).Run.func1()
      pkg/volume/util/nestedpendingoperations/nestedpendingoperations.go:183 +0x159

Goroutine 82 (running) created at:
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func1()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:268 +0x36f
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:360 +0x2e4
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).Run.func1()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:221 +0x53
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:155 +0x75
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:156 +0xba
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).Run()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:220 +0x2c4
  k8s.io/kubernetes/vendor/k8s.io/client-go/tools/cache.(*Reflector).Run-fm()
      staging/src/k8s.io/client-go/tools/cache/reflector.go:218 +0x4b
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.(*Group).StartWithChannel.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:56 +0x45
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:73 +0x6d

Goroutine 182 (running) created at:
  k8s.io/kubernetes/pkg/volume/util/nestedpendingoperations.(*nestedPendingOperations).Run()
      pkg/volume/util/nestedpendingoperations/nestedpendingoperations.go:178 +0x5b2
  k8s.io/kubernetes/pkg/volume/util/operationexecutor.(*operationExecutor).AttachVolume()
      pkg/volume/util/operationexecutor/operation_executor.go:675 +0x348
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).attachDesiredVolumes()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:293 +0x639
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).reconcile()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:233 +0x1b9
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).reconciliationLoopFunc.func1()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:110 +0x5e
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:155 +0x75
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.BackoffUntil()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:156 +0xba
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.JitterUntil()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:133 +0x114
  k8s.io/kubernetes/vendor/k8s.io/apimachinery/pkg/util/wait.Until()
      staging/src/k8s.io/apimachinery/pkg/util/wait/wait.go:90 +0x89
  k8s.io/kubernetes/pkg/controller/volume/attachdetach/reconciler.(*reconciler).Run()
      pkg/controller/volume/attachdetach/reconciler/reconciler.go:101 +0x2f
==================
I0624 09:06:36.045945  174704 shared_informer.go:247] Caches are synced for attach detach 
W0624 09:06:36.046287  174704 attach_detach_controller.go:710] Skipping the va as its pvName is nil, va.Name: "csi-4ff6fd4b10c02f804e7435dffeb62054338b590749cdaacf18e198ee0ab6dd66", nodeName: "mynode"
W0624 09:06:36.048112  174704 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.Node ended with: very short watch: k8s.io/client-go/informers/factory.go:134: Unexpected watch close - watch lasted less than a second and no items received
--- FAIL: Test_ADC_VolumeAttachmentRecovery (3.54s)
    --- FAIL: Test_ADC_VolumeAttachmentRecovery/Deleted_Pod_with_migrated_PV (0.11s)
        testing.go:1038: race detected during execution of test
    testing.go:1038: race detected during execution of test
FAIL

				from junit_bazel.xml

Filter through log files | View test history on testgrid


//pkg/kubelet/volumemanager/reconciler/go_default_test:run_2_of_2 0.00s

bazel test //pkg/kubelet/volumemanager/reconciler/go_default_test:run_2_of_2
exec ${PAGER:-/usr/bin/less} "$0" || exit 1
Executing tests from //pkg/kubelet/volumemanager/reconciler:go_default_test
-----------------------------------------------------------------------------
I0624 09:02:04.473827  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:04.473962  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:04.497673  148475 reconciler.go:244] operationExecutor.AttachVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") 
I0624 09:02:04.497761  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:04.497811  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:04.498391  148475 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") from node "mynodename" 
I0624 09:02:04.499004  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/vdb-test"
I0624 09:02:04.499112  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:04.499210  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") device mount path ""
I0624 09:02:04.601158  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") 
I0624 09:02:04.601228  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:04.601276  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:04.601797  148475 operation_generator.go:1357] Controller attach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") device path: "/fake/path"
I0624 09:02:04.602400  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/fake/path"
I0624 09:02:04.602514  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:04.602614  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") device mount path ""
I0624 09:02:04.704611  148475 reconciler.go:244] operationExecutor.AttachVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") 
I0624 09:02:04.704680  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:04.704730  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:04.705161  148475 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") from node "mynodename" 
I0624 09:02:04.705657  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/vdb-test"
I0624 09:02:04.705780  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:04.705881  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") device mount path ""
I0624 09:02:04.804687  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1uid" (UID: "pod1uid") 
I0624 09:02:04.805065  148475 operation_generator.go:797] UnmountVolume.TearDown succeeded for volume "fake-plugin/fake-device1" (OuterVolumeSpecName: "volume-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "volume-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:02:04.805699  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" 
I0624 09:02:04.805934  148475 operation_generator.go:891] UnmountDevice succeeded for volume "volume-name" %!(EXTRA string=UnmountDevice succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" )
I0624 09:02:04.806351  148475 reconciler.go:333] operationExecutor.DetachVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" 
I0624 09:02:04.806491  148475 operation_generator.go:470] DetachVolume.Detach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" 
I0624 09:02:04.905443  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") 
I0624 09:02:04.905508  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:04.905556  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:04.905987  148475 operation_generator.go:1357] Controller attach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") device path: "/fake/path"
I0624 09:02:04.906499  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/fake/path"
I0624 09:02:04.906617  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:04.906714  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") device mount path ""
I0624 09:02:05.006631  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1uid" (UID: "pod1uid") 
I0624 09:02:05.051855  148475 operation_generator.go:797] UnmountVolume.TearDown succeeded for volume "fake-plugin/fake-device1" (OuterVolumeSpecName: "volume-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "volume-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:02:05.052362  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1uid" (UID: "pod1uid") 
I0624 09:02:05.052497  148475 operation_generator.go:797] UnmountVolume.TearDown succeeded for volume "fake-plugin/fake-device1" (OuterVolumeSpecName: "volume-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "volume-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:02:05.052942  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" 
I0624 09:02:05.053065  148475 operation_generator.go:891] UnmountDevice succeeded for volume "volume-name" %!(EXTRA string=UnmountDevice succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" )
I0624 09:02:05.053246  148475 reconciler.go:319] Volume detached for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:02:05.109098  148475 reconciler.go:244] operationExecutor.AttachVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") 
I0624 09:02:05.109169  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:05.109229  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:05.109433  148475 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") from node "mynodename" 
I0624 09:02:05.110426  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/vdb-test"
I0624 09:02:05.110561  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:05.211404  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") 
I0624 09:02:05.211488  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:05.211567  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:05.211829  148475 operation_generator.go:1357] Controller attach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") device path: "/fake/path"
I0624 09:02:05.212777  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/fake/path"
I0624 09:02:05.212900  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:05.311969  148475 reconciler.go:244] operationExecutor.AttachVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") 
I0624 09:02:05.312046  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:05.312096  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:05.312397  148475 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") from node "mynodename" 
I0624 09:02:05.313051  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/vdb-test"
I0624 09:02:05.313187  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:05.418242  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1uid" (UID: "pod1uid") 
I0624 09:02:05.429239  148475 operation_generator.go:1170] UnmapVolume succeeded for volume "fake-plugin/fake-device1" (OuterVolumeSpecName: "volume-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "volume-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:02:05.485357  148475 operation_generator.go:1282] UnmapDevice succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" 
I0624 09:02:05.485678  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" 
I0624 09:02:05.486296  148475 reconciler.go:333] operationExecutor.DetachVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" 
I0624 09:02:05.486580  148475 operation_generator.go:470] DetachVolume.Detach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" 
I0624 09:02:05.487297  148475 reconciler.go:333] operationExecutor.DetachVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" 
E0624 09:02:05.489503  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/fake-device1 podName: nodeName:mynodename}" failed. No retries permitted until 2021-06-24 09:02:05.988373918 +0000 UTC m=+1.665810578 (durationBeforeRetry 500ms). Error: "DetachVolume.Detach failed for volume \"volume-name\" (UniqueName: \"fake-plugin/fake-device1\") on node \"mynodename\" : Trying to detach volume \"fake-device1\" that is not attached to the node \"mynodename\""
--- FAIL: Test_Run_Positive_BlockVolumeAttachMapUnmapDetach (0.21s)
    reconciler_test.go:740: 
        	Error Trace:	reconciler_test.go:740
        	Error:      	Received unexpected error:
        	            	No Detachers have expected DetachCallCount. Expected: <1>.
        	Test:       	Test_Run_Positive_BlockVolumeAttachMapUnmapDetach
I0624 09:02:05.521888  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") 
I0624 09:02:05.521955  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:05.522006  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:05.522230  148475 operation_generator.go:1357] Controller attach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") device path: "/fake/path"
I0624 09:02:05.522773  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/fake/path"
I0624 09:02:05.522885  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:05.638144  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1uid" (UID: "pod1uid") 
I0624 09:02:05.638310  148475 operation_generator.go:1170] UnmapVolume succeeded for volume "fake-plugin/fake-device1" (OuterVolumeSpecName: "volume-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "volume-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:02:05.638764  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" 
I0624 09:02:05.639049  148475 operation_generator.go:1282] UnmapDevice succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" 
I0624 09:02:05.639227  148475 reconciler.go:319] Volume detached for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:02:05.751174  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") 
I0624 09:02:05.751247  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:05.751313  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:05.752343  148475 operation_generator.go:1357] Controller attach succeeded for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:05.753395  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:05.753504  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:05.753815  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") device mount path ""
I0624 09:02:05.858144  148475 operation_generator.go:1683] MountVolume.NodeExpandVolume succeeded for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") 
I0624 09:02:05.959559  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") 
I0624 09:02:05.959641  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:05.959702  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:05.960017  148475 operation_generator.go:1357] Controller attach succeeded for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:05.986000  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:06.068413  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:06.091559  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:06.091696  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:06.400800  148475 operation_generator.go:1683] MountVolume.NodeExpandVolume succeeded for volume "pv" (UniqueName: "fake-plugin/pv") pod "pod1" (UID: "pod1uid") 
I0624 09:02:06.508319  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "fail-expansion-in-use" (UniqueName: "fake-plugin/fail-expansion-in-use") pod "pod1" (UID: "pod1uid") 
I0624 09:02:06.508404  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:06.508455  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:06.509094  148475 operation_generator.go:1357] Controller attach succeeded for volume "fail-expansion-in-use" (UniqueName: "fake-plugin/fail-expansion-in-use") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:06.518052  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "fail-expansion-in-use" (UniqueName: "fake-plugin/fail-expansion-in-use") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:06.518195  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "fail-expansion-in-use" (UniqueName: "fake-plugin/fail-expansion-in-use") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:06.518301  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "fail-expansion-in-use" (UniqueName: "fake-plugin/fail-expansion-in-use") pod "pod1" (UID: "pod1uid") device mount path ""
E0624 09:02:06.518637  148475 operation_generator.go:1669] MountVolume.NodeExapndVolume failed with %!!(MISSING)v(MISSING) for volume "fail-expansion-in-use" (UniqueName: "fake-plugin/fail-expansion-in-use") pod "pod1" (UID: "pod1uid") : volume-in-use
I0624 09:02:06.609454  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") pod "pod1" (UID: "pod1uid") 
I0624 09:02:06.609534  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:06.609590  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:06.609905  148475 operation_generator.go:1357] Controller attach succeeded for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:06.612417  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:06.612569  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:06.613008  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-mount-device-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:07.11282183 +0000 UTC m=+2.790258476 (durationBeforeRetry 500ms). Error: "MapVolume.SetUpDevice failed for volume \"timeout-mount-device-volume\" (UniqueName: \"fake-plugin/timeout-mount-device-volume\") pod \"pod1\" (UID: \"pod1uid\") : mount failed"
I0624 09:02:06.712729  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") on node "mynodename" 
I0624 09:02:06.712971  148475 operation_generator.go:1282] UnmapDevice succeeded for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") on node "mynodename" 
I0624 09:02:06.713188  148475 reconciler.go:319] Volume detached for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:02:06.826964  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "fail-mount-device-volume-name" (UniqueName: "fake-plugin/fail-mount-device-volume-name") pod "pod1" (UID: "pod1uid") 
I0624 09:02:06.827052  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:06.827108  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:06.827415  148475 operation_generator.go:1357] Controller attach succeeded for volume "fail-mount-device-volume-name" (UniqueName: "fake-plugin/fail-mount-device-volume-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:06.828322  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "fail-mount-device-volume-name" (UniqueName: "fake-plugin/fail-mount-device-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:06.828452  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "fail-mount-device-volume-name" (UniqueName: "fake-plugin/fail-mount-device-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:06.828843  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/fail-mount-device-volume-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:07.328639688 +0000 UTC m=+3.006076332 (durationBeforeRetry 500ms). Error: "MapVolume.SetUpDevice failed for volume \"fail-mount-device-volume-name\" (UniqueName: \"fake-plugin/fail-mount-device-volume-name\") pod \"pod1\" (UID: \"pod1uid\") : error mapping disk: fail-mount-device-volume-name"
I0624 09:02:06.922845  148475 reconciler.go:319] Volume detached for volume "fail-mount-device-volume-name" (UniqueName: "fake-plugin/fail-mount-device-volume-name") on node "mynodename" DevicePath "fake/path"
I0624 09:02:07.022483  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") 
I0624 09:02:07.031100  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:07.031217  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:07.048712  148475 operation_generator.go:1357] Controller attach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:07.056218  148475 operation_generator.go:1357] Controller attach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:07.057080  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") 
I0624 09:02:07.060711  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:07.061490  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:07.089780  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:07.562313929 +0000 UTC m=+3.239750589 (durationBeforeRetry 500ms). Error: "MapVolume.SetUpDevice failed for volume \"timeout-and-fail-mount-device-name\" (UniqueName: \"fake-plugin/timeout-and-fail-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : timed out mounting error"
I0624 09:02:07.562790  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:07.562957  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:07.563433  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:08.563190184 +0000 UTC m=+4.240626828 (durationBeforeRetry 1s). Error: "MapVolume.SetUpDevice failed for volume \"timeout-and-fail-mount-device-name\" (UniqueName: \"fake-plugin/timeout-and-fail-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mapping disk: timeout-and-fail-mount-device-name"
I0624 09:02:08.587701  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:08.587900  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:08.588322  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:10.588107666 +0000 UTC m=+6.265544362 (durationBeforeRetry 2s). Error: "MapVolume.SetUpDevice failed for volume \"timeout-and-fail-mount-device-name\" (UniqueName: \"fake-plugin/timeout-and-fail-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mapping disk: timeout-and-fail-mount-device-name"
I0624 09:02:10.588571  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:10.588737  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:10.589148  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:14.588954144 +0000 UTC m=+10.266390783 (durationBeforeRetry 4s). Error: "MapVolume.SetUpDevice failed for volume \"timeout-and-fail-mount-device-name\" (UniqueName: \"fake-plugin/timeout-and-fail-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mapping disk: timeout-and-fail-mount-device-name"
I0624 09:02:14.589428  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:14.589591  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:14.590043  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:22.589834691 +0000 UTC m=+18.267271332 (durationBeforeRetry 8s). Error: "MapVolume.SetUpDevice failed for volume \"timeout-and-fail-mount-device-name\" (UniqueName: \"fake-plugin/timeout-and-fail-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mapping disk: timeout-and-fail-mount-device-name"
I0624 09:02:17.140184  148475 reconciler.go:319] Volume detached for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:02:17.296346  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") 
I0624 09:02:17.296400  148475 operation_generator.go:1357] Controller attach succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:17.296438  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:17.296603  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:17.297250  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:17.297396  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:17.420041  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:17.420211  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:17.420612  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:17.920415504 +0000 UTC m=+13.597852146 (durationBeforeRetry 500ms). Error: "MapVolume.SetUpDevice failed for volume \"success-and-timeout-device-name\" (UniqueName: \"fake-plugin/success-and-timeout-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mounting state"
I0624 09:02:17.920906  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:17.921061  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:17.921454  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:18.921265103 +0000 UTC m=+14.598701746 (durationBeforeRetry 1s). Error: "MapVolume.SetUpDevice failed for volume \"success-and-timeout-device-name\" (UniqueName: \"fake-plugin/success-and-timeout-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mounting state"
I0624 09:02:18.922197  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:18.922383  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:18.922790  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:20.922609762 +0000 UTC m=+16.600046407 (durationBeforeRetry 2s). Error: "MapVolume.SetUpDevice failed for volume \"success-and-timeout-device-name\" (UniqueName: \"fake-plugin/success-and-timeout-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mounting state"
I0624 09:02:20.928218  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:20.928390  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:20.928804  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:24.928594571 +0000 UTC m=+20.606031214 (durationBeforeRetry 4s). Error: "MapVolume.SetUpDevice failed for volume \"success-and-timeout-device-name\" (UniqueName: \"fake-plugin/success-and-timeout-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mounting state"
I0624 09:02:24.940390  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:24.955602  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:24.958536  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:32.958330978 +0000 UTC m=+28.635767630 (durationBeforeRetry 8s). Error: "MapVolume.SetUpDevice failed for volume \"success-and-timeout-device-name\" (UniqueName: \"fake-plugin/success-and-timeout-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mounting state"
I0624 09:02:27.419511  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1uid" (UID: "pod1uid") 
I0624 09:02:27.419993  148475 operation_generator.go:1170] UnmapVolume succeeded for volume "fake-plugin/success-and-timeout-device-name" (OuterVolumeSpecName: "success-and-timeout-device-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "success-and-timeout-device-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:02:27.425955  148475 operation_generator.go:1282] UnmapDevice succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") on node "mynodename" 
I0624 09:02:27.440115  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") on node "mynodename" 
I0624 09:02:27.440440  148475 reconciler.go:319] Volume detached for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:02:27.529759  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") 
I0624 09:02:27.529848  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:27.529906  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:27.530416  148475 operation_generator.go:1357] Controller attach succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:27.531216  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:27.531379  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:27.639420  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:27.639588  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:27.640045  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:28.139815271 +0000 UTC m=+23.817251914 (durationBeforeRetry 500ms). Error: "MapVolume.SetUpDevice failed for volume \"success-and-failed-mount-device-name\" (UniqueName: \"fake-plugin/success-and-failed-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mapping disk: success-and-failed-mount-device-name"
I0624 09:02:28.186061  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:28.186245  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:28.186988  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:29.186464651 +0000 UTC m=+24.863901292 (durationBeforeRetry 1s). Error: "MapVolume.SetUpDevice failed for volume \"success-and-failed-mount-device-name\" (UniqueName: \"fake-plugin/success-and-failed-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mapping disk: success-and-failed-mount-device-name"
I0624 09:02:29.187495  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:29.187664  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:29.188143  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:31.187925574 +0000 UTC m=+26.865362218 (durationBeforeRetry 2s). Error: "MapVolume.SetUpDevice failed for volume \"success-and-failed-mount-device-name\" (UniqueName: \"fake-plugin/success-and-failed-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mapping disk: success-and-failed-mount-device-name"
I0624 09:02:31.194026  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:31.194230  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:31.194906  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:35.194518164 +0000 UTC m=+30.871954810 (durationBeforeRetry 4s). Error: "MapVolume.SetUpDevice failed for volume \"success-and-failed-mount-device-name\" (UniqueName: \"fake-plugin/success-and-failed-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mapping disk: success-and-failed-mount-device-name"
I0624 09:02:35.195038  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:35.195217  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:35.195643  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:43.195436441 +0000 UTC m=+38.872873080 (durationBeforeRetry 8s). Error: "MapVolume.SetUpDevice failed for volume \"success-and-failed-mount-device-name\" (UniqueName: \"fake-plugin/success-and-failed-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mapping disk: success-and-failed-mount-device-name"
I0624 09:02:37.688033  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1uid" (UID: "pod1uid") 
I0624 09:02:37.688188  148475 operation_generator.go:1170] UnmapVolume succeeded for volume "fake-plugin/success-and-failed-mount-device-name" (OuterVolumeSpecName: "success-and-failed-mount-device-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "success-and-failed-mount-device-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:02:37.688668  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") on node "mynodename" 
I0624 09:02:37.705670  148475 operation_generator.go:1282] UnmapDevice succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") on node "mynodename" 
I0624 09:02:37.710810  148475 reconciler.go:319] Volume detached for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:02:37.745171  148475 operation_generator.go:1357] Controller attach succeeded for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:37.745642  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") pod "pod1" (UID: "pod1uid") 
I0624 09:02:37.745710  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:37.745769  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:37.747146  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:37.747295  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:37.747790  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-mount-device-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:38.247571088 +0000 UTC m=+33.925007743 (durationBeforeRetry 500ms). Error: "MountVolume.MountDevice failed for volume \"timeout-mount-device-volume\" (UniqueName: \"fake-plugin/timeout-mount-device-volume\") pod \"pod1\" (UID: \"pod1uid\") : mount failed"
I0624 09:02:37.849084  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") on node "mynodename" 
I0624 09:02:37.849661  148475 operation_generator.go:891] UnmountDevice succeeded for volume "timeout-mount-device-volume" %!(EXTRA string=UnmountDevice succeeded for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") on node "mynodename" )
I0624 09:02:37.850171  148475 reconciler.go:319] Volume detached for volume "timeout-mount-device-volume" (UniqueName: "fake-plugin/timeout-mount-device-volume") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:02:37.949832  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "fail-mount-device-volume-name" (UniqueName: "fake-plugin/fail-mount-device-volume-name") pod "pod1" (UID: "pod1uid") 
I0624 09:02:37.949915  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:37.949976  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:37.950477  148475 operation_generator.go:1357] Controller attach succeeded for volume "fail-mount-device-volume-name" (UniqueName: "fake-plugin/fail-mount-device-volume-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:37.951348  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "fail-mount-device-volume-name" (UniqueName: "fake-plugin/fail-mount-device-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:37.951480  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "fail-mount-device-volume-name" (UniqueName: "fake-plugin/fail-mount-device-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:37.951937  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/fail-mount-device-volume-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:38.451721282 +0000 UTC m=+34.129157928 (durationBeforeRetry 500ms). Error: "MountVolume.MountDevice failed for volume \"fail-mount-device-volume-name\" (UniqueName: \"fake-plugin/fail-mount-device-volume-name\") pod \"pod1\" (UID: \"pod1uid\") : error mounting disk: /dev/sdb"
I0624 09:02:38.084925  148475 reconciler.go:319] Volume detached for volume "fail-mount-device-volume-name" (UniqueName: "fake-plugin/fail-mount-device-volume-name") on node "mynodename" DevicePath "fake/path"
I0624 09:02:38.153313  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") 
I0624 09:02:38.153422  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:38.153484  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:38.153909  148475 operation_generator.go:1357] Controller attach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:38.154618  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:38.154763  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:38.155747  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:38.654995453 +0000 UTC m=+34.332432102 (durationBeforeRetry 500ms). Error: "MountVolume.MountDevice failed for volume \"timeout-and-fail-mount-device-name\" (UniqueName: \"fake-plugin/timeout-and-fail-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : timed out mounting error"
I0624 09:02:38.666039  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:38.666209  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:38.666660  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:39.666456169 +0000 UTC m=+35.343892811 (durationBeforeRetry 1s). Error: "MountVolume.MountDevice failed for volume \"timeout-and-fail-mount-device-name\" (UniqueName: \"fake-plugin/timeout-and-fail-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mounting disk: /dev/sdb"
I0624 09:02:39.666873  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:39.667024  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:39.667388  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:41.667215395 +0000 UTC m=+37.344652035 (durationBeforeRetry 2s). Error: "MountVolume.MountDevice failed for volume \"timeout-and-fail-mount-device-name\" (UniqueName: \"fake-plugin/timeout-and-fail-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mounting disk: /dev/sdb"
I0624 09:02:41.695239  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:41.695410  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:41.695863  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:45.695642464 +0000 UTC m=+41.373079118 (durationBeforeRetry 4s). Error: "MountVolume.MountDevice failed for volume \"timeout-and-fail-mount-device-name\" (UniqueName: \"fake-plugin/timeout-and-fail-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mounting disk: /dev/sdb"
I0624 09:02:45.696357  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:45.696536  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:02:45.697057  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-mount-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:02:53.696776921 +0000 UTC m=+49.374213571 (durationBeforeRetry 8s). Error: "MountVolume.MountDevice failed for volume \"timeout-and-fail-mount-device-name\" (UniqueName: \"fake-plugin/timeout-and-fail-mount-device-name\") pod \"pod1\" (UID: \"pod1uid\") : error mounting disk: /dev/sdb"
I0624 09:02:48.296536  148475 reconciler.go:319] Volume detached for volume "timeout-and-fail-mount-device-name" (UniqueName: "fake-plugin/timeout-and-fail-mount-device-name") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:02:48.397676  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") 
I0624 09:02:48.397769  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:48.397836  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:48.398077  148475 operation_generator.go:1357] Controller attach succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:48.399221  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:48.401681  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:48.401834  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") device mount path ""
I0624 09:02:48.500701  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:48.500881  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:58.509142  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") pod "pod1uid" (UID: "pod1uid") 
I0624 09:02:58.525553  148475 operation_generator.go:797] UnmountVolume.TearDown succeeded for volume "fake-plugin/success-and-timeout-device-name" (OuterVolumeSpecName: "success-and-timeout-device-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "success-and-timeout-device-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:02:58.526084  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") on node "mynodename" 
I0624 09:02:58.526573  148475 operation_generator.go:891] UnmountDevice succeeded for volume "success-and-timeout-device-name" %!(EXTRA string=UnmountDevice succeeded for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") on node "mynodename" )
I0624 09:02:58.526838  148475 reconciler.go:319] Volume detached for volume "success-and-timeout-device-name" (UniqueName: "fake-plugin/success-and-timeout-device-name") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:02:58.607832  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") 
I0624 09:02:58.607913  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:02:58.607968  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:02:58.608786  148475 operation_generator.go:1357] Controller attach succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:02:58.609331  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:02:58.609469  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:58.609583  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") device mount path ""
I0624 09:02:58.713914  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:58.714090  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:58.718050  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:02:58.718203  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:08.732265  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") pod "pod1uid" (UID: "pod1uid") 
I0624 09:03:08.732870  148475 operation_generator.go:797] UnmountVolume.TearDown succeeded for volume "fake-plugin/success-and-failed-mount-device-name" (OuterVolumeSpecName: "success-and-failed-mount-device-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "success-and-failed-mount-device-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:03:08.733459  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") on node "mynodename" 
I0624 09:03:08.733755  148475 operation_generator.go:891] UnmountDevice succeeded for volume "success-and-failed-mount-device-name" %!(EXTRA string=UnmountDevice succeeded for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") on node "mynodename" )
I0624 09:03:08.734019  148475 reconciler.go:319] Volume detached for volume "success-and-failed-mount-device-name" (UniqueName: "fake-plugin/success-and-failed-mount-device-name") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:03:08.818629  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") pod "pod1" (UID: "pod1uid") 
I0624 09:03:08.818722  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:03:08.818771  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:03:08.819045  148475 operation_generator.go:1357] Controller attach succeeded for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:03:08.820181  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:03:08.820309  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:08.820659  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:09.32048828 +0000 UTC m=+64.997924921 (durationBeforeRetry 500ms). Error: "MapVolume.MapPodDevice failed for volume \"timeout-setup-volume\" (UniqueName: \"fake-plugin/timeout-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:08.945616  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") pod "pod1uid" (UID: "pod1uid") 
I0624 09:03:08.948330  148475 operation_generator.go:1170] UnmapVolume succeeded for volume "fake-plugin/timeout-setup-volume" (OuterVolumeSpecName: "timeout-setup-volume") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "timeout-setup-volume". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:03:08.948818  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") on node "mynodename" 
I0624 09:03:08.948992  148475 operation_generator.go:1282] UnmapDevice succeeded for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") on node "mynodename" 
I0624 09:03:08.952611  148475 reconciler.go:319] Volume detached for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:03:09.042986  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") pod "pod1" (UID: "pod1uid") 
I0624 09:03:09.043077  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:03:09.043139  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:03:09.043562  148475 operation_generator.go:1357] Controller attach succeeded for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:03:09.044205  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:03:09.044383  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:09.044949  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/fail-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:09.544714498 +0000 UTC m=+65.222151139 (durationBeforeRetry 500ms). Error: "MapVolume.MapPodDevice failed for volume \"fail-setup-volume\" (UniqueName: \"fake-plugin/fail-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:09.142928  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") on node "mynodename" 
I0624 09:03:09.143166  148475 operation_generator.go:1282] UnmapDevice succeeded for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") on node "mynodename" 
I0624 09:03:09.143841  148475 reconciler.go:319] Volume detached for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:03:09.244187  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") 
I0624 09:03:09.244261  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:03:09.244321  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:03:09.244729  148475 operation_generator.go:1357] Controller attach succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:03:09.245405  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:03:09.245542  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:09.245941  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:09.745754154 +0000 UTC m=+65.423190796 (durationBeforeRetry 500ms). Error: "MapVolume.MapPodDevice failed for volume \"timeout-and-fail-setup-volume\" (UniqueName: \"fake-plugin/timeout-and-fail-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:09.746298  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:09.746455  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:09.746848  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:10.746660306 +0000 UTC m=+66.424096946 (durationBeforeRetry 1s). Error: "MapVolume.MapPodDevice failed for volume \"timeout-and-fail-setup-volume\" (UniqueName: \"fake-plugin/timeout-and-fail-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:10.753653  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:10.753832  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:10.754357  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:12.754138574 +0000 UTC m=+68.431575223 (durationBeforeRetry 2s). Error: "MapVolume.MapPodDevice failed for volume \"timeout-and-fail-setup-volume\" (UniqueName: \"fake-plugin/timeout-and-fail-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:12.754952  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:12.755112  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:12.755516  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:16.755326918 +0000 UTC m=+72.432763560 (durationBeforeRetry 4s). Error: "MapVolume.MapPodDevice failed for volume \"timeout-and-fail-setup-volume\" (UniqueName: \"fake-plugin/timeout-and-fail-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:16.785256  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:16.785441  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:16.785886  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:24.7856874 +0000 UTC m=+80.463124042 (durationBeforeRetry 8s). Error: "MapVolume.MapPodDevice failed for volume \"timeout-and-fail-setup-volume\" (UniqueName: \"fake-plugin/timeout-and-fail-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:19.361593  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") on node "mynodename" 
I0624 09:03:19.361988  148475 operation_generator.go:1282] UnmapDevice succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") on node "mynodename" 
I0624 09:03:19.362235  148475 reconciler.go:319] Volume detached for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:03:19.462662  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") 
I0624 09:03:19.462740  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:03:19.462804  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:03:19.463244  148475 operation_generator.go:1357] Controller attach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:03:19.464515  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:03:19.464674  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:19.564414  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:19.564789  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:19.566056  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-setup-volume-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:20.065454807 +0000 UTC m=+75.742891464 (durationBeforeRetry 500ms). Error: "MapVolume.MapPodDevice failed for volume \"success-and-timeout-setup-volume-name\" (UniqueName: \"fake-plugin/success-and-timeout-setup-volume-name\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:20.099395  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:20.099575  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:20.102757  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-setup-volume-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:21.102548201 +0000 UTC m=+76.779984851 (durationBeforeRetry 1s). Error: "MapVolume.MapPodDevice failed for volume \"success-and-timeout-setup-volume-name\" (UniqueName: \"fake-plugin/success-and-timeout-setup-volume-name\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:21.127438  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:21.127612  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:21.128059  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-setup-volume-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:23.127855505 +0000 UTC m=+78.805292157 (durationBeforeRetry 2s). Error: "MapVolume.MapPodDevice failed for volume \"success-and-timeout-setup-volume-name\" (UniqueName: \"fake-plugin/success-and-timeout-setup-volume-name\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:23.149525  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:23.149700  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:23.150164  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-setup-volume-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:27.14994227 +0000 UTC m=+82.827378913 (durationBeforeRetry 4s). Error: "MapVolume.MapPodDevice failed for volume \"success-and-timeout-setup-volume-name\" (UniqueName: \"fake-plugin/success-and-timeout-setup-volume-name\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:27.156755  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:27.156927  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:27.157348  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-setup-volume-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:35.157149581 +0000 UTC m=+90.834586228 (durationBeforeRetry 8s). Error: "MapVolume.MapPodDevice failed for volume \"success-and-timeout-setup-volume-name\" (UniqueName: \"fake-plugin/success-and-timeout-setup-volume-name\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:29.620236  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1uid" (UID: "pod1uid") 
I0624 09:03:29.620602  148475 operation_generator.go:1170] UnmapVolume succeeded for volume "fake-plugin/success-and-timeout-setup-volume-name" (OuterVolumeSpecName: "success-and-timeout-setup-volume-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "success-and-timeout-setup-volume-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:03:29.621112  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") on node "mynodename" 
I0624 09:03:29.621285  148475 operation_generator.go:1282] UnmapDevice succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") on node "mynodename" 
I0624 09:03:29.621495  148475 reconciler.go:319] Volume detached for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:03:29.740818  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") 
I0624 09:03:29.740900  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:03:29.740953  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:03:29.741676  148475 operation_generator.go:1357] Controller attach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:03:29.742593  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:03:29.742728  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:29.859800  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:29.859970  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:29.860392  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-setup-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:30.360195294 +0000 UTC m=+86.037631947 (durationBeforeRetry 500ms). Error: "MapVolume.MapPodDevice failed for volume \"success-and-failed-setup-device-name\" (UniqueName: \"fake-plugin/success-and-failed-setup-device-name\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:30.404627  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:30.404836  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:30.405339  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-setup-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:31.405098877 +0000 UTC m=+87.082535518 (durationBeforeRetry 1s). Error: "MapVolume.MapPodDevice failed for volume \"success-and-failed-setup-device-name\" (UniqueName: \"fake-plugin/success-and-failed-setup-device-name\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:31.444769  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:31.444952  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:31.445378  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-setup-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:33.445175266 +0000 UTC m=+89.122611911 (durationBeforeRetry 2s). Error: "MapVolume.MapPodDevice failed for volume \"success-and-failed-setup-device-name\" (UniqueName: \"fake-plugin/success-and-failed-setup-device-name\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:33.445974  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:33.446160  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:33.446624  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-setup-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:37.446372791 +0000 UTC m=+93.123809435 (durationBeforeRetry 4s). Error: "MapVolume.MapPodDevice failed for volume \"success-and-failed-setup-device-name\" (UniqueName: \"fake-plugin/success-and-failed-setup-device-name\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:37.447825  148475 operation_generator.go:973] MapVolume.WaitForAttach entering for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:37.448015  148475 operation_generator.go:982] MapVolume.WaitForAttach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:37.449202  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-setup-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:45.449004556 +0000 UTC m=+101.126441205 (durationBeforeRetry 8s). Error: "MapVolume.MapPodDevice failed for volume \"success-and-failed-setup-device-name\" (UniqueName: \"fake-plugin/success-and-failed-setup-device-name\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:39.909477  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1uid" (UID: "pod1uid") 
I0624 09:03:39.909718  148475 operation_generator.go:1170] UnmapVolume succeeded for volume "fake-plugin/success-and-failed-setup-device-name" (OuterVolumeSpecName: "success-and-failed-setup-device-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "success-and-failed-setup-device-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:03:39.910297  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") on node "mynodename" 
I0624 09:03:39.910501  148475 operation_generator.go:1282] UnmapDevice succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") on node "mynodename" 
I0624 09:03:39.910816  148475 reconciler.go:319] Volume detached for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:03:40.005098  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") pod "pod1" (UID: "pod1uid") 
I0624 09:03:40.005181  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:03:40.005237  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:03:40.006929  148475 operation_generator.go:1357] Controller attach succeeded for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:03:40.007754  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:03:40.007877  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:40.007975  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") pod "pod1" (UID: "pod1uid") device mount path ""
E0624 09:03:40.008341  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:40.508197388 +0000 UTC m=+96.185634030 (durationBeforeRetry 500ms). Error: "MountVolume.SetUp failed for volume \"timeout-setup-volume\" (UniqueName: \"fake-plugin/timeout-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:40.104565  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") pod "pod1uid" (UID: "pod1uid") 
I0624 09:03:40.105037  148475 operation_generator.go:797] UnmountVolume.TearDown succeeded for volume "fake-plugin/timeout-setup-volume" (OuterVolumeSpecName: "timeout-setup-volume") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "timeout-setup-volume". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:03:40.105528  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") on node "mynodename" 
I0624 09:03:40.105839  148475 operation_generator.go:891] UnmountDevice succeeded for volume "timeout-setup-volume" %!(EXTRA string=UnmountDevice succeeded for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") on node "mynodename" )
I0624 09:03:40.106036  148475 reconciler.go:319] Volume detached for volume "timeout-setup-volume" (UniqueName: "fake-plugin/timeout-setup-volume") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:03:40.229024  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") pod "pod1" (UID: "pod1uid") 
I0624 09:03:40.229126  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:03:40.229188  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:03:40.229761  148475 operation_generator.go:1357] Controller attach succeeded for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:03:40.305243  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:03:40.305413  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:40.305520  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") pod "pod1" (UID: "pod1uid") device mount path ""
E0624 09:03:40.320221  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/fail-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:40.805757312 +0000 UTC m=+96.483193951 (durationBeforeRetry 500ms). Error: "MountVolume.SetUp failed for volume \"fail-setup-volume\" (UniqueName: \"fake-plugin/fail-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:40.329443  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") on node "mynodename" 
I0624 09:03:40.329813  148475 operation_generator.go:891] UnmountDevice succeeded for volume "fail-setup-volume" %!(EXTRA string=UnmountDevice succeeded for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") on node "mynodename" )
I0624 09:03:40.330065  148475 reconciler.go:319] Volume detached for volume "fail-setup-volume" (UniqueName: "fake-plugin/fail-setup-volume") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:03:40.437252  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") 
I0624 09:03:40.437336  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:03:40.437393  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:03:40.437655  148475 operation_generator.go:1357] Controller attach succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:03:40.438488  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:03:40.438637  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:40.438776  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") device mount path ""
E0624 09:03:40.439318  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:40.939063463 +0000 UTC m=+96.616500102 (durationBeforeRetry 500ms). Error: "MountVolume.SetUp failed for volume \"timeout-and-fail-setup-volume\" (UniqueName: \"fake-plugin/timeout-and-fail-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:40.952456  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:40.952601  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:40.953028  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:41.952817853 +0000 UTC m=+97.630254514 (durationBeforeRetry 1s). Error: "MountVolume.SetUp failed for volume \"timeout-and-fail-setup-volume\" (UniqueName: \"fake-plugin/timeout-and-fail-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:41.957909  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:41.958092  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:41.958561  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:43.958328428 +0000 UTC m=+99.635765069 (durationBeforeRetry 2s). Error: "MountVolume.SetUp failed for volume \"timeout-and-fail-setup-volume\" (UniqueName: \"fake-plugin/timeout-and-fail-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:43.962085  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:43.962262  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:43.962682  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:47.962483572 +0000 UTC m=+103.639920235 (durationBeforeRetry 4s). Error: "MountVolume.SetUp failed for volume \"timeout-and-fail-setup-volume\" (UniqueName: \"fake-plugin/timeout-and-fail-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:47.969561  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:47.969740  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:47.970215  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/timeout-and-fail-setup-volume podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:55.970016176 +0000 UTC m=+111.647452818 (durationBeforeRetry 8s). Error: "MountVolume.SetUp failed for volume \"timeout-and-fail-setup-volume\" (UniqueName: \"fake-plugin/timeout-and-fail-setup-volume\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:03:50.549874  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") on node "mynodename" 
I0624 09:03:50.550460  148475 operation_generator.go:891] UnmountDevice succeeded for volume "timeout-and-fail-setup-volume" %!(EXTRA string=UnmountDevice succeeded for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") on node "mynodename" )
I0624 09:03:50.550715  148475 reconciler.go:319] Volume detached for volume "timeout-and-fail-setup-volume" (UniqueName: "fake-plugin/timeout-and-fail-setup-volume") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:03:50.638701  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") 
I0624 09:03:50.638791  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:03:50.638854  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:03:50.639306  148475 operation_generator.go:1357] Controller attach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:03:50.640210  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:03:50.640385  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:50.640547  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") device mount path ""
I0624 09:03:50.739997  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:50.740265  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:50.740744  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-setup-volume-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:51.240512907 +0000 UTC m=+106.917949564 (durationBeforeRetry 500ms). Error: "MountVolume.SetUp failed for volume \"success-and-timeout-setup-volume-name\" (UniqueName: \"fake-plugin/success-and-timeout-setup-volume-name\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:51.253498  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:51.253668  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:51.254111  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-setup-volume-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:52.253918841 +0000 UTC m=+107.931355483 (durationBeforeRetry 1s). Error: "MountVolume.SetUp failed for volume \"success-and-timeout-setup-volume-name\" (UniqueName: \"fake-plugin/success-and-timeout-setup-volume-name\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:52.262316  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:52.262510  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:52.262935  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-setup-volume-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:54.262733715 +0000 UTC m=+109.940170366 (durationBeforeRetry 2s). Error: "MountVolume.SetUp failed for volume \"success-and-timeout-setup-volume-name\" (UniqueName: \"fake-plugin/success-and-timeout-setup-volume-name\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:54.271779  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:54.272099  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:54.272548  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-setup-volume-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:03:58.272342844 +0000 UTC m=+113.949779485 (durationBeforeRetry 4s). Error: "MountVolume.SetUp failed for volume \"success-and-timeout-setup-volume-name\" (UniqueName: \"fake-plugin/success-and-timeout-setup-volume-name\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:03:58.300946  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:03:58.301130  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:03:58.301874  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-timeout-setup-volume-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:04:06.301360456 +0000 UTC m=+121.978797093 (durationBeforeRetry 8s). Error: "MountVolume.SetUp failed for volume \"success-and-timeout-setup-volume-name\" (UniqueName: \"fake-plugin/success-and-timeout-setup-volume-name\") pod \"pod1\" (UID: \"pod1uid\") : time out on setup"
I0624 09:04:00.752399  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") pod "pod1uid" (UID: "pod1uid") 
I0624 09:04:00.752942  148475 operation_generator.go:797] UnmountVolume.TearDown succeeded for volume "fake-plugin/success-and-timeout-setup-volume-name" (OuterVolumeSpecName: "success-and-timeout-setup-volume-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "success-and-timeout-setup-volume-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:04:00.753481  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") on node "mynodename" 
I0624 09:04:00.754013  148475 operation_generator.go:891] UnmountDevice succeeded for volume "success-and-timeout-setup-volume-name" %!(EXTRA string=UnmountDevice succeeded for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") on node "mynodename" )
I0624 09:04:00.754241  148475 reconciler.go:319] Volume detached for volume "success-and-timeout-setup-volume-name" (UniqueName: "fake-plugin/success-and-timeout-setup-volume-name") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:04:00.886971  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") 
I0624 09:04:00.887054  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:04:00.887114  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:04:00.887533  148475 operation_generator.go:1357] Controller attach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") device path: "fake/path"
I0624 09:04:00.888394  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "fake/path"
I0624 09:04:00.888538  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:04:00.888672  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") device mount path ""
I0624 09:04:00.987291  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:04:00.987485  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:04:00.987934  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-setup-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:04:01.487701839 +0000 UTC m=+117.165138481 (durationBeforeRetry 500ms). Error: "MountVolume.SetUp failed for volume \"success-and-failed-setup-device-name\" (UniqueName: \"fake-plugin/success-and-failed-setup-device-name\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:04:01.494930  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:04:01.495106  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:04:01.506028  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-setup-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:04:02.495327058 +0000 UTC m=+118.172763712 (durationBeforeRetry 1s). Error: "MountVolume.SetUp failed for volume \"success-and-failed-setup-device-name\" (UniqueName: \"fake-plugin/success-and-failed-setup-device-name\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:04:02.496093  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:04:02.496298  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:04:02.496753  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-setup-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:04:04.496526968 +0000 UTC m=+120.173963611 (durationBeforeRetry 2s). Error: "MountVolume.SetUp failed for volume \"success-and-failed-setup-device-name\" (UniqueName: \"fake-plugin/success-and-failed-setup-device-name\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:04:04.496918  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:04:04.497096  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:04:04.497545  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-setup-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:04:08.497343355 +0000 UTC m=+124.174779996 (durationBeforeRetry 4s). Error: "MountVolume.SetUp failed for volume \"success-and-failed-setup-device-name\" (UniqueName: \"fake-plugin/success-and-failed-setup-device-name\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:04:08.498346  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:04:08.498518  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
E0624 09:04:08.502975  148475 nestedpendingoperations.go:301] Operation for "{volumeName:fake-plugin/success-and-failed-setup-device-name podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:04:16.502753367 +0000 UTC m=+132.180190021 (durationBeforeRetry 8s). Error: "MountVolume.SetUp failed for volume \"success-and-failed-setup-device-name\" (UniqueName: \"fake-plugin/success-and-failed-setup-device-name\") pod \"pod1\" (UID: \"pod1uid\") : mounting volume failed"
I0624 09:04:10.987032  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") pod "pod1uid" (UID: "pod1uid") 
I0624 09:04:10.987775  148475 operation_generator.go:797] UnmountVolume.TearDown succeeded for volume "fake-plugin/success-and-failed-setup-device-name" (OuterVolumeSpecName: "success-and-failed-setup-device-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "success-and-failed-setup-device-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:04:10.988340  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") on node "mynodename" 
I0624 09:04:10.988612  148475 operation_generator.go:891] UnmountDevice succeeded for volume "success-and-failed-setup-device-name" %!(EXTRA string=UnmountDevice succeeded for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") on node "mynodename" )
I0624 09:04:10.988971  148475 reconciler.go:319] Volume detached for volume "success-and-failed-setup-device-name" (UniqueName: "fake-plugin/success-and-failed-setup-device-name") on node "mynodename" DevicePath "/dev/sdb"
I0624 09:04:11.093826  148475 reconciler.go:224] operationExecutor.VerifyControllerAttachedVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") 
I0624 09:04:11.093922  148475 reconciler.go:157] Reconciler: start to sync state
E0624 09:04:11.093978  148475 reconciler.go:389] Cannot get volumes from disk open fake-dir: no such file or directory
I0624 09:04:11.094446  148475 operation_generator.go:1357] Controller attach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") device path: "/fake/path"
I0624 09:04:11.100207  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/fake/path"
I0624 09:04:11.100339  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:04:11.100454  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") device mount path ""
I0624 09:04:11.196938  148475 reconciler.go:196] operationExecutor.UnmountVolume started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1uid" (UID: "pod1uid") 
I0624 09:04:11.197291  148475 operation_generator.go:797] UnmountVolume.TearDown succeeded for volume "fake-plugin/fake-device1" (OuterVolumeSpecName: "volume-name") pod "pod1uid" (UID: "pod1uid"). InnerVolumeSpecName "volume-name". PluginName "fake-plugin", VolumeGidValue ""
I0624 09:04:11.197741  148475 reconciler.go:312] operationExecutor.UnmountDevice started for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" 
I0624 09:04:11.197892  148475 reconciler_test.go:1798] UnmountDevice called
I0624 09:04:11.198072  148475 operation_generator.go:891] UnmountDevice succeeded for volume "volume-name" %!(EXTRA string=UnmountDevice succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") on node "mynodename" )
I0624 09:04:11.198882  148475 operation_generator.go:556] MountVolume.WaitForAttach entering for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:04:11.199003  148475 operation_generator.go:565] MountVolume.WaitForAttach succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") DevicePath "/dev/sdb"
I0624 09:04:11.199101  148475 operation_generator.go:594] MountVolume.MountDevice succeeded for volume "volume-name" (UniqueName: "fake-plugin/fake-device1") pod "pod1" (UID: "pod1uid") device mount path ""
FAIL

				from junit_bazel.xml

Find pod1 mentions in log files | View test history on testgrid


Show 1938 Passed Tests