This job view page is being replaced by Spyglass soon. Check out the new job view.
PRdobsonj: Automated cherry pick of #102576: kubelet: do not call RemoveAll on volumes directory for
ResultFAILURE
Tests 2 failed / 1937 succeeded
Started2021-07-21 20:39
Elapsed31m7s
Revisionb8dd8fb08e5da3e2b8a00f3c3c1abc43f811b9e4
Refs 103828

Test Failures


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

bazel test //pkg/controller/volume/attachdetach/go_default_test:run_2_of_2
exec ${PAGER:-/usr/bin/less} "$0" || exit 1
Executing tests from //pkg/controller/volume/attachdetach:go_default_test
-----------------------------------------------------------------------------
I0721 21:02:15.924890  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:16.025580  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:16.036723  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:16.036868  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:16.044093  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:16.045703  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:16.045811  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:16.045990  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:16.047490  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:16.047595  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:16.047846  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:16.049166  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:16.049932  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:16.049264  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:16.051306  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:16.051548  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:16.051711  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:16.051807  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:16.052852  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:16.053252  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:16.053375  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:16.053480  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:16.053593  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:16.053690  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:18.044218  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:18.149938  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:18.174416  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:18.174526  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:18.174635  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:18.176003  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:18.176141  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:18.176249  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:18.177395  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:18.177545  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:18.177659  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:18.178773  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:18.178935  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:18.179063  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:18.180148  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:18.180292  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:18.180405  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:18.180544  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:18.180749  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0721 21:02:18.181652  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:18.181872  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:18.182162  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:18.182337  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:18.182491  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:18.182646  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:18.192741  236276 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0721 21:02:18.192776  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0721 21:02:20.157777  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:20.266987  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:20.275086  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:20.275238  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:20.275502  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:20.276937  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:20.277070  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:20.277318  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:20.278942  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:20.279053  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:20.279445  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:20.280902  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:20.281024  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:20.281284  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:20.282622  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:20.282725  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:20.288107  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:20.289392  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:20.290350  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:20.290540  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:20.290692  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:20.290867  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:20.291032  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:20.291249  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:20.291673  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0721 21:02:20.292039  236276 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0721 21:02:20.292361  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0721 21:02:22.272366  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:22.376570  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:22.384006  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:22.385475  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:22.386870  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:22.388342  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:22.389708  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:22.390014  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:22.390294  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0721 21:02:22.390562  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName3" (UniqueName: "kubernetes.io/testPlugin/volumeName3") from node "mynode-1" 
I0721 21:02:22.391009  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0721 21:02:22.391346  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:22.391469  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:22.391728  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:22.391834  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:22.392071  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:22.392180  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:22.392260  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName3" (UniqueName: "kubernetes.io/testPlugin/volumeName3") from node "mynode-1" 
I0721 21:02:22.392366  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:22.392474  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:22.392496  236276 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0721 21:02:22.392598  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:22.392700  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:22.392732  236276 event.go:291] "Event occurred" object="mynamespace/newpod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName3\" "
I0721 21:02:22.392936  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:22.392954  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:22.393256  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:22.393446  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:22.393621  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:22.393817  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:24.387868  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:24.488565  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:24.495977  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:24.496119  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:24.496259  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:24.497458  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:24.497583  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:24.497680  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:24.498747  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:24.498958  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:24.499062  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:24.499916  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:24.500034  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:24.500126  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:24.500949  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:24.501153  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:24.501223  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:24.501272  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:24.501463  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "vol1" (UniqueName: "kubernetes.io/testPlugin/vol1") from node "mynode-1" 
I0721 21:02:24.501666  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "vol1" (UniqueName: "kubernetes.io/testPlugin/vol1") from node "mynode-1" 
I0721 21:02:24.501815  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:24.502126  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:24.502391  236276 event.go:291] "Event occurred" object="mynamespace/pod1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"vol1\" "
I0721 21:02:24.502614  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:24.502767  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:24.502903  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:24.503016  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:25.494438  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:25.597278  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:25.604567  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:25.604722  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:25.604879  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:25.605951  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:25.606026  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:25.606123  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:25.607295  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:25.607434  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:25.607537  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:25.608652  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:25.608829  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:25.608935  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:25.609981  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:25.610136  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:25.610247  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:25.610457  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:25.611229  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:25.611550  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:25.611610  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:25.611795  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:25.612054  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:25.612249  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:26.515119  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0721 21:02:26.515279  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0721 21:02:26.515422  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0721 21:02:26.603391  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:26.704883  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:26.712116  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:26.712382  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:26.712516  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:26.713196  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:26.713330  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:26.713461  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:26.714443  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:26.714630  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:26.714752  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:26.715744  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:26.715855  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:26.716028  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:26.717036  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:26.717223  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:26.717338  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:26.717497  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:26.718078  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:26.718279  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:26.718533  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:26.718568  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:26.718710  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:26.718927  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:27.622674  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0721 21:02:27.622840  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0721 21:02:27.622979  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0721 21:02:27.709983  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:27.810597  236276 shared_informer.go:247] Caches are synced for attach detach 
W0721 21:02:27.812413  236276 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.PersistentVolume 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
W0721 21:02:27.813069  236276 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
I0721 21:02:27.817424  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
E0721 21:02:27.818776  236276 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
E0721 21:02:27.820153  236276 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
E0721 21:02:27.821557  236276 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
E0721 21:02:27.822847  236276 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
I0721 21:02:27.824248  236276 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" 
I0721 21:02:27.824690  236276 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" 
I0721 21:02:27.824979  236276 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" 
E0721 21:02:27.825041  236276 csi_attacher.go:455] [attachment.ID=csi-77bd5b88d32d48e5a31f0073211a7dd54ed0066f008e12364f4b6ecb61dc7370] watch channel had been closed
==================
WARNING: DATA RACE
Write at 0x00c0005e6758 by goroutine 168:
  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
  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

