This job view page is being replaced by Spyglass soon. Check out the new job view.
ResultFAILURE
Tests 2 failed / 1939 succeeded
Started2021-06-24 09:21
Elapsed31m52s
Revisionrelease-1.20

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
-----------------------------------------------------------------------------
I0624 09:50:03.610785  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:03.717711  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:03.731311  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:03.731580  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:03.731699  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:03.732429  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:03.732598  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:03.732718  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:03.733432  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:03.733684  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:03.733798  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:03.734508  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:03.734640  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:03.734764  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:03.735642  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:03.735771  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:03.735891  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:03.738144  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:03.738353  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:03.738431  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:03.738520  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:03.738690  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:03.738875  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:03.740956  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:05.729793  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:05.830587  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:05.837684  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:05.838027  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:05.838150  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:05.838830  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:05.839088  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:05.839210  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:05.840083  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:05.840185  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:05.840288  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:05.841357  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:05.841516  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:05.841638  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:05.842579  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:05.842667  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:05.842759  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:05.842957  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:05.843238  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:50:05.843654  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:50:05.843912  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:05.844177  270768 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0624 09:50:05.844236  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:05.844353  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:05.844634  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:05.844781  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:05.844915  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:07.835904  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:07.940432  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:07.947584  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:07.947853  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:07.948053  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:07.949245  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:07.949378  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:07.949525  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:07.950792  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:07.950921  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:07.951040  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:07.952294  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:07.952431  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:07.952551  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:07.953662  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:07.953777  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:07.953930  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:07.954035  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:07.954278  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:50:07.954774  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:50:07.955201  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:07.955263  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:07.955414  270768 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0624 09:50:07.955635  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:07.955834  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:07.956032  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:07.956195  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:09.945815  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:10.047361  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:10.053315  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:10.054240  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:10.055109  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:10.055945  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:10.055984  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:10.056080  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:10.056113  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:10.055997  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:10.056223  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:10.056700  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:10.056952  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:10.057077  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:10.058036  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:10.058175  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:10.058298  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:10.058332  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:10.058609  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:50:10.059211  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:10.059419  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:10.059429  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:10.059816  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:10.059885  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:50:10.060009  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:10.060195  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:10.060548  270768 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0624 09:50:10.060760  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName3" (UniqueName: "kubernetes.io/testPlugin/volumeName3") from node "mynode-1" 
I0624 09:50:10.061095  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName3" (UniqueName: "kubernetes.io/testPlugin/volumeName3") from node "mynode-1" 
I0624 09:50:10.061225  270768 event.go:291] "Event occurred" object="mynamespace/newpod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName3\" "
I0624 09:50:12.052808  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:12.153355  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:12.160812  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:12.162229  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:12.163561  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:12.163985  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:12.164118  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:12.164185  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:12.164454  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:12.164605  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:12.164797  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:12.164961  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:12.165275  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:12.165405  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:12.166104  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:12.166217  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:12.166337  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:12.166359  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:12.166563  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "vol1" (UniqueName: "kubernetes.io/testPlugin/vol1") from node "mynode-1" 
I0624 09:50:12.167020  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "vol1" (UniqueName: "kubernetes.io/testPlugin/vol1") from node "mynode-1" 
I0624 09:50:12.167599  270768 event.go:291] "Event occurred" object="mynamespace/pod1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"vol1\" "
I0624 09:50:12.167608  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:12.167954  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:12.168135  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:12.168323  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:12.168499  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:12.168672  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:13.159480  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:13.265813  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:13.272402  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:13.272579  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:13.272743  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:13.273709  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:13.273868  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:13.274000  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:13.275067  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:13.275252  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:13.275410  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:13.276234  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:13.276484  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:13.276620  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:13.277335  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:13.277470  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:13.277610  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:13.278386  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:13.278598  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:13.278693  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:13.278792  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:13.278988  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:13.279153  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:13.279234  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:14.183661  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:50:14.183852  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:50:14.183988  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:50:14.270689  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:14.373151  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:14.380476  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:14.380624  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:14.380788  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:14.381839  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:14.381965  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:14.382091  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:14.383150  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:14.383267  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:14.383400  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:14.384459  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:14.384597  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:14.384721  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:14.385754  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:14.385946  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:14.386074  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:14.386162  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:14.386879  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:14.387106  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:14.387239  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:14.387320  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:14.387536  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:14.387784  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:15.291041  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:50:15.291208  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:50:15.291343  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:50:15.386021  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:15.486572  270768 shared_informer.go:247] Caches are synced for attach detach 
W0624 09:50:15.488376  270768 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
W0624 09:50:15.488427  270768 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
W0624 09:50:15.488616  270768 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.CSINode 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
W0624 09:50:15.488952  270768 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
I0624 09:50:15.492781  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
E0624 09:50:15.494288  270768 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" : no volume plugin matched name: kubernetes.io/testPlugin
E0624 09:50:15.495687  270768 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" : no volume plugin matched name: kubernetes.io/testPlugin
E0624 09:50:15.497130  270768 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" : no volume plugin matched name: kubernetes.io/testPlugin
E0624 09:50:15.498440  270768 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" : no volume plugin matched name: kubernetes.io/testPlugin
I0624 09:50:15.506904  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/vol1") on node "mynode-1" 
I0624 09:50:15.507117  270768 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" 
I0624 09:50:15.507420  270768 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" 
E0624 09:50:15.507486  270768 csi_attacher.go:455] [attachment.ID=csi-77bd5b88d32d48e5a31f0073211a7dd54ed0066f008e12364f4b6ecb61dc7370] watch channel had been closed
==================
WARNING: DATA RACE
Write at 0x00c00030cfa8 by goroutine 185:
  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 0x00c00030cfa8 by goroutine 183:
  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 185 (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 183 (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
E0624 09:50:15.508092  270768 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/vol1 podName: nodeName:mynode-1}" failed. No retries permitted until 2021-06-24 09:50:16.007824385 +0000 UTC m=+12.528910836 (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"
==================
E0624 09:50:15.508282  270768 csi_attacher.go:455] [attachment.ID=csi-4ff6fd4b10c02f804e7435dffeb62054338b590749cdaacf18e198ee0ab6dd66] watch channel had been closed
E0624 09:50:15.509424  270768 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/pdName podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:50:16.009173376 +0000 UTC m=+12.530259824 (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"
I0624 09:50:15.509740  270768 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"
I0624 09:50:15.509990  270768 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"
I0624 09:50:15.510194  270768 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"
I0624 09:50:15.510417  270768 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"
I0624 09:50:15.510633  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" : volume attachment watch channel had been closed"
I0624 09:50:15.596120  270768 shared_informer.go:247] Caches are synced for attach detach 
W0624 09:50:15.597754  270768 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
W0624 09:50:15.597804  270768 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
W0624 09:50:15.597937  270768 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.CSINode 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
W0624 09:50:15.598452  270768 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
W0624 09:50:15.597995  270768 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.CSIDriver 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.55s)
    --- 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
