This job view page is being replaced by Spyglass soon. Check out the new job view.
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2022-06-06 15:30
Elapsed23m19s
Revision012b72af216204b6c6c2ebccfa01c829ae9eb7ee

No Test Failures!


Error lines from build-log.txt

... skipping 128 lines ...
=== RUN   TestValidateConfigWithNoNetPermissionParams
{"level":"info","time":"2022-06-06T15:33:47.503807893Z","caller":"config/config.go:364","msg":"No Net Permissions given in Config. Using default permissions."}
--- PASS: TestValidateConfigWithNoNetPermissionParams (0.00s)
=== RUN   TestValidateConfigWithMultipleNetPermissionParams
--- PASS: TestValidateConfigWithMultipleNetPermissionParams (0.02s)
=== RUN   TestValidateConfigWithInvalidPermissions
{"level":"error","time":"2022-06-06T15:33:47.529172793Z","caller":"config/config.go:375","msg":"Invalid value WRITE_ONLY for Permissions under NetPermission Config A","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.validateConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:375\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.TestValidateConfigWithInvalidPermissions\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config_test.go:144\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestValidateConfigWithInvalidPermissions (0.00s)
=== RUN   TestValidateConfigWithInvalidClusterId
{"level":"error","time":"2022-06-06T15:33:47.529346152Z","caller":"config/config.go:316","msg":"cluster id must not exceed 64 characters","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.validateConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:316\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.TestValidateConfigWithInvalidClusterId\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config_test.go:156\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestValidateConfigWithInvalidClusterId (0.00s)
=== RUN   TestSnapshotConfigWhenMaxUnspecified
{"level":"info","time":"2022-06-06T15:33:47.550276899Z","caller":"config/config.go:364","msg":"No Net Permissions given in Config. Using default permissions."}
--- PASS: TestSnapshotConfigWhenMaxUnspecified (0.02s)
=== RUN   TestSnapshotConfigWhenMaxSpecifiedAsEnv
{"level":"info","time":"2022-06-06T15:33:47.551427008Z","caller":"config/config.go:364","msg":"No Net Permissions given in Config. Using default permissions."}
--- PASS: TestSnapshotConfigWhenMaxSpecifiedAsEnv (0.00s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config	0.125s
=== RUN   TestQuerySnapshotsUtil
{"level":"error","time":"2022-06-06T15:35:00.77819659Z","caller":"config/config.go:311","msg":"no Virtual Center hosts defined","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.validateConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:311\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.FromEnv\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:295\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.configFromEnvOrSim\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:105\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.getCommonUtilsTest.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:115\nsync.(*Once).doSlow\n\t/usr/local/go/src/sync/once.go:68\nsync.(*Once).Do\n\t/usr/local/go/src/sync/once.go:59\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.getCommonUtilsTest\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:112\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.TestQuerySnapshotsUtil\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:146\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
{"level":"info","time":"2022-06-06T15:35:01.296989124Z","caller":"vsphere/utils.go:189","msg":"Defaulting timeout for vCenter Client to 5 minutes"}
{"level":"info","time":"2022-06-06T15:35:01.297265955Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
{"level":"info","time":"2022-06-06T15:35:01.299518328Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
{"level":"info","time":"2022-06-06T15:35:01.299746544Z","caller":"vsphere/virtualcentermanager.go:122","msg":"Successfully registered VC \"127.0.0.1\""}
{"level":"info","time":"2022-06-06T15:35:01.376066443Z","caller":"vsphere/virtualcenter.go:183","msg":"New session ID for 'user' = e9b011ed-bd40-40f3-a056-350266e19816"}
{"level":"info","time":"2022-06-06T15:35:01.379344427Z","caller":"volume/manager.go:175","msg":"Initializing new defaultManager..."}
... skipping 6 lines ...
    utils_test.go:161: Snapshots: 
--- PASS: TestQuerySnapshotsUtil (0.65s)
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList/CompatibleDatastoreFound
{"level":"info","time":"2022-06-06T15:35:01.456723467Z","caller":"utils/utils.go:269","msg":"compatible datastore found, dsURL = \"/tmp/govcsim-DC0-LocalDS_1-348040436\", dsRef = Datastore:/tmp/govcsim-DC0-LocalDS_1-348040436@group-5"}
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList/FailToFindGivenDatastoreInCompatibleList
{"level":"error","time":"2022-06-06T15:35:01.535702625Z","caller":"utils/utils.go:274","msg":"failed to find datastore with URL \"/tmp/govcsim-DC0-LocalDS_1-348040436\" from the input datastore list, [Datastore:/tmp/govcsim-DC0-LocalDS_2-2405972285@group-5 Datastore:/tmp/govcsim-DC0-LocalDS_0-162214853@group-5]","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:274\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:252\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList/FailToFindGivenDatastoreInVC
{"level":"error","time":"2022-06-06T15:35:01.557054256Z","caller":"vsphere/datacenter.go:82","msg":"couldn't find Datastore given URL \"an-invalid-datastore-url\"","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/cns-lib/vsphere.(*Datacenter).GetDatastoreInfoByURL\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/cns-lib/vsphere/datacenter.go:82\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:251\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:252\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
{"level":"error","time":"2022-06-06T15:35:01.557146043Z","caller":"utils/utils.go:253","msg":"failed to find datastore with URL \"an-invalid-datastore-url\" in datacenter \"/DC0\" from VC \"127.0.0.1\", Error: couldn't find Datastore given URL \"an-invalid-datastore-url\"","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:253\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:252\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
{"level":"error","time":"2022-06-06T15:35:01.557173739Z","caller":"utils/utils.go:263","msg":"failed to find datastore with URL \"an-invalid-datastore-url\" in VC \"127.0.0.1\"","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:263\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:252\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList/EmptyDatastoreURLFromInput
{"level":"error","time":"2022-06-06T15:35:01.590430427Z","caller":"vsphere/datacenter.go:82","msg":"couldn't find Datastore given URL \"\"","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/cns-lib/vsphere.(*Datacenter).GetDatastoreInfoByURL\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/cns-lib/vsphere/datacenter.go:82\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:251\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:252\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
{"level":"error","time":"2022-06-06T15:35:01.59059372Z","caller":"utils/utils.go:253","msg":"failed to find datastore with URL \"\" in datacenter \"/DC0\" from VC \"127.0.0.1\", Error: couldn't find Datastore given URL \"\"","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:253\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:252\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
{"level":"error","time":"2022-06-06T15:35:01.590649297Z","caller":"utils/utils.go:263","msg":"failed to find datastore with URL \"\" in VC \"127.0.0.1\"","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:263\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:252\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList (0.16s)
    --- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList/CompatibleDatastoreFound (0.03s)
    --- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList/FailToFindGivenDatastoreInCompatibleList (0.08s)
    --- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList/FailToFindGivenDatastoreInVC (0.02s)
    --- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList/EmptyDatastoreURLFromInput (0.03s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils	1.077s
=== RUN   TestUseVslmAPIsFuncForVC67Update3l
--- PASS: TestUseVslmAPIsFuncForVC67Update3l (0.00s)
=== RUN   TestUseVslmAPIsFuncForVC67Update3a
{"level":"error","time":"2022-06-06T15:35:06.435318324Z","caller":"common/common_controller_helper.go:197","msg":"Found vCenter version :\"6.7.3\". The minimum version for CSI migration is vCenter Server 6.7 Update 3l","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common.UseVslmAPIs\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/common_controller_helper.go:197\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common.TestUseVslmAPIsFuncForVC67Update3a\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/common_controller_helper_test.go:77\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
    common_controller_helper_test.go:81: expected err received. err: Found vCenter version :"6.7.3". The minimum version for CSI migration is vCenter Server 6.7 Update 3l
--- PASS: TestUseVslmAPIsFuncForVC67Update3a (0.01s)
=== RUN   TestUseVslmAPIsFuncForVC6dot6
--- PASS: TestUseVslmAPIsFuncForVC6dot6 (0.00s)
=== RUN   TestUseVslmAPIsFuncForVC7
--- PASS: TestUseVslmAPIsFuncForVC7 (0.00s)
... skipping 40 lines ...
    --- PASS: TestParseCSISnapshotID/EmptyCSISnapshotID (0.00s)
    --- PASS: TestParseCSISnapshotID/UnexpectedFormattedCSISnapshotID (0.00s)
=== RUN   TestQueryVolumeSnapshotsByVolumeIDWithQuerySnapshotsCnsVolumeNotFoundFault
{"level":"warn","time":"2022-06-06T15:35:06.457852412Z","caller":"common/vsphereutil.go:910","msg":"volume dummy-id was not found during QuerySnapshots, ignore volume.."}
--- PASS: TestQueryVolumeSnapshotsByVolumeIDWithQuerySnapshotsCnsVolumeNotFoundFault (0.00s)
=== RUN   TestQueryVolumeSnapshotsByVolumeIDWithQuerySnapshotsUnexpectedFault
{"level":"error","time":"2022-06-06T15:35:06.458817532Z","caller":"common/vsphereutil.go:913","msg":"unexpected fault &{RuntimeFault:{MethodFault:{FaultCause:<nil> FaultMessage:[]}} InvalidProperty:unexpected} received in QuerySnapshots result: {DynamicData:{} Snapshot:{DynamicData:{} SnapshotId:{DynamicData:{} Id:} VolumeId:{DynamicData:{} Id:} Description: CreateTime:0001-01-01 00:00:00 +0000 UTC} Error:0xc000144180} for volume: dummy-id","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common.QueryVolumeSnapshotsByVolumeID\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/vsphereutil.go:913\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common.TestQueryVolumeSnapshotsByVolumeIDWithQuerySnapshotsUnexpectedFault\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/vsphereutil_test.go:66\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestQueryVolumeSnapshotsByVolumeIDWithQuerySnapshotsUnexpectedFault (0.00s)
=== RUN   TestQueryVolumeSnapshotWithQuerySnapshotsCnsSnapshotNotFoundFault
{"level":"error","time":"2022-06-06T15:35:06.459491485Z","caller":"common/vsphereutil.go:769","msg":"snapshot-id: dummy-snap-id not found for volume-id: dummy-id during QuerySnapshots, err: {CnsFault:{BaseMethodFault:<nil> Reason:} VolumeId:{DynamicData:{} Id:dummy-id} SnapshotId:{DynamicData:{} Id:dummy-snap-id}}","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common.QueryVolumeSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/vsphereutil.go:769\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common.TestQueryVolumeSnapshotWithQuerySnapshotsCnsSnapshotNotFoundFault\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/vsphereutil_test.go:99\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestQueryVolumeSnapshotWithQuerySnapshotsCnsSnapshotNotFoundFault (0.00s)
=== RUN   TestQueryVolumeSnapshotWithQuerySnapshotsUnexpectedFault
{"level":"error","time":"2022-06-06T15:35:06.471125505Z","caller":"common/vsphereutil.go:772","msg":"unexpected error received when retrieving snapshot info for volume-id: dummy-id snapshot-id: dummy-snap-id err: &{RuntimeFault:{MethodFault:{FaultCause:<nil> FaultMessage:[]}} InvalidProperty:unexpected}","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common.QueryVolumeSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/vsphereutil.go:772\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common.TestQueryVolumeSnapshotWithQuerySnapshotsUnexpectedFault\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/vsphereutil_test.go:126\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestQueryVolumeSnapshotWithQuerySnapshotsUnexpectedFault (0.01s)
=== RUN   TestQueryAllVolumeSnapshotsWithQuerySnapshotsUnexpectedFault
{"level":"error","time":"2022-06-06T15:35:06.472245542Z","caller":"common/vsphereutil.go:836","msg":"faults are not expected when invoking QuerySnapshots without volume-id and snapshot-id, fault: &{RuntimeFault:{MethodFault:{FaultCause:<nil> FaultMessage:[]}} InvalidProperty:unexpected}","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common.QueryAllVolumeSnapshots\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/vsphereutil.go:836\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common.TestQueryAllVolumeSnapshotsWithQuerySnapshotsUnexpectedFault\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/vsphereutil_test.go:151\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestQueryAllVolumeSnapshotsWithQuerySnapshotsUnexpectedFault (0.00s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common	0.424s
=== RUN   TestIsFSSEnabledInGcWithSync
{"level":"info","time":"2022-06-06T15:35:14.935757211Z","caller":"k8sorchestrator/k8sorchestrator.go:973","msg":"volume-health feature state set to false in internal-feature-states.csi.vsphere.vmware.com ConfigMap"}
--- PASS: TestIsFSSEnabledInGcWithSync (0.01s)
=== RUN   TestIsFSSEnabledInGcWithoutSync
{"level":"info","time":"2022-06-06T15:35:14.936864213Z","caller":"k8sorchestrator/k8sorchestrator.go:973","msg":"volume-extend feature state set to false in internal-feature-states.csi.vsphere.vmware.com ConfigMap"}
{"level":"info","time":"2022-06-06T15:35:14.937205209Z","caller":"k8sorchestrator/k8sorchestrator.go:992","msg":"volume-health feature state set to false in csi-feature-states ConfigMap"}
--- PASS: TestIsFSSEnabledInGcWithoutSync (0.00s)
=== RUN   TestIsFSSEnabledInGcWrongValues
{"level":"error","time":"2022-06-06T15:35:14.93750576Z","caller":"k8sorchestrator/k8sorchestrator.go:967","msg":"Error while converting volume-extend feature state value: false to boolean. Setting the feature state to false","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common/commonco/k8sorchestrator.(*K8sOrchestrator).IsFSSEnabled\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/commonco/k8sorchestrator/k8sorchestrator.go:967\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common/commonco/k8sorchestrator.TestIsFSSEnabledInGcWrongValues\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/commonco/k8sorchestrator/k8sorchestrator_test.go:143\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestIsFSSEnabledInGcWrongValues (0.00s)
=== RUN   TestIsFSSEnabledInSV
{"level":"error","time":"2022-06-06T15:35:14.942195435Z","caller":"k8sorchestrator/k8sorchestrator.go:953","msg":"Error while converting csi-migration feature state value: false to boolean. Setting the feature state to false","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common/commonco/k8sorchestrator.(*K8sOrchestrator).IsFSSEnabled\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/commonco/k8sorchestrator/k8sorchestrator.go:953\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common/commonco/k8sorchestrator.TestIsFSSEnabledInSV\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/commonco/k8sorchestrator/k8sorchestrator_test.go:179\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestIsFSSEnabledInSV (0.00s)
=== RUN   TestIsFSSEnabledInVanilla
{"level":"error","time":"2022-06-06T15:35:14.94351295Z","caller":"k8sorchestrator/k8sorchestrator.go:939","msg":"Error while converting volume-health feature state value: false to boolean. Setting the feature state to false","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common/commonco/k8sorchestrator.(*K8sOrchestrator).IsFSSEnabled\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/commonco/k8sorchestrator/k8sorchestrator.go:939\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common/commonco/k8sorchestrator.TestIsFSSEnabledInVanilla\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/commonco/k8sorchestrator/k8sorchestrator_test.go:217\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestIsFSSEnabledInVanilla (0.01s)
=== RUN   TestIsFSSEnabledWithWrongClusterFlavor
--- PASS: TestIsFSSEnabledWithWrongClusterFlavor (0.00s)
=== RUN   TestGetNodesForVolumes
--- PASS: TestGetNodesForVolumes (0.00s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/common/commonco/k8sorchestrator	0.324s
=== RUN   TestLogNewError
{"level":"error","time":"2022-06-06T15:34:33.249847511Z","caller":"logger/logger_test.go:27","msg":"Error Test","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/logger.TestLogNewError\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/logger/logger_test.go:27\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestLogNewError (0.01s)
=== RUN   TestLogNewErrorf
{"level":"error","time":"2022-06-06T15:34:33.257884346Z","caller":"logger/logger_test.go:35","msg":"Error Test","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/logger.TestLogNewErrorf\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/logger/logger_test.go:35\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestLogNewErrorf (0.00s)
=== RUN   TestLogNewErrorCode
{"level":"error","time":"2022-06-06T15:34:33.25828699Z","caller":"logger/logger_test.go:43","msg":"Error Test","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/logger.TestLogNewErrorCode\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/logger/logger_test.go:43\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestLogNewErrorCode (0.00s)
=== RUN   TestLogNewErrorCodef
{"level":"error","time":"2022-06-06T15:34:33.258541262Z","caller":"logger/logger_test.go:51","msg":"Error Test","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/logger.TestLogNewErrorCodef\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/logger/logger_test.go:51\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestLogNewErrorCodef (0.00s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/logger	0.079s
=== RUN   TestUnescape
=== RUN   TestUnescape/0
=== PAUSE TestUnescape/0
... skipping 2 lines ...
=== RUN   TestUnescape/2
=== PAUSE TestUnescape/2
=== RUN   TestUnescape/3
=== PAUSE TestUnescape/3
=== CONT  TestUnescape/0
=== CONT  TestUnescape/3
{"level":"info","time":"2022-06-06T15:35:03.086175276Z","caller":"osutils/linux_os_utils.go:1053","msg":"Error parsing mount \"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/foo\\\\0bc\": invalid syntax"}
=== CONT  TestUnescape/1
=== CONT  TestUnescape/2
{"level":"info","time":"2022-06-06T15:35:03.089180926Z","caller":"osutils/linux_os_utils.go:1053","msg":"Error parsing mount \"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/foo\\\\04\": invalid syntax"}
--- PASS: TestUnescape (0.00s)
    --- PASS: TestUnescape/0 (0.00s)
    --- PASS: TestUnescape/1 (0.01s)
    --- PASS: TestUnescape/3 (0.01s)
    --- PASS: TestUnescape/2 (0.01s)
=== RUN   TestGetDiskPath
... skipping 6 lines ...
--- PASS: TestGetDiskPath (0.00s)
    --- PASS: TestGetDiskPath/#00 (0.00s)
    --- PASS: TestGetDiskPath/#01 (0.00s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/osutils	0.442s
=== RUN   TestCreateVolumeWithStoragePolicy
{"level":"error","time":"2022-06-06T15:35:22.033538935Z","caller":"config/config.go:311","msg":"no Virtual Center hosts defined","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.validateConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:311\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.FromEnv\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:295\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.configFromEnvOrSim\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:167\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.getControllerTest.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:312\nsync.(*Once).doSlow\n\t/usr/local/go/src/sync/once.go:68\nsync.(*Once).Do\n\t/usr/local/go/src/sync/once.go:59\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.getControllerTest\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:309\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.TestCreateVolumeWithStoragePolicy\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:388\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
{"level":"info","time":"2022-06-06T15:35:22.464153797Z","caller":"vsphere/utils.go:189","msg":"Defaulting timeout for vCenter Client to 5 minutes"}
{"level":"info","time":"2022-06-06T15:35:22.464984272Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
{"level":"info","time":"2022-06-06T15:35:22.465126259Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
{"level":"info","time":"2022-06-06T15:35:22.465368776Z","caller":"vsphere/virtualcentermanager.go:122","msg":"Successfully registered VC \"127.0.0.1\""}
{"level":"info","time":"2022-06-06T15:35:22.502442503Z","caller":"vsphere/virtualcenter.go:183","msg":"New session ID for 'user' = 318e729b-a52f-4739-adc3-911be1580739"}
{"level":"info","time":"2022-06-06T15:35:22.504761252Z","caller":"volume/manager.go:175","msg":"Initializing new defaultManager..."}
... skipping 77 lines ...
{"level":"info","time":"2022-06-06T15:35:22.872430135Z","caller":"volume/manager.go:1039","msg":"DeleteVolume: Volume deleted successfully. volumeID: \"f89fedbe-7b1f-46af-a639-ecbea858195b\", opId: \"\"","TraceId":"767e2170-c610-4731-b976-bebc195628f7"}
{"level":"info","time":"2022-06-06T15:35:22.872563275Z","caller":"vanilla/controller.go:979","msg":"Volume \"f89fedbe-7b1f-46af-a639-ecbea858195b\" deleted successfully.","TraceId":"767e2170-c610-4731-b976-bebc195628f7"}
--- PASS: TestExtendVolume (0.10s)
=== RUN   TestMigratedExtendVolume
    controller_test.go:695: ControllerExpandVolume will be called with req +{[vsanDatastore] 08281a5f-a21d-1eff-62d6-02009d0f19a1/004dbb1694f14e3598abef852b113e3b.vmdk required_bytes:1024  map[] <nil> {} [] 0}
{"level":"info","time":"2022-06-06T15:35:22.873776094Z","caller":"vanilla/controller.go:1246","msg":"ControllerExpandVolume: called with args {VolumeId:[vsanDatastore] 08281a5f-a21d-1eff-62d6-02009d0f19a1/004dbb1694f14e3598abef852b113e3b.vmdk CapacityRange:required_bytes:1024  Secrets:map[] VolumeCapability:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"23f12bdb-837d-411b-bf89-83ed14988fbc"}
{"level":"error","time":"2022-06-06T15:35:22.873865964Z","caller":"vanilla/controller.go:1256","msg":"cannot expand migrated vSphere volume. :\"[vsanDatastore] 08281a5f-a21d-1eff-62d6-02009d0f19a1/004dbb1694f14e3598abef852b113e3b.vmdk\"","TraceId":"23f12bdb-837d-411b-bf89-83ed14988fbc","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.(*controller).ControllerExpandVolume.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:1256\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.(*controller).ControllerExpandVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:1329\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.TestMigratedExtendVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:696\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
    controller_test.go:698: Expected error received. migrated volume with VMDK path can not be expanded
--- PASS: TestMigratedExtendVolume (0.00s)
=== RUN   TestCompleteControllerFlow
{"level":"info","time":"2022-06-06T15:35:22.874294908Z","caller":"vanilla/controller.go:828","msg":"CreateVolume: called with args {Name:test-pvc-216f0771-54b6-4df2-a9e5-587f1da48339 CapacityRange:required_bytes:1073741824  VolumeCapabilities:[access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"0435ecc7-3e8e-40eb-80e1-540ca790ab78"}
{"level":"info","time":"2022-06-06T15:35:22.910470544Z","caller":"volume/manager.go:410","msg":"CreateVolume: VolumeName: \"test-pvc-216f0771-54b6-4df2-a9e5-587f1da48339\", opId: \"\"","TraceId":"0435ecc7-3e8e-40eb-80e1-540ca790ab78"}
{"level":"info","time":"2022-06-06T15:35:22.91150134Z","caller":"volume/util.go:322","msg":"Volume created successfully. VolumeName: \"test-pvc-216f0771-54b6-4df2-a9e5-587f1da48339\", volumeID: \"5bec1ba0-08df-4e39-b6b8-7fa327e7c745\"","TraceId":"0435ecc7-3e8e-40eb-80e1-540ca790ab78"}
{"level":"info","time":"2022-06-06T15:35:22.911579621Z","caller":"vanilla/controller.go:863","msg":"Volume created successfully. Volume Handle: \"5bec1ba0-08df-4e39-b6b8-7fa327e7c745\", PV Name: \"test-pvc-216f0771-54b6-4df2-a9e5-587f1da48339\"","TraceId":"0435ecc7-3e8e-40eb-80e1-540ca790ab78"}
... skipping 38 lines ...
{"level":"info","time":"2022-06-06T15:35:22.982739845Z","caller":"utils/utils.go:118","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"0fbfce37-9278-442f-bc20-1aefea5b67ea"}
{"level":"info","time":"2022-06-06T15:35:22.990418689Z","caller":"utils/utils.go:150","msg":"setting max iteration to 0 for total records count: 0","TraceId":"0fbfce37-9278-442f-bc20-1aefea5b67ea"}
{"level":"info","time":"2022-06-06T15:35:22.990475045Z","caller":"utils/utils.go:170","msg":"0 more snapshots to be queried","TraceId":"0fbfce37-9278-442f-bc20-1aefea5b67ea"}
{"level":"info","time":"2022-06-06T15:35:22.990524187Z","caller":"utils/utils.go:173","msg":"QuerySnapshots retrieved all records (0) for the SnapshotQuerySpec: {DynamicData:{} VolumeId:{DynamicData:{} Id:92ce5576-a638-44df-a072-0beb575b1ea5} SnapshotId:<nil>} in 1 iterations","TraceId":"0fbfce37-9278-442f-bc20-1aefea5b67ea"}
{"level":"info","time":"2022-06-06T15:35:22.990558567Z","caller":"utils/utils.go:208","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:92ce5576-a638-44df-a072-0beb575b1ea5}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> healthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"0fbfce37-9278-442f-bc20-1aefea5b67ea"}
{"level":"info","time":"2022-06-06T15:35:22.993320272Z","caller":"utils/utils.go:215","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"0fbfce37-9278-442f-bc20-1aefea5b67ea"}
{"level":"error","time":"2022-06-06T15:35:22.993534133Z","caller":"vanilla/controller.go:951","msg":"volume: 92ce5576-a638-44df-a072-0beb575b1ea5 with existing snapshots [size_bytes:1073741824 snapshot_id:\"92ce5576-a638-44df-a072-0beb575b1ea5+f2dacac2-fba3-49f1-a907-7aebe028197e\" source_volume_id:\"92ce5576-a638-44df-a072-0beb575b1ea5\" creation_time:<seconds:1654529722 nanos:978885279 > ready_to_use:true ] cannot be deleted, please delete snapshots before deleting the volume","TraceId":"0fbfce37-9278-442f-bc20-1aefea5b67ea","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.(*controller).DeleteVolume.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:951\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.(*controller).DeleteVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:973\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.TestDeleteVolumeWithSnapshots\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:896\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
    controller_test.go:903: received error as expected when attempting to delete volume with snapshot, error: rpc error: code = FailedPrecondition desc = volume: 92ce5576-a638-44df-a072-0beb575b1ea5 with existing snapshots [size_bytes:1073741824 snapshot_id:"92ce5576-a638-44df-a072-0beb575b1ea5+f2dacac2-fba3-49f1-a907-7aebe028197e" source_volume_id:"92ce5576-a638-44df-a072-0beb575b1ea5" creation_time:<seconds:1654529722 nanos:978885279 > ready_to_use:true ] cannot be deleted, please delete snapshots before deleting the volume
--- PASS: TestDeleteVolumeWithSnapshots (0.05s)
=== RUN   TestCreateBlockVolumeSnapshotWithIdempotency
{"level":"info","time":"2022-06-06T15:35:22.994594427Z","caller":"vanilla/controller.go:828","msg":"CreateVolume: called with args {Name:test-pvc-76a266cc-8136-43c4-a12d-45907855c76d CapacityRange:required_bytes:1073741824  VolumeCapabilities:[access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"13584b1b-38a2-4d84-894f-20b3ad9f2b18"}
{"level":"info","time":"2022-06-06T15:35:23.01809254Z","caller":"volume/manager.go:410","msg":"CreateVolume: VolumeName: \"test-pvc-76a266cc-8136-43c4-a12d-45907855c76d\", opId: \"\"","TraceId":"13584b1b-38a2-4d84-894f-20b3ad9f2b18"}
{"level":"info","time":"2022-06-06T15:35:23.018972582Z","caller":"volume/util.go:322","msg":"Volume created successfully. VolumeName: \"test-pvc-76a266cc-8136-43c4-a12d-45907855c76d\", volumeID: \"cdfa8b97-d582-4bb1-893e-d650a20efec4\"","TraceId":"13584b1b-38a2-4d84-894f-20b3ad9f2b18"}
{"level":"info","time":"2022-06-06T15:35:23.019036558Z","caller":"vanilla/controller.go:863","msg":"Volume created successfully. Volume Handle: \"cdfa8b97-d582-4bb1-893e-d650a20efec4\", PV Name: \"test-pvc-76a266cc-8136-43c4-a12d-45907855c76d\"","TraceId":"13584b1b-38a2-4d84-894f-20b3ad9f2b18"}
... skipping 134 lines ...
{"level":"info","time":"2022-06-06T15:35:23.257312488Z","caller":"utils/utils.go:118","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"9b3ef9ef-35fc-4b38-963c-441e5f6d9748"}
{"level":"info","time":"2022-06-06T15:35:23.263066999Z","caller":"utils/utils.go:150","msg":"setting max iteration to 0 for total records count: 0","TraceId":"9b3ef9ef-35fc-4b38-963c-441e5f6d9748"}
{"level":"info","time":"2022-06-06T15:35:23.263270867Z","caller":"utils/utils.go:170","msg":"0 more snapshots to be queried","TraceId":"9b3ef9ef-35fc-4b38-963c-441e5f6d9748"}
{"level":"info","time":"2022-06-06T15:35:23.263344923Z","caller":"utils/utils.go:173","msg":"QuerySnapshots retrieved all records (0) for the SnapshotQuerySpec: {DynamicData:{} VolumeId:{DynamicData:{} Id:78c32bab-4e37-4fee-b105-c7d54101e193} SnapshotId:<nil>} in 1 iterations","TraceId":"9b3ef9ef-35fc-4b38-963c-441e5f6d9748"}
{"level":"info","time":"2022-06-06T15:35:23.263425011Z","caller":"utils/utils.go:208","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:78c32bab-4e37-4fee-b105-c7d54101e193}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> healthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"9b3ef9ef-35fc-4b38-963c-441e5f6d9748"}
{"level":"info","time":"2022-06-06T15:35:23.269339244Z","caller":"utils/utils.go:215","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"9b3ef9ef-35fc-4b38-963c-441e5f6d9748"}
{"level":"error","time":"2022-06-06T15:35:23.269411115Z","caller":"vanilla/controller.go:1701","msg":"the number of snapshots on the source volume 78c32bab-4e37-4fee-b105-c7d54101e193 reaches the configured maximum (3)","TraceId":"9b3ef9ef-35fc-4b38-963c-441e5f6d9748","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.(*controller).CreateSnapshot.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:1701\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.(*controller).CreateSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:1735\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.TestCreateBlockVolumeSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:1210\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
    controller_test.go:1217: received error as expected when attempting to create snapshot on volume when existing number of snapshots reaches the configured maximum, error: rpc error: code = FailedPrecondition desc = the number of snapshots on the source volume 78c32bab-4e37-4fee-b105-c7d54101e193 reaches the configured maximum (3).
{"level":"info","time":"2022-06-06T15:35:23.269642031Z","caller":"vanilla/controller.go:1751","msg":"DeleteSnapshot: called with args {SnapshotId:78c32bab-4e37-4fee-b105-c7d54101e193+af3f4b64-aab5-4dcf-9b25-450f2a59458c Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"582935e4-e015-42ed-885e-78b19ddef853"}
{"level":"info","time":"2022-06-06T15:35:23.276697537Z","caller":"volume/util.go:415","msg":"Calling CnsClient.DeleteSnapshots: VolumeID [\"78c32bab-4e37-4fee-b105-c7d54101e193\"] SnapshotID [\"af3f4b64-aab5-4dcf-9b25-450f2a59458c\"] cnsSnapshotDeleteSpecList [types.CnsSnapshotDeleteSpec{DynamicData:types.DynamicData{}, VolumeId:types.CnsVolumeId{DynamicData:types.DynamicData{}, Id:\"78c32bab-4e37-4fee-b105-c7d54101e193\"}, SnapshotId:types.CnsSnapshotId{DynamicData:types.DynamicData{}, Id:\"af3f4b64-aab5-4dcf-9b25-450f2a59458c\"}}]","TraceId":"582935e4-e015-42ed-885e-78b19ddef853"}
{"level":"info","time":"2022-06-06T15:35:23.279682524Z","caller":"volume/manager.go:2175","msg":"DeleteSnapshot: VolumeID: \"78c32bab-4e37-4fee-b105-c7d54101e193\", SnapshotID: \"af3f4b64-aab5-4dcf-9b25-450f2a59458c\", opId: \"\"","TraceId":"582935e4-e015-42ed-885e-78b19ddef853"}
{"level":"info","time":"2022-06-06T15:35:23.279819416Z","caller":"volume/manager.go:2231","msg":"DeleteSnapshot: Snapshot \"af3f4b64-aab5-4dcf-9b25-450f2a59458c\" on volume \"78c32bab-4e37-4fee-b105-c7d54101e193\" is deleted successfully. opId: \"\"","TraceId":"582935e4-e015-42ed-885e-78b19ddef853"}
{"level":"info","time":"2022-06-06T15:35:23.279897636Z","caller":"vanilla/controller.go:1779","msg":"DeleteSnapshot: successfully deleted snapshot \"78c32bab-4e37-4fee-b105-c7d54101e193+af3f4b64-aab5-4dcf-9b25-450f2a59458c\"","TraceId":"582935e4-e015-42ed-885e-78b19ddef853"}
{"level":"info","time":"2022-06-06T15:35:23.279942494Z","caller":"vanilla/controller.go:1790","msg":"Snapshot \"78c32bab-4e37-4fee-b105-c7d54101e193+af3f4b64-aab5-4dcf-9b25-450f2a59458c\" deleted successfully.","TraceId":"582935e4-e015-42ed-885e-78b19ddef853"}
... skipping 54 lines ...
{"level":"info","time":"2022-06-06T15:35:23.47440003Z","caller":"volume/manager.go:410","msg":"CreateVolume: VolumeName: \"test-pvc-78089314-4ae8-4047-a060-f50fa5d10d58\", opId: \"\"","TraceId":"883934e3-6c91-4876-8fcb-3d7bc234956f"}
{"level":"info","time":"2022-06-06T15:35:23.47569333Z","caller":"volume/util.go:322","msg":"Volume created successfully. VolumeName: \"test-pvc-78089314-4ae8-4047-a060-f50fa5d10d58\", volumeID: \"351e9cf9-b29c-4a6e-b30f-0bfd4204c017\"","TraceId":"883934e3-6c91-4876-8fcb-3d7bc234956f"}
{"level":"info","time":"2022-06-06T15:35:23.475909042Z","caller":"vanilla/controller.go:863","msg":"Volume created successfully. Volume Handle: \"351e9cf9-b29c-4a6e-b30f-0bfd4204c017\", PV Name: \"test-pvc-78089314-4ae8-4047-a060-f50fa5d10d58\"","TraceId":"883934e3-6c91-4876-8fcb-3d7bc234956f"}
{"level":"info","time":"2022-06-06T15:35:23.477597509Z","caller":"vanilla/controller.go:828","msg":"CreateVolume: called with args {Name:test-pvc-37e47db0-87e9-4ba5-9705-28e6c8a604ed CapacityRange:required_bytes:2147483648  VolumeCapabilities:[access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[] Secrets:map[] VolumeContentSource:snapshot:<snapshot_id:\"ccd47c80-b7d4-4fdb-afe3-e6bb8893f706+28b38759-781f-4766-84d2-8866bd1f55f3\" >  AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"a7f696b0-d005-4389-b810-6e06947bc146"}
{"level":"info","time":"2022-06-06T15:35:23.477919902Z","caller":"utils/utils.go:208","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:ccd47c80-b7d4-4fdb-afe3-e6bb8893f706}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> healthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"a7f696b0-d005-4389-b810-6e06947bc146"}
{"level":"info","time":"2022-06-06T15:35:23.492698655Z","caller":"utils/utils.go:215","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"a7f696b0-d005-4389-b810-6e06947bc146"}
{"level":"error","time":"2022-06-06T15:35:23.49287598Z","caller":"vanilla/controller.go:435","msg":"size mismatches, requested volume size 2147483648 and source snapshot size 1073741824","TraceId":"a7f696b0-d005-4389-b810-6e06947bc146","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.(*controller).createBlockVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:435\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.(*controller).CreateVolume.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:855\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.(*controller).CreateVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:857\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.TestCreateVolumeFromSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:1418\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
    controller_test.go:1425: received error as expected when attempting to create volume from snapshot, error: rpc error: code = InvalidArgument desc = size mismatches, requested volume size 2147483648 and source snapshot size 1073741824
{"level":"info","time":"2022-06-06T15:35:23.493463318Z","caller":"vanilla/controller.go:881","msg":"DeleteVolume: called with args: {VolumeId:351e9cf9-b29c-4a6e-b30f-0bfd4204c017 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"f6846edc-246f-4ca9-937f-fe0c80678363"}
{"level":"info","time":"2022-06-06T15:35:23.500379846Z","caller":"common/vsphereutil.go:1095","msg":"volume: 351e9cf9-b29c-4a6e-b30f-0bfd4204c017 is of type: BLOCK","TraceId":"f6846edc-246f-4ca9-937f-fe0c80678363"}
{"level":"info","time":"2022-06-06T15:35:23.500554586Z","caller":"utils/utils.go:93","msg":"Invoking QuerySnapshots with spec: {DynamicData:{} VolumeId:{DynamicData:{} Id:351e9cf9-b29c-4a6e-b30f-0bfd4204c017} SnapshotId:<nil>}","TraceId":"f6846edc-246f-4ca9-937f-fe0c80678363"}
{"level":"info","time":"2022-06-06T15:35:23.500608692Z","caller":"utils/utils.go:118","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"f6846edc-246f-4ca9-937f-fe0c80678363"}
{"level":"info","time":"2022-06-06T15:35:23.513409675Z","caller":"utils/utils.go:131","msg":"QuerySnapshots retrieved no results for the spec: {DynamicData:{} VolumeId:{DynamicData:{} Id:351e9cf9-b29c-4a6e-b30f-0bfd4204c017} SnapshotId:<nil>}","TraceId":"f6846edc-246f-4ca9-937f-fe0c80678363"}
{"level":"info","time":"2022-06-06T15:35:23.513550917Z","caller":"utils/utils.go:150","msg":"setting max iteration to 0 for total records count: 0","TraceId":"f6846edc-246f-4ca9-937f-fe0c80678363"}
... skipping 473 lines ...
{"level":"info","time":"2022-06-06T15:35:25.005813778Z","caller":"utils/utils.go:118","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"7de7fb2b-ad19-403f-a7b4-cebe35259297"}
{"level":"info","time":"2022-06-06T15:35:25.044309272Z","caller":"utils/utils.go:150","msg":"setting max iteration to 0 for total records count: 0","TraceId":"7de7fb2b-ad19-403f-a7b4-cebe35259297"}
{"level":"info","time":"2022-06-06T15:35:25.04462506Z","caller":"utils/utils.go:170","msg":"0 more snapshots to be queried","TraceId":"7de7fb2b-ad19-403f-a7b4-cebe35259297"}
{"level":"info","time":"2022-06-06T15:35:25.04478966Z","caller":"utils/utils.go:173","msg":"QuerySnapshots retrieved all records (0) for the SnapshotQuerySpec: {DynamicData:{} VolumeId:{DynamicData:{} Id:3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db} SnapshotId:<nil>} in 1 iterations","TraceId":"7de7fb2b-ad19-403f-a7b4-cebe35259297"}
{"level":"info","time":"2022-06-06T15:35:25.044989219Z","caller":"utils/utils.go:208","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> healthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"7de7fb2b-ad19-403f-a7b4-cebe35259297"}
{"level":"info","time":"2022-06-06T15:35:25.050710685Z","caller":"utils/utils.go:215","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"7de7fb2b-ad19-403f-a7b4-cebe35259297"}
{"level":"error","time":"2022-06-06T15:35:25.050879035Z","caller":"vanilla/controller.go:1297","msg":"volume: 3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db with existing snapshots [size_bytes:1073741824 snapshot_id:\"3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db+dd876420-2e67-4d83-9457-78fa0992eaf1\" source_volume_id:\"3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db\" creation_time:<seconds:1654529725 nanos:542640 > ready_to_use:true ] cannot be expanded. Please delete snapshots before expanding the volume","TraceId":"7de7fb2b-ad19-403f-a7b4-cebe35259297","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.(*controller).ControllerExpandVolume.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:1297\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.(*controller).ControllerExpandVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:1329\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla.TestExpandVolumeWithSnapshots\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:2002\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
    controller_test.go:2009: received error as expected when attempting to expand volume with snapshot, error: rpc error: code = FailedPrecondition desc = volume: 3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db with existing snapshots [size_bytes:1073741824 snapshot_id:"3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db+dd876420-2e67-4d83-9457-78fa0992eaf1" source_volume_id:"3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db" creation_time:<seconds:1654529725 nanos:542640 > ready_to_use:true ] cannot be expanded. Please delete snapshots before expanding the volume
{"level":"info","time":"2022-06-06T15:35:25.051754931Z","caller":"vanilla/controller.go:1751","msg":"DeleteSnapshot: called with args {SnapshotId:3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db+dd876420-2e67-4d83-9457-78fa0992eaf1 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"1fac961c-d27c-458e-a2a4-8143c767f4fe"}
{"level":"info","time":"2022-06-06T15:35:25.061541107Z","caller":"volume/util.go:415","msg":"Calling CnsClient.DeleteSnapshots: VolumeID [\"3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db\"] SnapshotID [\"dd876420-2e67-4d83-9457-78fa0992eaf1\"] cnsSnapshotDeleteSpecList [types.CnsSnapshotDeleteSpec{DynamicData:types.DynamicData{}, VolumeId:types.CnsVolumeId{DynamicData:types.DynamicData{}, Id:\"3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db\"}, SnapshotId:types.CnsSnapshotId{DynamicData:types.DynamicData{}, Id:\"dd876420-2e67-4d83-9457-78fa0992eaf1\"}}]","TraceId":"1fac961c-d27c-458e-a2a4-8143c767f4fe"}
{"level":"info","time":"2022-06-06T15:35:25.074663727Z","caller":"volume/manager.go:2175","msg":"DeleteSnapshot: VolumeID: \"3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db\", SnapshotID: \"dd876420-2e67-4d83-9457-78fa0992eaf1\", opId: \"\"","TraceId":"1fac961c-d27c-458e-a2a4-8143c767f4fe"}
{"level":"info","time":"2022-06-06T15:35:25.074977981Z","caller":"volume/manager.go:2231","msg":"DeleteSnapshot: Snapshot \"dd876420-2e67-4d83-9457-78fa0992eaf1\" on volume \"3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db\" is deleted successfully. opId: \"\"","TraceId":"1fac961c-d27c-458e-a2a4-8143c767f4fe"}
{"level":"info","time":"2022-06-06T15:35:25.075230201Z","caller":"vanilla/controller.go:1779","msg":"DeleteSnapshot: successfully deleted snapshot \"3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db+dd876420-2e67-4d83-9457-78fa0992eaf1\"","TraceId":"1fac961c-d27c-458e-a2a4-8143c767f4fe"}
{"level":"info","time":"2022-06-06T15:35:25.075414341Z","caller":"vanilla/controller.go:1790","msg":"Snapshot \"3cfe4c5f-9a66-40dd-a2f9-7ce1f962b0db+dd876420-2e67-4d83-9457-78fa0992eaf1\" deleted successfully.","TraceId":"1fac961c-d27c-458e-a2a4-8143c767f4fe"}
... skipping 15 lines ...
=== RUN   TestDeleteBlockVolumeSnapshotWithManagedObjectNotFound
{"level":"info","time":"2022-06-06T15:35:25.140965228Z","caller":"vanilla/controller.go:828","msg":"CreateVolume: called with args {Name:test-pvc-a6faa50c-0137-4835-8ff0-99b3713a9a9a CapacityRange:required_bytes:1073741824  VolumeCapabilities:[access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"23146883-b9a1-4088-ad0d-db14f6686183"}
{"level":"info","time":"2022-06-06T15:35:25.182836218Z","caller":"volume/manager.go:410","msg":"CreateVolume: VolumeName: \"test-pvc-a6faa50c-0137-4835-8ff0-99b3713a9a9a\", opId: \"\"","TraceId":"23146883-b9a1-4088-ad0d-db14f6686183"}
{"level":"info","time":"2022-06-06T15:35:25.184350083Z","caller":"volume/util.go:322","msg":"Volume created successfully. VolumeName: \"test-pvc-a6faa50c-0137-4835-8ff0-99b3713a9a9a\", volumeID: \"0e4d06a8-2dc0-41b3-898f-415cfcb3544d\"","TraceId":"23146883-b9a1-4088-ad0d-db14f6686183"}
{"level":"info","time":"2022-06-06T15:35:25.184492333Z","caller":"vanilla/controller.go:863","msg":"Volume created successfully. Volume Handle: \"0e4d06a8-2dc0-41b3-898f-415cfcb3544d\", PV Name: \"test-pvc-a6faa50c-0137-4835-8ff0-99b3713a9a9a\"","TraceId":"23146883-b9a1-4088-ad0d-db14f6686183"}
{"level":"info","time":"2022-06-06T15:35:25.187937853Z","caller":"vanilla/controller.go:1751","msg":"DeleteSnapshot: called with args {SnapshotId:0e4d06a8-2dc0-41b3-898f-415cfcb3544d+540ad0c9-c48a-43e7-968d-5c0734e7d054 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"31154589-aa3a-4d2f-b007-faa1e699262a"}
{"level":"info","time":"2022-06-06T15:35:25.200609405Z","caller":"volume/manager.go:2149","msg":"Snapshot \"540ad0c9-c48a-43e7-968d-5c0734e7d054\" on volume \"0e4d06a8-2dc0-41b3-898f-415cfcb3544d\" might have already been deleted with the error ServerFaultCode: ManagedObjectNotFound. Calling CNS QuerySnapshots API to confirm it","TraceId":"31154589-aa3a-4d2f-b007-faa1e699262a"}
{"level":"info","time":"2022-06-06T15:35:25.216946201Z","caller":"volume/util.go:495","msg":"fault in the result of query CNS for snapshot 540ad0c9-c48a-43e7-968d-5c0734e7d054 on volume 0e4d06a8-2dc0-41b3-898f-415cfcb3544d: (types.CnsSnapshotNotFoundFault) {\n CnsFault: (types.CnsFault) {\n  BaseMethodFault: (types.BaseMethodFault) <nil>,\n  Reason: (string) \"\"\n },\n VolumeId: (types.CnsVolumeId) {\n  DynamicData: (types.DynamicData) {\n  },\n  Id: (string) (len=36) \"0e4d06a8-2dc0-41b3-898f-415cfcb3544d\"\n },\n SnapshotId: (types.CnsSnapshotId) {\n  DynamicData: (types.DynamicData) {\n  },\n  Id: (string) (len=36) \"540ad0c9-c48a-43e7-968d-5c0734e7d054\"\n }\n}\n","TraceId":"31154589-aa3a-4d2f-b007-faa1e699262a"}
{"level":"info","time":"2022-06-06T15:35:25.217254724Z","caller":"volume/manager.go:2160","msg":"DeleteSnapshot: Snapshot \"540ad0c9-c48a-43e7-968d-5c0734e7d054\" on volume \"0e4d06a8-2dc0-41b3-898f-415cfcb3544d\" is confirmed to be deleted successfully","TraceId":"31154589-aa3a-4d2f-b007-faa1e699262a"}
{"level":"info","time":"2022-06-06T15:35:25.217499998Z","caller":"vanilla/controller.go:1779","msg":"DeleteSnapshot: successfully deleted snapshot \"0e4d06a8-2dc0-41b3-898f-415cfcb3544d+540ad0c9-c48a-43e7-968d-5c0734e7d054\"","TraceId":"31154589-aa3a-4d2f-b007-faa1e699262a"}
{"level":"info","time":"2022-06-06T15:35:25.217704193Z","caller":"vanilla/controller.go:1790","msg":"Snapshot \"0e4d06a8-2dc0-41b3-898f-415cfcb3544d+540ad0c9-c48a-43e7-968d-5c0734e7d054\" deleted successfully.","TraceId":"31154589-aa3a-4d2f-b007-faa1e699262a"}
{"level":"info","time":"2022-06-06T15:35:25.218264466Z","caller":"vanilla/controller.go:881","msg":"DeleteVolume: called with args: {VolumeId:0e4d06a8-2dc0-41b3-898f-415cfcb3544d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"0ede2048-6d9a-41aa-b1ba-8e97bf79fbad"}
{"level":"info","time":"2022-06-06T15:35:25.221889578Z","caller":"common/vsphereutil.go:1095","msg":"volume: 0e4d06a8-2dc0-41b3-898f-415cfcb3544d is of type: BLOCK","TraceId":"0ede2048-6d9a-41aa-b1ba-8e97bf79fbad"}
... skipping 69 lines ...
{"level":"info","time":"2022-06-06T15:35:25.547420694Z","caller":"volume/manager.go:1039","msg":"DeleteVolume: Volume deleted successfully. volumeID: \"831abab9-370e-45f7-ba69-ef7be0ac38a1\", opId: \"\"","TraceId":"9ad464ce-cb1f-466c-9f53-016e882450cd"}
{"level":"info","time":"2022-06-06T15:35:25.547616853Z","caller":"vanilla/controller.go:979","msg":"Volume \"831abab9-370e-45f7-ba69-ef7be0ac38a1\" deleted successfully.","TraceId":"9ad464ce-cb1f-466c-9f53-016e882450cd"}
--- PASS: TestCreateSnapshotWithManagedObjectNotFound (0.28s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla	3.777s
=== RUN   TestWCPCreateVolumeWithStoragePolicy
{"level":"error","time":"2022-06-06T15:35:28.144992731Z","caller":"config/config.go:311","msg":"no Virtual Center hosts defined","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.validateConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:311\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.FromEnv\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:295\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcp.configFromEnvOrSim\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:131\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcp.getControllerTest.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:141\nsync.(*Once).doSlow\n\t/usr/local/go/src/sync/once.go:68\nsync.(*Once).Do\n\t/usr/local/go/src/sync/once.go:59\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcp.getControllerTest\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:138\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcp.TestWCPCreateVolumeWithStoragePolicy\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:271\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
{"level":"info","time":"2022-06-06T15:35:28.614830861Z","caller":"vsphere/utils.go:189","msg":"Defaulting timeout for vCenter Client to 5 minutes"}
{"level":"info","time":"2022-06-06T15:35:28.615180469Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
{"level":"info","time":"2022-06-06T15:35:28.615842798Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
{"level":"info","time":"2022-06-06T15:35:28.626157547Z","caller":"vsphere/virtualcentermanager.go:122","msg":"Successfully registered VC \"127.0.0.1\""}
{"level":"info","time":"2022-06-06T15:35:28.666907878Z","caller":"vsphere/virtualcenter.go:183","msg":"New session ID for 'user' = 3f64fa25-4cab-4c5a-ba55-0c0cd7cd4032"}
{"level":"info","time":"2022-06-06T15:35:28.668468535Z","caller":"volume/manager.go:175","msg":"Initializing new defaultManager..."}
... skipping 5 lines ...
{"level":"info","time":"2022-06-06T15:35:28.768694789Z","caller":"volume/manager.go:1014","msg":"DeleteVolume: volumeID: \"d4853b37-93e9-4a41-a9bd-5fc45be7ab9a\", opId: \"\"","TraceId":"f283ffa0-cd95-4838-bd9c-d0f423088ea3"}
{"level":"info","time":"2022-06-06T15:35:28.768768568Z","caller":"volume/manager.go:1039","msg":"DeleteVolume: Volume deleted successfully. volumeID: \"d4853b37-93e9-4a41-a9bd-5fc45be7ab9a\", opId: \"\"","TraceId":"f283ffa0-cd95-4838-bd9c-d0f423088ea3"}
{"level":"info","time":"2022-06-06T15:35:28.76889987Z","caller":"wcp/controller.go:839","msg":"Volume \"d4853b37-93e9-4a41-a9bd-5fc45be7ab9a\" deleted successfully.","TraceId":"f283ffa0-cd95-4838-bd9c-d0f423088ea3"}
--- PASS: TestWCPCreateVolumeWithStoragePolicy (0.63s)
=== RUN   TestWCPCreateVolumeWithZonalLabelPresentButNoStorageTopoType
{"level":"info","time":"2022-06-06T15:35:28.783897754Z","caller":"wcp/controller.go:746","msg":"CreateVolume: called with args {Name:test-pvc-77e98def-6ee0-4b9c-a0e9-cc6d699d6df5 CapacityRange:required_bytes:1073741824  VolumeCapabilities:[access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[storagepolicyid:aa6d5a82-1c88-45da-85d3-3d74b91a5bad] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:preferred:<segments:<key:\"topology.kubernetes.io/zone\" value:\"zone1\" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"4975a487-5e20-4276-9e2e-db80e7b64157"}
{"level":"error","time":"2022-06-06T15:35:28.786196472Z","caller":"wcp/controller.go:432","msg":"StorageTopologyType is unset while topology label is present","TraceId":"4975a487-5e20-4276-9e2e-db80e7b64157","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcp.(*controller).createBlockVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:432\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcp.(*controller).CreateVolume.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:782\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcp.(*controller).CreateVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:784\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcp.TestWCPCreateVolumeWithZonalLabelPresentButNoStorageTopoType\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:436\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
    controller_test.go:438: expected error is thrown: rpc error: code = InvalidArgument desc = StorageTopologyType is unset while topology label is present
--- PASS: TestWCPCreateVolumeWithZonalLabelPresentButNoStorageTopoType (0.02s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcp	0.808s
=== RUN   TestGuestClusterControllerFlow
{"level":"error","time":"2022-06-06T15:35:22.784968683Z","caller":"config/config.go:582","msg":"no Supervisor Cluster endpoint defined in Guest Cluster config","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.validateGCConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:582\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.FromEnvToGC\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:522\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcpguest.configFromEnvOrSim\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcpguest/controller_test.go:72\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcpguest.getControllerTest.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcpguest/controller_test.go:88\nsync.(*Once).doSlow\n\t/usr/local/go/src/sync/once.go:68\nsync.(*Once).Do\n\t/usr/local/go/src/sync/once.go:59\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcpguest.getControllerTest\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcpguest/controller_test.go:85\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcpguest.TestGuestClusterControllerFlow\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcpguest/controller_test.go:121\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
{"level":"info","time":"2022-06-06T15:35:22.789917913Z","caller":"wcpguest/controller.go:233","msg":"CreateVolume: called with args {Name:pvc-12345 CapacityRange:required_bytes:1073741824  VolumeCapabilities:[access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[svstorageclass:test-storageclass] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"6cb05910-78d2-4c90-9c28-e87dcedbb4c2"}
{"level":"info","time":"2022-06-06T15:35:22.794386232Z","caller":"wcpguest/controller_helper.go:257","msg":"Waiting up to 240 seconds for PersistentVolumeClaim -12345 in namespace test-namespace to have phase Bound","TraceId":"6cb05910-78d2-4c90-9c28-e87dcedbb4c2"}
{"level":"info","time":"2022-06-06T15:35:27.796083155Z","caller":"wcpguest/controller_helper.go:273","msg":"PersistentVolumeClaim -12345 in namespace test-namespace is in state Bound","TraceId":"6cb05910-78d2-4c90-9c28-e87dcedbb4c2"}
{"level":"info","time":"2022-06-06T15:35:27.796271356Z","caller":"wcpguest/controller.go:379","msg":"Volume created successfully. Volume Handle: \"-12345\", PV Name: \"pvc-12345\"","TraceId":"6cb05910-78d2-4c90-9c28-e87dcedbb4c2"}
{"level":"info","time":"2022-06-06T15:35:27.797298779Z","caller":"wcpguest/controller.go:398","msg":"DeleteVolume: called with args: {VolumeId:-12345 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"92cf9001-684c-4886-a3b0-161e45d305c9"}
{"level":"info","time":"2022-06-06T15:35:27.797418053Z","caller":"wcpguest/controller.go:443","msg":"DeleteVolume: Volume deleted successfully. VolumeID: \"-12345\"","TraceId":"92cf9001-684c-4886-a3b0-161e45d305c9"}
... skipping 20 lines ...
=== RUN   TestGenerateVolumeAccessibleTopologyFromPVCAnnotation
    controller_test.go:347: Calling generateVolumeAccessibleTopologyFromPVCAnnotation with csi.vsphere.volume-accessible-topology annotation value "[{\"topology.kubernetes.io/zone\":\"zone1\"},{\"topology.kubernetes.io/zone\":\"zone2\"}]"
    controller_test.go:365: accessibleTopologies [map[topology.kubernetes.io/zone:zone1] map[topology.kubernetes.io/zone:zone2]] match with expectedAccessibleTopologies: [map[topology.kubernetes.io/zone:zone1] map[topology.kubernetes.io/zone:zone2]]
--- PASS: TestGenerateVolumeAccessibleTopologyFromPVCAnnotation (0.00s)
=== RUN   TestGenerateVolumeAccessibleTopologyFromInvalidPVCAnnotation
    controller_test.go:382: Calling generateVolumeAccessibleTopologyFromPVCAnnotation with csi.vsphere.volume-accessible-topology annotation value "[{\"topology.kubernetes.io/zone\":\"zone1\",{\"topology.kubernetes.io/zone\":\"zone2\"}]"
    controller_test.go:391: expected error: failed to parse annotation: "csi.vsphere.volume-accessible-topology" value [{"topology.kubernetes.io/zone":"zone1",{"topology.kubernetes.io/zone":"zone2"}] from the claim: "name", namespace: "ns". err: invalid character '{' looking for beginning of object key string
--- PASS: TestGenerateVolumeAccessibleTopologyFromInvalidPVCAnnotation (0.00s)
=== RUN   TestGenerateGuestClusterRequestedTopologyJSON
    controller_test.go:404: Calling generateGuestClusterRequestedTopologyJSON with topologies: [segments:<key:"topology.kubernetes.io/zone" value:"zone1" >  segments:<key:"topology.kubernetes.io/zone" value:"zone2" > ]
    controller_test.go:416: volumeAccessibleTopologyJSON [{"topology.kubernetes.io/zone":"zone1"},{"topology.kubernetes.io/zone":"zone2"}] match with expectedVolumeAccessibleTopologyJSON: [{"topology.kubernetes.io/zone":"zone1"},{"topology.kubernetes.io/zone":"zone2"}]
--- PASS: TestGenerateGuestClusterRequestedTopologyJSON (0.00s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcpguest	18.224s
=== RUN   TestSyncerWorkflows
    syncer_test.go:161: TestSyncerWorkflows: start
{"level":"error","time":"2022-06-06T15:35:36.776879002Z","caller":"config/config.go:311","msg":"no Virtual Center hosts defined","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.validateConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:311\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config.FromEnv\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:295\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer.configFromEnvOrSim\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/syncer_test.go:150\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer.TestSyncerWorkflows\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/syncer_test.go:163\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
{"level":"info","time":"2022-06-06T15:35:37.168757116Z","caller":"vsphere/utils.go:189","msg":"Defaulting timeout for vCenter Client to 5 minutes"}
{"level":"info","time":"2022-06-06T15:35:37.168886022Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
{"level":"info","time":"2022-06-06T15:35:37.168925331Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
{"level":"info","time":"2022-06-06T15:35:37.169033705Z","caller":"vsphere/virtualcentermanager.go:122","msg":"Successfully registered VC \"127.0.0.1\""}
{"level":"info","time":"2022-06-06T15:35:37.179750608Z","caller":"vsphere/virtualcenter.go:183","msg":"New session ID for 'user' = 2d3ef72e-235b-4f11-8a72-deae166f2b64"}
{"level":"info","time":"2022-06-06T15:35:37.183365512Z","caller":"volume/manager.go:175","msg":"Initializing new defaultManager..."}
... skipping 158 lines ...
    --- PASS: TestValidatePVCAnnotationForVolumeHealth/TestUpdatePVCAnnVolumeHealthToInaccessibleByCSIServiceAccount (0.00s)
    --- PASS: TestValidatePVCAnnotationForVolumeHealth/TestUpdatePVCAnnVolumeHealthToAccessibleByCSIServiceAccount (0.02s)
    --- PASS: TestValidatePVCAnnotationForVolumeHealth/TestUpdatePVCRemoveAnnVolumeHealthByDevopsUser (0.00s)
    --- PASS: TestValidatePVCAnnotationForVolumeHealth/TestUpdatePVCRemoveAnnVolumeHealthByCSIServiceAccount (0.00s)
=== RUN   TestValidateStorageClassForAllowVolumeExpansion
{"level":"info","time":"2022-06-06T15:35:22.526367343Z","caller":"admissionhandler/validatestorageclass.go:77","msg":"Validating StorageClass: \"sc\""}
{"level":"error","time":"2022-06-06T15:35:22.526420934Z","caller":"admissionhandler/validatestorageclass.go:101","msg":"validation of StorageClass: \"sc\" Failed","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/admissionhandler.validateStorageClass\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/admissionhandler/validatestorageclass.go:101\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/admissionhandler.TestValidateStorageClassForAllowVolumeExpansion\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/admissionhandler/validatestorageclass_test.go:53\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
    validatestorageclass_test.go:59: TestValidateStorageClassForAllowVolumeExpansion Passed
--- PASS: TestValidateStorageClassForAllowVolumeExpansion (0.00s)
=== RUN   TestValidateStorageClassForMigrationParameter
{"level":"info","time":"2022-06-06T15:35:22.52689946Z","caller":"admissionhandler/validatestorageclass.go:77","msg":"Validating StorageClass: \"sc\""}
{"level":"error","time":"2022-06-06T15:35:22.526952844Z","caller":"admissionhandler/validatestorageclass.go:101","msg":"validation of StorageClass: \"sc\" Failed","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/admissionhandler.validateStorageClass\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/admissionhandler/validatestorageclass.go:101\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/admissionhandler.TestValidateStorageClassForMigrationParameter\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/admissionhandler/validatestorageclass_test.go:77\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
{"level":"info","time":"2022-06-06T15:35:22.527271839Z","caller":"admissionhandler/validatestorageclass.go:77","msg":"Validating StorageClass: \"sc\""}
{"level":"error","time":"2022-06-06T15:35:22.527326468Z","caller":"admissionhandler/validatestorageclass.go:101","msg":"validation of StorageClass: \"sc\" Failed","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/admissionhandler.validateStorageClass\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/admissionhandler/validatestorageclass.go:101\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/admissionhandler.TestValidateStorageClassForMigrationParameter\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/admissionhandler/validatestorageclass_test.go:91\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
    validatestorageclass_test.go:98: TestValidateStorageClassForMigrationParameter Passed
--- PASS: TestValidateStorageClassForMigrationParameter (0.00s)
=== RUN   TestValidateStorageClassForValidStorageClass
{"level":"info","time":"2022-06-06T15:35:22.52774136Z","caller":"admissionhandler/validatestorageclass.go:77","msg":"Validating StorageClass: \"sc\""}
{"level":"info","time":"2022-06-06T15:35:22.533424635Z","caller":"admissionhandler/validatestorageclass.go:99","msg":"Validation of StorageClass: \"sc\" Passed"}
    validatestorageclass_test.go:120: TestValidateStorageClassForValidStorageClass Passed
... skipping 6 lines ...
{"level":"info","time":"2022-06-06T15:35:34.793111635Z","caller":"csinodetopology/csinodetopology_controller.go:393","msg":"Successfully updated topology labels for worker \"test-csinodetopology-name\" in GUEST_CLUSTER"}
=== RUN   TestCSINodeTopologyControllerForTKGSHA/TestWithVmStatusZoneEmpty
{"level":"info","time":"2022-06-06T15:35:34.805683054Z","caller":"csinodetopology/csinodetopology_controller.go:342","msg":"Start reconciling the CSINodeTopology request test-csinodetopology-name in GUEST_CLUSTER"}
{"level":"info","time":"2022-06-06T15:35:34.806661593Z","caller":"csinodetopology/csinodetopology_controller.go:393","msg":"Successfully updated topology labels for worker \"test-csinodetopology-name\" in GUEST_CLUSTER"}
=== RUN   TestCSINodeTopologyControllerForTKGSHA/TestWithGetVmFailure
{"level":"info","time":"2022-06-06T15:35:34.809231515Z","caller":"csinodetopology/csinodetopology_controller.go:342","msg":"Start reconciling the CSINodeTopology request test-csinodetopology-name in GUEST_CLUSTER"}
{"level":"error","time":"2022-06-06T15:35:34.8113659Z","caller":"csinodetopology/csinodetopology_controller.go:410","msg":"failed to get VirtualMachines for the node: \"test-csinodetopology-name\". Error: virtualmachines.vmoperator.vmware.com \"test-csinodetopology-name\" not found","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/cnsoperator/controller/csinodetopology.getNodeTopologyInfoForGuest\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/cnsoperator/controller/csinodetopology/csinodetopology_controller.go:410\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/cnsoperator/controller/csinodetopology.(*ReconcileCSINodeTopology).reconcileForGuest\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/cnsoperator/controller/csinodetopology/csinodetopology_controller.go:370\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/cnsoperator/controller/csinodetopology.(*ReconcileCSINodeTopology).Reconcile\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/cnsoperator/controller/csinodetopology/csinodetopology_controller.go:225\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/cnsoperator/controller/csinodetopology.TestCSINodeTopologyControllerForTKGSHA.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/cnsoperator/controller/csinodetopology/csinodetopology_controller_test.go:175\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
{"level":"error","time":"2022-06-06T15:35:34.811465242Z","caller":"csinodetopology/csinodetopology_controller.go:374","msg":"failed to fetch topology information for the worker node \"test-csinodetopology-name\". Error: failed to get VirtualMachines for the node: \"test-csinodetopology-name\". Error: virtualmachines.vmoperator.vmware.com \"test-csinodetopology-name\" not found","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/cnsoperator/controller/csinodetopology.(*ReconcileCSINodeTopology).reconcileForGuest\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/cnsoperator/controller/csinodetopology/csinodetopology_controller.go:374\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/cnsoperator/controller/csinodetopology.(*ReconcileCSINodeTopology).Reconcile\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/cnsoperator/controller/csinodetopology/csinodetopology_controller.go:225\nsigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/cnsoperator/controller/csinodetopology.TestCSINodeTopologyControllerForTKGSHA.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/cnsoperator/controller/csinodetopology/csinodetopology_controller_test.go:175\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1439"}
--- PASS: TestCSINodeTopologyControllerForTKGSHA (0.03s)
    --- PASS: TestCSINodeTopologyControllerForTKGSHA/TestWithVmStatusZonePopulated (0.01s)
    --- PASS: TestCSINodeTopologyControllerForTKGSHA/TestWithVmStatusZoneEmpty (0.01s)
    --- PASS: TestCSINodeTopologyControllerForTKGSHA/TestWithGetVmFailure (0.01s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/cnsoperator/controller/csinodetopology	0.171s
make[1]: Leaving directory '/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver'
make push-images
make[1]: Entering directory '/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver'
hack/release.sh -p
building gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af for linux
error: no builder "vsphere-csi-builder-win" found
builder instance not found, safe to proceed
#1 [internal] load build definition from Dockerfile
#1 transferring dockerfile: 3.09kB done
#1 DONE 0.1s

#2 [internal] load .dockerignore
... skipping 136 lines ...
#8 11.51 python3                  x86_64       3.10.0-3.ph4     photon-updates   3.44M 3605256
#8 11.51 ncurses                  x86_64       6.2-6.ph4        photon-updates 363.42k 372138
#8 11.51 expat                    x86_64       2.2.9-9.ph4      photon-updates  31.54k 32296
#8 11.51 pcre                     x86_64       8.44-2.ph4       photon-release 727.69k 745153
#8 11.51 libseccomp               x86_64       2.5.0-2.ph4      photon-release 167.72k 171743
#8 11.51 libmicrohttpd            x86_64       0.9.71-2.ph4     photon-release 148.80k 152368
#8 11.51 libgpg-error             x86_64       1.39-1.ph4       photon-release 223.29k 228654
#8 11.51 libacl                   x86_64       2.2.53-1.ph4     photon-release  39.69k 40642
#8 11.51 kmod                     x86_64       27-1.ph4         photon-release 266.29k 272681
#8 11.51 systemd-rpm-macros       noarch       247.11-2.ph4     photon-updates   5.45k 5581
#8 11.51 systemd-pam              x86_64       247.11-2.ph4     photon-updates 452.89k 463757
#8 11.51 systemd-libs             x86_64       247.11-2.ph4     photon-updates   1.60M 1673900
#8 11.51 elfutils                 x86_64       0.181-4.ph4      photon-updates   3.56M 3728253
... skipping 177 lines ...
#8 32.90 Installing/Updating: libselinux-3.3-1.ph4.x86_64
#8 32.92 Installing/Updating: coreutils-selinux-9.1-1.ph4.x86_64
#8 33.04 Installing/Updating: xz-5.2.5-2.ph4.x86_64
#8 33.06 Installing/Updating: cracklib-2.9.7-2.ph4.x86_64
#8 33.09 using empty dict to provide pw_dict
#8 33.09 Installing/Updating: gc-8.0.4-1.ph4.x86_64
#8 33.13 Installing/Updating: libgpg-error-1.39-1.ph4.x86_64
#8 33.16 Installing/Updating: libgcrypt-1.9.4-1.ph4.x86_64
#8 33.21 Installing/Updating: ncurses-6.2-6.ph4.x86_64
#8 33.22 Installing/Updating: libtirpc-1.2.6-2.ph4.x86_64
#8 33.25 Installing/Updating: libltdl-2.4.6-3.ph4.x86_64
#8 33.27 Installing/Updating: libunistring-0.9.10-1.ph4.x86_64
#8 33.34 Installing/Updating: pkg-config-0.29.2-4.ph4.x86_64
... skipping 194 lines ...
 ---> Running in 4843afb7c9ca
Removing intermediate container 4843afb7c9ca
 ---> baff1d23e8a8
Successfully built baff1d23e8a8
Successfully tagged gcr.io/cloud-provider-vsphere/csi/ci/syncer:012b72af
tagging image gcr.io/cloud-provider-vsphere/csi/ci/syncer:012b72af as latest
error: failed to find instance "vsphere-csi-builder-win": open /root/.docker/buildx/instances/vsphere-csi-builder-win: no such file or directory
vsphere-csi-builder-win
building gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af for windows
#1 [internal] booting buildkit
#1 pulling image moby/buildkit:buildx-stable-1
#1 pulling image moby/buildkit:buildx-stable-1 4.8s done
#1 creating container buildx_buildkit_vsphere-csi-builder-win0
... skipping 188 lines ...
#18 DONE 2.5s
WARNING! Your password will be stored unencrypted in /root/.docker/config.json.
Configure a credential helper to remove this warning. See
https://docs.docker.com/engine/reference/commandline/login/#credentials-store

Login Succeeded
error: failed to find instance "vsphere-csi-builder-win": open /root/.docker/buildx/instances/vsphere-csi-builder-win: no such file or directory
vsphere-csi-builder-win
building gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af for windows
#1 [internal] booting buildkit
#1 pulling image moby/buildkit:buildx-stable-1 0.1s done
#1 creating container buildx_buildkit_vsphere-csi-builder-win0
#1 creating container buildx_buildkit_vsphere-csi-builder-win0 0.8s done
... skipping 233 lines ...

#18 exporting to image
#18 pushing layers 1.3s done
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-1809-amd64:012b72af@sha256:8bff46d1b8a42dfc6efe99ea7daf88267e3a08dd74a9b976c35899df4b34f240
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-1809-amd64:012b72af@sha256:8bff46d1b8a42dfc6efe99ea7daf88267e3a08dd74a9b976c35899df4b34f240 0.3s done
#18 DONE 6.1s
error: failed to find instance "vsphere-csi-builder-win": open /root/.docker/buildx/instances/vsphere-csi-builder-win: no such file or directory
vsphere-csi-builder-win
building gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af for windows
#1 [internal] booting buildkit
#1 pulling image moby/buildkit:buildx-stable-1
#1 pulling image moby/buildkit:buildx-stable-1 0.2s done
#1 creating container buildx_buildkit_vsphere-csi-builder-win0
... skipping 247 lines ...

#18 exporting to image
#18 pushing layers 2.1s done
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-1903-amd64:012b72af@sha256:a2033c55bdd8bfa3385515c74125b63d6c76c6b4f0a63037c556c51dda21bafb
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-1903-amd64:012b72af@sha256:a2033c55bdd8bfa3385515c74125b63d6c76c6b4f0a63037c556c51dda21bafb 0.3s done
#18 DONE 5.7s
error: failed to find instance "vsphere-csi-builder-win": open /root/.docker/buildx/instances/vsphere-csi-builder-win: no such file or directory
vsphere-csi-builder-win
building gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af for windows
#1 [internal] booting buildkit
#1 pulling image moby/buildkit:buildx-stable-1
#1 pulling image moby/buildkit:buildx-stable-1 0.2s done
#1 creating container buildx_buildkit_vsphere-csi-builder-win0
... skipping 199 lines ...

#18 exporting to image
#18 pushing layers 1.2s done
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-1909-amd64:012b72af@sha256:7220894741bb1cd403a5593f70af624cb811e4fd2629aad9ec436dd33d271c1e
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-1909-amd64:012b72af@sha256:7220894741bb1cd403a5593f70af624cb811e4fd2629aad9ec436dd33d271c1e 0.3s done
#18 DONE 4.6s
error: failed to find instance "vsphere-csi-builder-win": open /root/.docker/buildx/instances/vsphere-csi-builder-win: no such file or directory
vsphere-csi-builder-win
building gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af for windows
#1 [internal] booting buildkit
#1 pulling image moby/buildkit:buildx-stable-1 0.1s done
#1 creating container buildx_buildkit_vsphere-csi-builder-win0
#1 creating container buildx_buildkit_vsphere-csi-builder-win0 0.8s done
... skipping 189 lines ...

#18 exporting to image
#18 pushing layers 1.8s done
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-2004-amd64:012b72af@sha256:442c77c40cfcc233d977468663f56377696756f48feb9b5b0cf912d2db85b9d9
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-2004-amd64:012b72af@sha256:442c77c40cfcc233d977468663f56377696756f48feb9b5b0cf912d2db85b9d9 0.5s done
#18 DONE 5.3s
error: failed to find instance "vsphere-csi-builder-win": open /root/.docker/buildx/instances/vsphere-csi-builder-win: no such file or directory
vsphere-csi-builder-win
building gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af for windows
#1 [internal] booting buildkit
#1 pulling image moby/buildkit:buildx-stable-1 0.1s done
#1 creating container buildx_buildkit_vsphere-csi-builder-win0
#1 creating container buildx_buildkit_vsphere-csi-builder-win0 0.8s done
... skipping 224 lines ...

#18 exporting to image
#18 pushing layers 1.4s done
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-20h2-amd64:012b72af@sha256:64de45c86d537de01163a8083977e49a12ad4ede9502e03cd90624a77ba15e08
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-20h2-amd64:012b72af@sha256:64de45c86d537de01163a8083977e49a12ad4ede9502e03cd90624a77ba15e08 0.3s done
#18 DONE 4.7s
error: failed to find instance "vsphere-csi-builder-win": open /root/.docker/buildx/instances/vsphere-csi-builder-win: no such file or directory
vsphere-csi-builder-win
building gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af for windows
#1 [internal] booting buildkit
#1 pulling image moby/buildkit:buildx-stable-1 0.1s done
#1 creating container buildx_buildkit_vsphere-csi-builder-win0
#1 creating container buildx_buildkit_vsphere-csi-builder-win0 0.8s done
... skipping 224 lines ...
#18 exporting to image
#18 pushing layers 1.3s done
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-ltsc2022-amd64:012b72af@sha256:a951fdc61495bdbabc662b5ca11b458204cb3f6f7f3d9039478d812caa6f15a3
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-ltsc2022-amd64:012b72af@sha256:a951fdc61495bdbabc662b5ca11b458204cb3f6f7f3d9039478d812caa6f15a3 0.3s done
#18 DONE 4.7s
building gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af for linux
error: no builder "vsphere-csi-builder-win" found
builder instance not found, safe to proceed
#1 [internal] load build definition from Dockerfile
#1 transferring dockerfile: 32B done
#1 DONE 0.0s

#2 [internal] load .dockerignore
... skipping 103 lines ...
annotating gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af for 2004
fullversion for mcr.microsoft.com/windows/nanoserver:20H2 : 10.0.19042.1706
annotating gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af for 20H2
fullversion for mcr.microsoft.com/windows/nanoserver:ltsc2022 : 10.0.20348.707
annotating gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af for ltsc2022
pushing manifest for tag gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af
failed to mount blob cloud-provider-vsphere/csi/ci/driver-linux-amd64@sha256:703fd1eddc788fdb7e10b04e4357e88b44dfcdf4b08a879d2de5f634a5e2e556 to gcr.io/cloud-provider-vsphere/csi/ci/driver:012b72af: unknown blob
make[1]: *** [Makefile:416: push-images] Error 1
make[1]: Leaving directory '/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver'
make: *** [Makefile:211: deploy] Error 2