Previous read at 0x00c0005e6758 by goroutine 78:
  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

Goroutine 168 (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

Goroutine 78 (finished) 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
==================
E0721 21:02:27.826455  236276 csi_attacher.go:455] [attachment.ID=csi-4ff6fd4b10c02f804e7435dffeb62054338b590749cdaacf18e198ee0ab6dd66] watch channel had been closed
E0721 21:02:27.826543  236276 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-07-21 21:02:28.325344495 +0000 UTC m=+12.606160994 (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"
I0721 21:02:27.827538  236276 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"
I0721 21:02:27.830308  236276 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"
E0721 21:02:27.830641  236276 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-07-21 21:02:28.32987413 +0000 UTC m=+12.610690638 (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"
I0721 21:02:27.830762  236276 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"
I0721 21:02:27.831030  236276 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"
I0721 21:02:27.831524  236276 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"
I0721 21:02:27.918114  236276 shared_informer.go:247] Caches are synced for attach detach 
W0721 21:02:27.920304  236276 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.PersistentVolumeClaim 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
W0721 21:02:27.920360  236276 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.Pod 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
W0721 21:02:27.920605  236276 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
W0721 21:02:27.921110  236276 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_2_of_2 0.00s

bazel test //pkg/controller/volume/attachdetach/go_default_test:run_2_of_2
exec ${PAGER:-/usr/bin/less} "$0" || exit 1
Executing tests from //pkg/controller/volume/attachdetach:go_default_test
-----------------------------------------------------------------------------
I0721 21:02:15.924890  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:16.025580  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:16.036723  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:16.036868  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:16.044093  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:16.045703  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:16.045811  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:16.045990  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:16.047490  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:16.047595  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:16.047846  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:16.049166  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:16.049932  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:16.049264  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:16.051306  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:16.051548  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:16.051711  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:16.051807  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:16.052852  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:16.053252  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:16.053375  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:16.053480  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:16.053593  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:16.053690  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:18.044218  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:18.149938  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:18.174416  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:18.174526  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:18.174635  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:18.176003  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:18.176141  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:18.176249  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:18.177395  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:18.177545  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:18.177659  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:18.178773  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:18.178935  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:18.179063  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:18.180148  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:18.180292  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:18.180405  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:18.180544  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:18.180749  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0721 21:02:18.181652  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:18.181872  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:18.182162  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:18.182337  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:18.182491  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:18.182646  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:18.192741  236276 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0721 21:02:18.192776  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0721 21:02:20.157777  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:20.266987  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:20.275086  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:20.275238  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:20.275502  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:20.276937  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:20.277070  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:20.277318  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:20.278942  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:20.279053  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:20.279445  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:20.280902  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:20.281024  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:20.281284  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:20.282622  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:20.282725  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:20.288107  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:20.289392  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:20.290350  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:20.290540  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:20.290692  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:20.290867  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:20.291032  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:20.291249  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:20.291673  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0721 21:02:20.292039  236276 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0721 21:02:20.292361  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0721 21:02:22.272366  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:22.376570  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:22.384006  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:22.385475  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:22.386870  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:22.388342  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:22.389708  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:22.390014  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:22.390294  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0721 21:02:22.390562  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName3" (UniqueName: "kubernetes.io/testPlugin/volumeName3") from node "mynode-1" 
I0721 21:02:22.391009  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0721 21:02:22.391346  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:22.391469  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:22.391728  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:22.391834  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:22.392071  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:22.392180  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:22.392260  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName3" (UniqueName: "kubernetes.io/testPlugin/volumeName3") from node "mynode-1" 
I0721 21:02:22.392366  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:22.392474  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:22.392496  236276 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0721 21:02:22.392598  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:22.392700  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:22.392732  236276 event.go:291] "Event occurred" object="mynamespace/newpod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName3\" "
I0721 21:02:22.392936  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:22.392954  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:22.393256  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:22.393446  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:22.393621  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:22.393817  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:24.387868  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:24.488565  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:24.495977  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:24.496119  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:24.496259  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:24.497458  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:24.497583  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:24.497680  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:24.498747  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:24.498958  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:24.499062  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:24.499916  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:24.500034  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:24.500126  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:24.500949  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:24.501153  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:24.501223  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:24.501272  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:24.501463  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "vol1" (UniqueName: "kubernetes.io/testPlugin/vol1") from node "mynode-1" 
I0721 21:02:24.501666  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "vol1" (UniqueName: "kubernetes.io/testPlugin/vol1") from node "mynode-1" 
I0721 21:02:24.501815  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:24.502126  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:24.502391  236276 event.go:291] "Event occurred" object="mynamespace/pod1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"vol1\" "
I0721 21:02:24.502614  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:24.502767  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:24.502903  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:24.503016  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:25.494438  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:25.597278  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:25.604567  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:25.604722  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:25.604879  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:25.605951  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:25.606026  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:25.606123  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:25.607295  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:25.607434  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:25.607537  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:25.608652  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:25.608829  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:25.608935  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:25.609981  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:25.610136  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:25.610247  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:25.610457  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:25.611229  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:25.611550  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:25.611610  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:25.611795  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:25.612054  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:25.612249  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:26.515119  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0721 21:02:26.515279  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0721 21:02:26.515422  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0721 21:02:26.603391  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:26.704883  236276 shared_informer.go:247] Caches are synced for attach detach 
I0721 21:02:26.712116  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:26.712382  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:26.712516  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0721 21:02:26.713196  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:26.713330  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:26.713461  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0721 21:02:26.714443  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:26.714630  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:26.714752  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0721 21:02:26.715744  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:26.715855  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:26.716028  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0721 21:02:26.717036  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:26.717223  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:26.717338  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0721 21:02:26.717497  236276 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:26.718078  236276 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:26.718279  236276 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:26.718533  236276 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:26.718568  236276 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0721 21:02:26.718710  236276 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:26.718927  236276 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0721 21:02:27.622674  236276 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0721 21:02:27.622840  236276 operation_generator.go:1409] Verified volume is safe to detach for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0721 21:02:27.622979  236276 operation_generator.go:470] DetachVolume.Detach succeeded for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0721 21:02:27.709983  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
I0721 21:02:27.810597  236276 shared_informer.go:247] Caches are synced for attach detach 
W0721 21:02:27.812413  236276 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.PersistentVolume 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
W0721 21:02:27.813069  236276 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
I0721 21:02:27.817424  236276 shared_informer.go:240] Waiting for caches to sync for attach detach
E0721 21:02:27.818776  236276 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
E0721 21:02:27.820153  236276 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
E0721 21:02:27.821557  236276 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
E0721 21:02:27.822847  236276 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
I0721 21:02:27.824248  236276 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" 
I0721 21:02:27.824690  236276 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" 
I0721 21:02:27.824979  236276 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" 
E0721 21:02:27.825041  236276 csi_attacher.go:455] [attachment.ID=csi-77bd5b88d32d48e5a31f0073211a7dd54ed0066f008e12364f4b6ecb61dc7370] watch channel had been closed
==================
WARNING: DATA RACE
Write at 0x00c0005e6758 by goroutine 168:
  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
  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

Previous read at 0x00c0005e6758 by goroutine 78:
  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

Goroutine 168 (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

Goroutine 78 (finished) 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
==================
E0721 21:02:27.826455  236276 csi_attacher.go:455] [attachment.ID=csi-4ff6fd4b10c02f804e7435dffeb62054338b590749cdaacf18e198ee0ab6dd66] watch channel had been closed
E0721 21:02:27.826543  236276 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-07-21 21:02:28.325344495 +0000 UTC m=+12.606160994 (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"
I0721 21:02:27.827538  236276 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"
I0721 21:02:27.830308  236276 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"
E0721 21:02:27.830641  236276 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-07-21 21:02:28.32987413 +0000 UTC m=+12.610690638 (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"
I0721 21:02:27.830762  236276 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"
I0721 21:02:27.831030  236276 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"
I0721 21:02:27.831524  236276 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"
I0721 21:02:27.918114  236276 shared_informer.go:247] Caches are synced for attach detach 
W0721 21:02:27.920304  236276 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.PersistentVolumeClaim 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
W0721 21:02:27.920360  236276 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.Pod 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
W0721 21:02:27.920605  236276 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
W0721 21:02:27.921110  236276 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


Show 1937 Passed Tests