-----------------------------------------------------------------------------
I0624 09:50:03.610785  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:03.717711  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:03.731311  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:03.731580  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:03.731699  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:03.732429  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:03.732598  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:03.732718  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:03.733432  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:03.733684  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:03.733798  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:03.734508  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:03.734640  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:03.734764  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:03.735642  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:03.735771  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:03.735891  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:03.738144  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:03.738353  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:03.738431  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:03.738520  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:03.738690  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:03.738875  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:03.740956  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:05.729793  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:05.830587  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:05.837684  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:05.838027  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:05.838150  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:05.838830  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:05.839088  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:05.839210  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:05.840083  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:05.840185  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:05.840288  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:05.841357  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:05.841516  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:05.841638  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:05.842579  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:05.842667  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:05.842759  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:05.842957  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:05.843238  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:50:05.843654  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:50:05.843912  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:05.844177  270768 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0624 09:50:05.844236  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:05.844353  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:05.844634  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:05.844781  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:05.844915  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:07.835904  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:07.940432  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:07.947584  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:07.947853  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:07.948053  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:07.949245  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:07.949378  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:07.949525  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:07.950792  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:07.950921  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:07.951040  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:07.952294  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:07.952431  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:07.952551  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:07.953662  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:07.953777  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:07.953930  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:07.954035  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:07.954278  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:50:07.954774  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:50:07.955201  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:07.955263  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:07.955414  270768 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0624 09:50:07.955635  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:07.955834  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:07.956032  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:07.956195  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:09.945815  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:10.047361  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:10.053315  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:10.054240  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:10.055109  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:10.055945  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:10.055984  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:10.056080  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:10.056113  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:10.055997  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:10.056223  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:10.056700  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:10.056952  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:10.057077  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:10.058036  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:10.058175  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:10.058298  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:10.058332  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:10.058609  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:50:10.059211  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:10.059419  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:10.059429  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:10.059816  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:10.059885  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName2" (UniqueName: "kubernetes.io/testPlugin/volumeName2") from node "mynode-1" 
I0624 09:50:10.060009  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:10.060195  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:10.060548  270768 event.go:291] "Event occurred" object="mynamespace/newpod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName2\" "
I0624 09:50:10.060760  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName3" (UniqueName: "kubernetes.io/testPlugin/volumeName3") from node "mynode-1" 
I0624 09:50:10.061095  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName3" (UniqueName: "kubernetes.io/testPlugin/volumeName3") from node "mynode-1" 
I0624 09:50:10.061225  270768 event.go:291] "Event occurred" object="mynamespace/newpod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName3\" "
I0624 09:50:12.052808  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:12.153355  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:12.160812  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:12.162229  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:12.163561  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:12.163985  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:12.164118  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:12.164185  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:12.164454  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:12.164605  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:12.164797  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:12.164961  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:12.165275  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:12.165405  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:12.166104  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:12.166217  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:12.166337  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:12.166359  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:12.166563  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "vol1" (UniqueName: "kubernetes.io/testPlugin/vol1") from node "mynode-1" 
I0624 09:50:12.167020  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "vol1" (UniqueName: "kubernetes.io/testPlugin/vol1") from node "mynode-1" 
I0624 09:50:12.167599  270768 event.go:291] "Event occurred" object="mynamespace/pod1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"vol1\" "
I0624 09:50:12.167608  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:12.167954  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:12.168135  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:12.168323  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:12.168499  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:12.168672  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:13.159480  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:13.265813  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:13.272402  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:13.272579  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:13.272743  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:13.273709  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:13.273868  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:13.274000  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:13.275067  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:13.275252  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:13.275410  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:13.276234  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:13.276484  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:13.276620  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:13.277335  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:13.277470  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:13.277610  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:13.278386  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:13.278598  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:13.278693  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:13.278792  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:13.278988  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:13.279153  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:13.279234  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:14.183661  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:50:14.183852  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:50:14.183988  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:50:14.270689  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:14.373151  270768 shared_informer.go:247] Caches are synced for attach detach 
I0624 09:50:14.380476  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:14.380624  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:14.380788  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" 
I0624 09:50:14.381839  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:14.381965  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:14.382091  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" 
I0624 09:50:14.383150  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:14.383267  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:14.383400  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-1" 
I0624 09:50:14.384459  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:14.384597  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:14.384721  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" 
I0624 09:50:14.385754  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:14.385946  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:14.386074  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" 
I0624 09:50:14.386162  270768 reconciler.go:295] attacherDetacher.AttachVolume started for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:14.386879  270768 event.go:291] "Event occurred" object="mynamespace/mypod-2" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:14.387106  270768 event.go:291] "Event occurred" object="mynamespace/mypod-3" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:14.387239  270768 operation_generator.go:360] AttachVolume.Attach succeeded for volume "volumeName" (UniqueName: "kubernetes.io/testPlugin/volumeName") from node "mynode" 
I0624 09:50:14.387320  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:14.387536  270768 event.go:291] "Event occurred" object="mynamespace/mypod-0" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:14.387784  270768 event.go:291] "Event occurred" object="mynamespace/mypod-1" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"volumeName\" "
I0624 09:50:15.291041  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:50:15.291208  270768 operation_generator.go:1409] Verified volume is safe to detach for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:50:15.291343  270768 operation_generator.go:470] DetachVolume.Detach succeeded for volume "pv1" (UniqueName: "kubernetes.io/testPlugin/vol1") on node "mynode-1" 
I0624 09:50:15.386021  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
I0624 09:50:15.486572  270768 shared_informer.go:247] Caches are synced for attach detach 
W0624 09:50:15.488376  270768 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
W0624 09:50:15.488427  270768 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
W0624 09:50:15.488616  270768 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.CSINode 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
W0624 09:50:15.488952  270768 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
I0624 09:50:15.492781  270768 shared_informer.go:240] Waiting for caches to sync for attach detach
E0624 09:50:15.494288  270768 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-4" : no volume plugin matched name: kubernetes.io/testPlugin
E0624 09:50:15.495687  270768 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode" : no volume plugin matched name: kubernetes.io/testPlugin
E0624 09:50:15.497130  270768 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-2" : no volume plugin matched name: kubernetes.io/testPlugin
E0624 09:50:15.498440  270768 reconciler.go:228] attacherDetacher.DetachVolume failed to start for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" : DetachVolume.FindAttachablePluginByName failed for volume "nil" (UniqueName: "kubernetes.io/testPlugin/lostVolumeName") on node "mynode-3" : no volume plugin matched name: kubernetes.io/testPlugin
I0624 09:50:15.506904  270768 reconciler.go:219] attacherDetacher.DetachVolume started for volume "nil" (UniqueName: "kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/vol1") on node "mynode-1" 
I0624 09:50:15.507117  270768 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" 
I0624 09:50:15.507420  270768 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" 
E0624 09:50:15.507486  270768 csi_attacher.go:455] [attachment.ID=csi-77bd5b88d32d48e5a31f0073211a7dd54ed0066f008e12364f4b6ecb61dc7370] watch channel had been closed
==================
WARNING: DATA RACE
Write at 0x00c00030cfa8 by goroutine 185:
  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 0x00c00030cfa8 by goroutine 183:
  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 185 (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 183 (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
E0624 09:50:15.508092  270768 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/vol1 podName: nodeName:mynode-1}" failed. No retries permitted until 2021-06-24 09:50:16.007824385 +0000 UTC m=+12.528910836 (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"
==================
E0624 09:50:15.508282  270768 csi_attacher.go:455] [attachment.ID=csi-4ff6fd4b10c02f804e7435dffeb62054338b590749cdaacf18e198ee0ab6dd66] watch channel had been closed
E0624 09:50:15.509424  270768 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/pd.csi.storage.gke.io^projects/UNSPECIFIED/zones/UNSPECIFIED/disks/pdName podName: nodeName:}" failed. No retries permitted until 2021-06-24 09:50:16.009173376 +0000 UTC m=+12.530259824 (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"
I0624 09:50:15.509740  270768 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"
I0624 09:50:15.509990  270768 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"
I0624 09:50:15.510194  270768 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"
I0624 09:50:15.510417  270768 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"
I0624 09:50:15.510633  270768 event.go:291] "Event occurred" object="mynamespace/mypod-4" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pd.csi.storage.gke.io-pdName\" : volume attachment watch channel had been closed"
I0624 09:50:15.596120  270768 shared_informer.go:247] Caches are synced for attach detach 
W0624 09:50:15.597754  270768 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
W0624 09:50:15.597804  270768 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
W0624 09:50:15.597937  270768 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.CSINode 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
W0624 09:50:15.598452  270768 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
W0624 09:50:15.597995  270768 reflector.go:436] k8s.io/client-go/informers/factory.go:134: watch of *v1.CSIDriver 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.55s)
    --- 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 1939 Passed Tests