This job view page is being replaced by Spyglass soon. Check out the new job view.
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2022-06-08 20:02
Elapsed29m37s
Revision347c5b39faa1d10d313fee43c2fcfa64e2152f6e

No Test Failures!


Error lines from build-log.txt

... skipping 128 lines ...
=== RUN   TestValidateConfigWithNoNetPermissionParams
{"level":"info","time":"2022-06-08T20:05:02.721791032Z","caller":"config/config.go:364","msg":"No Net Permissions given in Config. Using default permissions."}
--- PASS: TestValidateConfigWithNoNetPermissionParams (0.00s)
=== RUN   TestValidateConfigWithMultipleNetPermissionParams
--- PASS: TestValidateConfigWithMultipleNetPermissionParams (0.01s)
=== RUN   TestValidateConfigWithInvalidPermissions
{"level":"error","time":"2022-06-08T20:05:02.730090363Z","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-08T20:05:02.730415819Z","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-08T20:05:02.732449774Z","caller":"config/config.go:364","msg":"No Net Permissions given in Config. Using default permissions."}
--- PASS: TestSnapshotConfigWhenMaxUnspecified (0.00s)
=== RUN   TestSnapshotConfigWhenMaxSpecifiedAsEnv
{"level":"info","time":"2022-06-08T20:05:02.734200069Z","caller":"config/config.go:364","msg":"No Net Permissions given in Config. Using default permissions."}
--- PASS: TestSnapshotConfigWhenMaxSpecifiedAsEnv (0.01s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/config	0.096s
=== RUN   TestQuerySnapshotsUtil
{"level":"error","time":"2022-06-08T20:05:40.868415509Z","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-08T20:05:41.272818052Z","caller":"vsphere/utils.go:189","msg":"Defaulting timeout for vCenter Client to 5 minutes"}
{"level":"info","time":"2022-06-08T20:05:41.272955981Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
{"level":"info","time":"2022-06-08T20:05:41.272982387Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
{"level":"info","time":"2022-06-08T20:05:41.273026844Z","caller":"vsphere/virtualcentermanager.go:122","msg":"Successfully registered VC \"127.0.0.1\""}
{"level":"info","time":"2022-06-08T20:05:41.288397752Z","caller":"vsphere/virtualcenter.go:183","msg":"New session ID for 'user' = a91aba39-abf1-474f-afcf-32394f873d0a"}
{"level":"info","time":"2022-06-08T20:05:41.288834594Z","caller":"volume/manager.go:175","msg":"Initializing new defaultManager..."}
... skipping 6 lines ...
    utils_test.go:161: Snapshots: 
--- PASS: TestQuerySnapshotsUtil (0.45s)
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList/CompatibleDatastoreFound
{"level":"info","time":"2022-06-08T20:05:41.334676057Z","caller":"utils/utils.go:269","msg":"compatible datastore found, dsURL = \"/tmp/govcsim-DC0-LocalDS_1-2834671982\", dsRef = Datastore:/tmp/govcsim-DC0-LocalDS_1-2834671982@group-5"}
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList/FailToFindGivenDatastoreInCompatibleList
{"level":"error","time":"2022-06-08T20:05:41.371628889Z","caller":"utils/utils.go:274","msg":"failed to find datastore with URL \"/tmp/govcsim-DC0-LocalDS_1-2834671982\" from the input datastore list, [Datastore:/tmp/govcsim-DC0-LocalDS_2-4197129724@group-5 Datastore:/tmp/govcsim-DC0-LocalDS_0-2598403640@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-08T20:05:41.37972092Z","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-08T20:05:41.379971122Z","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-08T20:05:41.380039124Z","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-08T20:05:41.40162173Z","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-08T20:05:41.401725304Z","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-08T20:05:41.401755614Z","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.09s)
    --- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList/CompatibleDatastoreFound (0.02s)
    --- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList/FailToFindGivenDatastoreInCompatibleList (0.04s)
    --- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList/FailToFindGivenDatastoreInVC (0.01s)
    --- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList/EmptyDatastoreURLFromInput (0.02s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/common/utils	0.642s
=== RUN   TestUseVslmAPIsFuncForVC67Update3l
--- PASS: TestUseVslmAPIsFuncForVC67Update3l (0.00s)
=== RUN   TestUseVslmAPIsFuncForVC67Update3a
{"level":"error","time":"2022-06-08T20:05:42.331010638Z","caller":"common/common_controller_helper.go:205","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:205\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 46 lines ...
    --- PASS: TestParseCSISnapshotID/EmptyCSISnapshotID (0.00s)
    --- PASS: TestParseCSISnapshotID/UnexpectedFormattedCSISnapshotID (0.00s)
=== RUN   TestQueryVolumeSnapshotsByVolumeIDWithQuerySnapshotsCnsVolumeNotFoundFault
{"level":"warn","time":"2022-06-08T20:05:42.35057011Z","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-08T20:05:42.351143091Z","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:0xc0000b42c0} 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-08T20:05:42.351319446Z","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-08T20:05:42.35148182Z","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.00s)
=== RUN   TestQueryAllVolumeSnapshotsWithQuerySnapshotsUnexpectedFault
{"level":"error","time":"2022-06-08T20:05:42.351922471Z","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.209s
=== RUN   TestIsFSSEnabledInGcWithSync
{"level":"info","time":"2022-06-08T20:05:44.471743374Z","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.00s)
=== RUN   TestIsFSSEnabledInGcWithoutSync
{"level":"info","time":"2022-06-08T20:05:44.474066336Z","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-08T20:05:44.474214838Z","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-08T20:05:44.474420938Z","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.01s)
=== RUN   TestIsFSSEnabledInSV
{"level":"error","time":"2022-06-08T20:05:44.480726379Z","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-08T20:05:44.482691663Z","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.00s)
=== 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.185s
=== RUN   TestLogNewError
{"level":"error","time":"2022-06-08T20:05:34.338172749Z","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.00s)
=== RUN   TestLogNewErrorf
{"level":"error","time":"2022-06-08T20:05:34.338480873Z","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-08T20:05:34.338596298Z","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-08T20:05:34.338706193Z","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.084s
=== 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-08T20:05:43.25805687Z","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/2
{"level":"info","time":"2022-06-08T20:05:43.258280727Z","caller":"osutils/linux_os_utils.go:1053","msg":"Error parsing mount \"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/foo\\\\04\": invalid syntax"}
=== CONT  TestUnescape/1
--- PASS: TestUnescape (0.00s)
    --- PASS: TestUnescape/0 (0.00s)
    --- PASS: TestUnescape/3 (0.00s)
    --- PASS: TestUnescape/2 (0.00s)
    --- PASS: TestUnescape/1 (0.00s)
... skipping 7 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.111s
=== RUN   TestCreateVolumeWithStoragePolicy
{"level":"error","time":"2022-06-08T20:05:54.357408065Z","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-08T20:05:54.73104124Z","caller":"vsphere/utils.go:189","msg":"Defaulting timeout for vCenter Client to 5 minutes"}
{"level":"info","time":"2022-06-08T20:05:54.731296908Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
{"level":"info","time":"2022-06-08T20:05:54.731377658Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
{"level":"info","time":"2022-06-08T20:05:54.749333497Z","caller":"vsphere/virtualcentermanager.go:122","msg":"Successfully registered VC \"127.0.0.1\""}
{"level":"info","time":"2022-06-08T20:05:54.793177162Z","caller":"vsphere/virtualcenter.go:183","msg":"New session ID for 'user' = fa3c7fe6-05ad-462b-9674-fab4438a52d4"}
{"level":"info","time":"2022-06-08T20:05:54.793823991Z","caller":"volume/manager.go:175","msg":"Initializing new defaultManager..."}
... skipping 77 lines ...
{"level":"info","time":"2022-06-08T20:05:55.03840751Z","caller":"volume/manager.go:1039","msg":"DeleteVolume: Volume deleted successfully. volumeID: \"069c447c-dd20-4c1f-bf8a-541e1e4a12d9\", opId: \"\"","TraceId":"baddec20-ba2a-4023-a62f-99cac9a99d06"}
{"level":"info","time":"2022-06-08T20:05:55.038440961Z","caller":"vanilla/controller.go:979","msg":"Volume \"069c447c-dd20-4c1f-bf8a-541e1e4a12d9\" deleted successfully.","TraceId":"baddec20-ba2a-4023-a62f-99cac9a99d06"}
--- PASS: TestExtendVolume (0.09s)
=== 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-08T20:05:55.039484719Z","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":"d27d0023-cd0e-484a-bf6d-9d4057817173"}
{"level":"error","time":"2022-06-08T20:05:55.039546814Z","caller":"vanilla/controller.go:1256","msg":"cannot expand migrated vSphere volume. :\"[vsanDatastore] 08281a5f-a21d-1eff-62d6-02009d0f19a1/004dbb1694f14e3598abef852b113e3b.vmdk\"","TraceId":"d27d0023-cd0e-484a-bf6d-9d4057817173","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:1330\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-08T20:05:55.040235228Z","caller":"vanilla/controller.go:828","msg":"CreateVolume: called with args {Name:test-pvc-21ce92a2-ff2e-4165-b551-f269d7e23d9b 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":"d5b78730-50c4-405f-85bd-57cc264ba393"}
{"level":"info","time":"2022-06-08T20:05:55.079689954Z","caller":"volume/manager.go:410","msg":"CreateVolume: VolumeName: \"test-pvc-21ce92a2-ff2e-4165-b551-f269d7e23d9b\", opId: \"\"","TraceId":"d5b78730-50c4-405f-85bd-57cc264ba393"}
{"level":"info","time":"2022-06-08T20:05:55.080389076Z","caller":"volume/util.go:322","msg":"Volume created successfully. VolumeName: \"test-pvc-21ce92a2-ff2e-4165-b551-f269d7e23d9b\", volumeID: \"e7f195b0-a230-4e13-be47-f637adff3d6d\"","TraceId":"d5b78730-50c4-405f-85bd-57cc264ba393"}
{"level":"info","time":"2022-06-08T20:05:55.080440866Z","caller":"vanilla/controller.go:863","msg":"Volume created successfully. Volume Handle: \"e7f195b0-a230-4e13-be47-f637adff3d6d\", PV Name: \"test-pvc-21ce92a2-ff2e-4165-b551-f269d7e23d9b\"","TraceId":"d5b78730-50c4-405f-85bd-57cc264ba393"}
... skipping 38 lines ...
{"level":"info","time":"2022-06-08T20:05:55.169094121Z","caller":"utils/utils.go:118","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"6aa22421-fa2e-42ae-9b49-795c78bf8168"}
{"level":"info","time":"2022-06-08T20:05:55.177253053Z","caller":"utils/utils.go:150","msg":"setting max iteration to 0 for total records count: 0","TraceId":"6aa22421-fa2e-42ae-9b49-795c78bf8168"}
{"level":"info","time":"2022-06-08T20:05:55.177329966Z","caller":"utils/utils.go:170","msg":"0 more snapshots to be queried","TraceId":"6aa22421-fa2e-42ae-9b49-795c78bf8168"}
{"level":"info","time":"2022-06-08T20:05:55.177355961Z","caller":"utils/utils.go:173","msg":"QuerySnapshots retrieved all records (0) for the SnapshotQuerySpec: {DynamicData:{} VolumeId:{DynamicData:{} Id:79223b95-b2fb-4688-bcd8-81c2377d21fe} SnapshotId:<nil>} in 1 iterations","TraceId":"6aa22421-fa2e-42ae-9b49-795c78bf8168"}
{"level":"info","time":"2022-06-08T20:05:55.17740415Z","caller":"utils/utils.go:208","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:79223b95-b2fb-4688-bcd8-81c2377d21fe}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> healthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"6aa22421-fa2e-42ae-9b49-795c78bf8168"}
{"level":"info","time":"2022-06-08T20:05:55.179182403Z","caller":"utils/utils.go:215","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"6aa22421-fa2e-42ae-9b49-795c78bf8168"}
{"level":"error","time":"2022-06-08T20:05:55.179489504Z","caller":"vanilla/controller.go:951","msg":"volume: 79223b95-b2fb-4688-bcd8-81c2377d21fe with existing snapshots [size_bytes:1073741824 snapshot_id:\"79223b95-b2fb-4688-bcd8-81c2377d21fe+262c81b0-6fbe-41ad-b276-edb02d151ef4\" source_volume_id:\"79223b95-b2fb-4688-bcd8-81c2377d21fe\" creation_time:<seconds:1654718755 nanos:163938635 > ready_to_use:true ] cannot be deleted, please delete snapshots before deleting the volume","TraceId":"6aa22421-fa2e-42ae-9b49-795c78bf8168","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: 79223b95-b2fb-4688-bcd8-81c2377d21fe with existing snapshots [size_bytes:1073741824 snapshot_id:"79223b95-b2fb-4688-bcd8-81c2377d21fe+262c81b0-6fbe-41ad-b276-edb02d151ef4" source_volume_id:"79223b95-b2fb-4688-bcd8-81c2377d21fe" creation_time:<seconds:1654718755 nanos:163938635 > 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-08T20:05:55.18086567Z","caller":"vanilla/controller.go:828","msg":"CreateVolume: called with args {Name:test-pvc-461bd41b-5251-4a9f-b435-34c71e9d2727 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":"1267f8bf-462a-4e74-bd78-7779fb4207f4"}
{"level":"info","time":"2022-06-08T20:05:55.211288759Z","caller":"volume/manager.go:410","msg":"CreateVolume: VolumeName: \"test-pvc-461bd41b-5251-4a9f-b435-34c71e9d2727\", opId: \"\"","TraceId":"1267f8bf-462a-4e74-bd78-7779fb4207f4"}
{"level":"info","time":"2022-06-08T20:05:55.212375614Z","caller":"volume/util.go:322","msg":"Volume created successfully. VolumeName: \"test-pvc-461bd41b-5251-4a9f-b435-34c71e9d2727\", volumeID: \"e4f38463-d818-4ae5-9393-23e9052a9338\"","TraceId":"1267f8bf-462a-4e74-bd78-7779fb4207f4"}
{"level":"info","time":"2022-06-08T20:05:55.212430656Z","caller":"vanilla/controller.go:863","msg":"Volume created successfully. Volume Handle: \"e4f38463-d818-4ae5-9393-23e9052a9338\", PV Name: \"test-pvc-461bd41b-5251-4a9f-b435-34c71e9d2727\"","TraceId":"1267f8bf-462a-4e74-bd78-7779fb4207f4"}
... skipping 134 lines ...
{"level":"info","time":"2022-06-08T20:05:55.332835462Z","caller":"utils/utils.go:118","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"bdf4857d-ff24-4edc-96b5-63354ecc5067"}
{"level":"info","time":"2022-06-08T20:05:55.336645975Z","caller":"utils/utils.go:150","msg":"setting max iteration to 0 for total records count: 0","TraceId":"bdf4857d-ff24-4edc-96b5-63354ecc5067"}
{"level":"info","time":"2022-06-08T20:05:55.336693401Z","caller":"utils/utils.go:170","msg":"0 more snapshots to be queried","TraceId":"bdf4857d-ff24-4edc-96b5-63354ecc5067"}
{"level":"info","time":"2022-06-08T20:05:55.336715501Z","caller":"utils/utils.go:173","msg":"QuerySnapshots retrieved all records (0) for the SnapshotQuerySpec: {DynamicData:{} VolumeId:{DynamicData:{} Id:36ee22da-2167-4987-b59a-5423831ddc17} SnapshotId:<nil>} in 1 iterations","TraceId":"bdf4857d-ff24-4edc-96b5-63354ecc5067"}
{"level":"info","time":"2022-06-08T20:05:55.336756479Z","caller":"utils/utils.go:208","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:36ee22da-2167-4987-b59a-5423831ddc17}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> healthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"bdf4857d-ff24-4edc-96b5-63354ecc5067"}
{"level":"info","time":"2022-06-08T20:05:55.338105872Z","caller":"utils/utils.go:215","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"bdf4857d-ff24-4edc-96b5-63354ecc5067"}
{"level":"error","time":"2022-06-08T20:05:55.338153914Z","caller":"vanilla/controller.go:1704","msg":"the number of snapshots on the source volume 36ee22da-2167-4987-b59a-5423831ddc17 reaches the configured maximum (3)","TraceId":"bdf4857d-ff24-4edc-96b5-63354ecc5067","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:1704\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:1738\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 36ee22da-2167-4987-b59a-5423831ddc17 reaches the configured maximum (3).
{"level":"info","time":"2022-06-08T20:05:55.338403159Z","caller":"vanilla/controller.go:1754","msg":"DeleteSnapshot: called with args {SnapshotId:36ee22da-2167-4987-b59a-5423831ddc17+7e0a86a9-5cc9-4d5c-84a3-b6f90fe7eddd Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"ca6e25b1-182e-4d83-b2f4-1929fd0b4075"}
{"level":"info","time":"2022-06-08T20:05:55.344217839Z","caller":"volume/util.go:415","msg":"Calling CnsClient.DeleteSnapshots: VolumeID [\"36ee22da-2167-4987-b59a-5423831ddc17\"] SnapshotID [\"7e0a86a9-5cc9-4d5c-84a3-b6f90fe7eddd\"] cnsSnapshotDeleteSpecList [types.CnsSnapshotDeleteSpec{DynamicData:types.DynamicData{}, VolumeId:types.CnsVolumeId{DynamicData:types.DynamicData{}, Id:\"36ee22da-2167-4987-b59a-5423831ddc17\"}, SnapshotId:types.CnsSnapshotId{DynamicData:types.DynamicData{}, Id:\"7e0a86a9-5cc9-4d5c-84a3-b6f90fe7eddd\"}}]","TraceId":"ca6e25b1-182e-4d83-b2f4-1929fd0b4075"}
{"level":"info","time":"2022-06-08T20:05:55.347918514Z","caller":"volume/manager.go:2175","msg":"DeleteSnapshot: VolumeID: \"36ee22da-2167-4987-b59a-5423831ddc17\", SnapshotID: \"7e0a86a9-5cc9-4d5c-84a3-b6f90fe7eddd\", opId: \"\"","TraceId":"ca6e25b1-182e-4d83-b2f4-1929fd0b4075"}
{"level":"info","time":"2022-06-08T20:05:55.347986926Z","caller":"volume/manager.go:2231","msg":"DeleteSnapshot: Snapshot \"7e0a86a9-5cc9-4d5c-84a3-b6f90fe7eddd\" on volume \"36ee22da-2167-4987-b59a-5423831ddc17\" is deleted successfully. opId: \"\"","TraceId":"ca6e25b1-182e-4d83-b2f4-1929fd0b4075"}
{"level":"info","time":"2022-06-08T20:05:55.348022826Z","caller":"vanilla/controller.go:1782","msg":"DeleteSnapshot: successfully deleted snapshot \"36ee22da-2167-4987-b59a-5423831ddc17+7e0a86a9-5cc9-4d5c-84a3-b6f90fe7eddd\"","TraceId":"ca6e25b1-182e-4d83-b2f4-1929fd0b4075"}
{"level":"info","time":"2022-06-08T20:05:55.348044609Z","caller":"vanilla/controller.go:1793","msg":"Snapshot \"36ee22da-2167-4987-b59a-5423831ddc17+7e0a86a9-5cc9-4d5c-84a3-b6f90fe7eddd\" deleted successfully.","TraceId":"ca6e25b1-182e-4d83-b2f4-1929fd0b4075"}
... skipping 54 lines ...
{"level":"info","time":"2022-06-08T20:05:55.522092915Z","caller":"volume/manager.go:410","msg":"CreateVolume: VolumeName: \"test-pvc-c4c91c9d-ee98-4923-b58d-c64f07bb576e\", opId: \"\"","TraceId":"08cebf42-4a97-4213-b1e4-75147be2cbda"}
{"level":"info","time":"2022-06-08T20:05:55.522994327Z","caller":"volume/util.go:322","msg":"Volume created successfully. VolumeName: \"test-pvc-c4c91c9d-ee98-4923-b58d-c64f07bb576e\", volumeID: \"a3c8df9a-19d8-4907-beaa-ab623891c33f\"","TraceId":"08cebf42-4a97-4213-b1e4-75147be2cbda"}
{"level":"info","time":"2022-06-08T20:05:55.523043404Z","caller":"vanilla/controller.go:863","msg":"Volume created successfully. Volume Handle: \"a3c8df9a-19d8-4907-beaa-ab623891c33f\", PV Name: \"test-pvc-c4c91c9d-ee98-4923-b58d-c64f07bb576e\"","TraceId":"08cebf42-4a97-4213-b1e4-75147be2cbda"}
{"level":"info","time":"2022-06-08T20:05:55.523963132Z","caller":"vanilla/controller.go:828","msg":"CreateVolume: called with args {Name:test-pvc-c17a3fed-56ad-4054-aa69-7bc8336074d6 CapacityRange:required_bytes:2147483648  VolumeCapabilities:[access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[] Secrets:map[] VolumeContentSource:snapshot:<snapshot_id:\"97ea2248-6a8f-4270-9566-275dca0b644f+79446e6c-6f69-408f-b3ef-f8021e8390aa\" >  AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"fd3ec380-3e51-4787-b9cd-9d8f06da9af2"}
{"level":"info","time":"2022-06-08T20:05:55.524033938Z","caller":"utils/utils.go:208","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:97ea2248-6a8f-4270-9566-275dca0b644f}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> healthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"fd3ec380-3e51-4787-b9cd-9d8f06da9af2"}
{"level":"info","time":"2022-06-08T20:05:55.525305941Z","caller":"utils/utils.go:215","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"fd3ec380-3e51-4787-b9cd-9d8f06da9af2"}
{"level":"error","time":"2022-06-08T20:05:55.525334928Z","caller":"vanilla/controller.go:435","msg":"size mismatches, requested volume size 2147483648 and source snapshot size 1073741824","TraceId":"fd3ec380-3e51-4787-b9cd-9d8f06da9af2","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-08T20:05:55.525527328Z","caller":"vanilla/controller.go:881","msg":"DeleteVolume: called with args: {VolumeId:a3c8df9a-19d8-4907-beaa-ab623891c33f Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"f707da12-248d-4500-a156-4f44d5f48485"}
{"level":"info","time":"2022-06-08T20:05:55.526835457Z","caller":"common/vsphereutil.go:1095","msg":"volume: a3c8df9a-19d8-4907-beaa-ab623891c33f is of type: BLOCK","TraceId":"f707da12-248d-4500-a156-4f44d5f48485"}
{"level":"info","time":"2022-06-08T20:05:55.5268858Z","caller":"utils/utils.go:93","msg":"Invoking QuerySnapshots with spec: {DynamicData:{} VolumeId:{DynamicData:{} Id:a3c8df9a-19d8-4907-beaa-ab623891c33f} SnapshotId:<nil>}","TraceId":"f707da12-248d-4500-a156-4f44d5f48485"}
{"level":"info","time":"2022-06-08T20:05:55.526899566Z","caller":"utils/utils.go:118","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"f707da12-248d-4500-a156-4f44d5f48485"}
{"level":"info","time":"2022-06-08T20:05:55.568600127Z","caller":"utils/utils.go:131","msg":"QuerySnapshots retrieved no results for the spec: {DynamicData:{} VolumeId:{DynamicData:{} Id:a3c8df9a-19d8-4907-beaa-ab623891c33f} SnapshotId:<nil>}","TraceId":"f707da12-248d-4500-a156-4f44d5f48485"}
{"level":"info","time":"2022-06-08T20:05:55.568653579Z","caller":"utils/utils.go:150","msg":"setting max iteration to 0 for total records count: 0","TraceId":"f707da12-248d-4500-a156-4f44d5f48485"}
... skipping 473 lines ...
{"level":"info","time":"2022-06-08T20:05:56.260153005Z","caller":"utils/utils.go:118","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"29975ae0-8946-4dc8-8dcf-b6a49e45ec38"}
{"level":"info","time":"2022-06-08T20:05:56.265406968Z","caller":"utils/utils.go:150","msg":"setting max iteration to 0 for total records count: 0","TraceId":"29975ae0-8946-4dc8-8dcf-b6a49e45ec38"}
{"level":"info","time":"2022-06-08T20:05:56.265458156Z","caller":"utils/utils.go:170","msg":"0 more snapshots to be queried","TraceId":"29975ae0-8946-4dc8-8dcf-b6a49e45ec38"}
{"level":"info","time":"2022-06-08T20:05:56.265482357Z","caller":"utils/utils.go:173","msg":"QuerySnapshots retrieved all records (0) for the SnapshotQuerySpec: {DynamicData:{} VolumeId:{DynamicData:{} Id:7be9d6a2-6850-4a31-8d20-200cca3dec52} SnapshotId:<nil>} in 1 iterations","TraceId":"29975ae0-8946-4dc8-8dcf-b6a49e45ec38"}
{"level":"info","time":"2022-06-08T20:05:56.265521103Z","caller":"utils/utils.go:208","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:7be9d6a2-6850-4a31-8d20-200cca3dec52}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> healthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"29975ae0-8946-4dc8-8dcf-b6a49e45ec38"}
{"level":"info","time":"2022-06-08T20:05:56.267319512Z","caller":"utils/utils.go:215","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"29975ae0-8946-4dc8-8dcf-b6a49e45ec38"}
{"level":"error","time":"2022-06-08T20:05:56.267425359Z","caller":"vanilla/controller.go:1298","msg":"volume: 7be9d6a2-6850-4a31-8d20-200cca3dec52 with existing snapshots [size_bytes:1073741824 snapshot_id:\"7be9d6a2-6850-4a31-8d20-200cca3dec52+fef2f00b-8f3c-4232-baa1-becc4a598d87\" source_volume_id:\"7be9d6a2-6850-4a31-8d20-200cca3dec52\" creation_time:<seconds:1654718756 nanos:257286429 > ready_to_use:true ] cannot be expanded. Please delete snapshots before expanding the volume","TraceId":"29975ae0-8946-4dc8-8dcf-b6a49e45ec38","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:1298\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:1330\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: 7be9d6a2-6850-4a31-8d20-200cca3dec52 with existing snapshots [size_bytes:1073741824 snapshot_id:"7be9d6a2-6850-4a31-8d20-200cca3dec52+fef2f00b-8f3c-4232-baa1-becc4a598d87" source_volume_id:"7be9d6a2-6850-4a31-8d20-200cca3dec52" creation_time:<seconds:1654718756 nanos:257286429 > ready_to_use:true ] cannot be expanded. Please delete snapshots before expanding the volume
{"level":"info","time":"2022-06-08T20:05:56.267703935Z","caller":"vanilla/controller.go:1754","msg":"DeleteSnapshot: called with args {SnapshotId:7be9d6a2-6850-4a31-8d20-200cca3dec52+fef2f00b-8f3c-4232-baa1-becc4a598d87 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"18c1de75-bfba-46a3-a352-b7bee928df69"}
{"level":"info","time":"2022-06-08T20:05:56.268757136Z","caller":"volume/util.go:415","msg":"Calling CnsClient.DeleteSnapshots: VolumeID [\"7be9d6a2-6850-4a31-8d20-200cca3dec52\"] SnapshotID [\"fef2f00b-8f3c-4232-baa1-becc4a598d87\"] cnsSnapshotDeleteSpecList [types.CnsSnapshotDeleteSpec{DynamicData:types.DynamicData{}, VolumeId:types.CnsVolumeId{DynamicData:types.DynamicData{}, Id:\"7be9d6a2-6850-4a31-8d20-200cca3dec52\"}, SnapshotId:types.CnsSnapshotId{DynamicData:types.DynamicData{}, Id:\"fef2f00b-8f3c-4232-baa1-becc4a598d87\"}}]","TraceId":"18c1de75-bfba-46a3-a352-b7bee928df69"}
{"level":"info","time":"2022-06-08T20:05:56.276216208Z","caller":"volume/manager.go:2175","msg":"DeleteSnapshot: VolumeID: \"7be9d6a2-6850-4a31-8d20-200cca3dec52\", SnapshotID: \"fef2f00b-8f3c-4232-baa1-becc4a598d87\", opId: \"\"","TraceId":"18c1de75-bfba-46a3-a352-b7bee928df69"}
{"level":"info","time":"2022-06-08T20:05:56.276281788Z","caller":"volume/manager.go:2231","msg":"DeleteSnapshot: Snapshot \"fef2f00b-8f3c-4232-baa1-becc4a598d87\" on volume \"7be9d6a2-6850-4a31-8d20-200cca3dec52\" is deleted successfully. opId: \"\"","TraceId":"18c1de75-bfba-46a3-a352-b7bee928df69"}
{"level":"info","time":"2022-06-08T20:05:56.276318409Z","caller":"vanilla/controller.go:1782","msg":"DeleteSnapshot: successfully deleted snapshot \"7be9d6a2-6850-4a31-8d20-200cca3dec52+fef2f00b-8f3c-4232-baa1-becc4a598d87\"","TraceId":"18c1de75-bfba-46a3-a352-b7bee928df69"}
{"level":"info","time":"2022-06-08T20:05:56.276335228Z","caller":"vanilla/controller.go:1793","msg":"Snapshot \"7be9d6a2-6850-4a31-8d20-200cca3dec52+fef2f00b-8f3c-4232-baa1-becc4a598d87\" deleted successfully.","TraceId":"18c1de75-bfba-46a3-a352-b7bee928df69"}
... skipping 15 lines ...
=== RUN   TestDeleteBlockVolumeSnapshotWithManagedObjectNotFound
{"level":"info","time":"2022-06-08T20:05:56.297499079Z","caller":"vanilla/controller.go:828","msg":"CreateVolume: called with args {Name:test-pvc-00c46431-7615-4611-9d47-75a23a9eab28 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":"c8c3e652-2667-4462-8b02-fdf6bd4bc1a4"}
{"level":"info","time":"2022-06-08T20:05:56.320882733Z","caller":"volume/manager.go:410","msg":"CreateVolume: VolumeName: \"test-pvc-00c46431-7615-4611-9d47-75a23a9eab28\", opId: \"\"","TraceId":"c8c3e652-2667-4462-8b02-fdf6bd4bc1a4"}
{"level":"info","time":"2022-06-08T20:05:56.321755616Z","caller":"volume/util.go:322","msg":"Volume created successfully. VolumeName: \"test-pvc-00c46431-7615-4611-9d47-75a23a9eab28\", volumeID: \"641f6d1d-13f1-415b-9071-3b8ca4e5c4d4\"","TraceId":"c8c3e652-2667-4462-8b02-fdf6bd4bc1a4"}
{"level":"info","time":"2022-06-08T20:05:56.321815899Z","caller":"vanilla/controller.go:863","msg":"Volume created successfully. Volume Handle: \"641f6d1d-13f1-415b-9071-3b8ca4e5c4d4\", PV Name: \"test-pvc-00c46431-7615-4611-9d47-75a23a9eab28\"","TraceId":"c8c3e652-2667-4462-8b02-fdf6bd4bc1a4"}
{"level":"info","time":"2022-06-08T20:05:56.324256334Z","caller":"vanilla/controller.go:1754","msg":"DeleteSnapshot: called with args {SnapshotId:641f6d1d-13f1-415b-9071-3b8ca4e5c4d4+f6c8dcf6-0360-4257-b557-893557aea77d Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"da36ab19-46f1-4af2-9a88-982806666b5c"}
{"level":"info","time":"2022-06-08T20:05:56.328018764Z","caller":"volume/manager.go:2149","msg":"Snapshot \"f6c8dcf6-0360-4257-b557-893557aea77d\" on volume \"641f6d1d-13f1-415b-9071-3b8ca4e5c4d4\" might have already been deleted with the error ServerFaultCode: ManagedObjectNotFound. Calling CNS QuerySnapshots API to confirm it","TraceId":"da36ab19-46f1-4af2-9a88-982806666b5c"}
{"level":"info","time":"2022-06-08T20:05:56.332687141Z","caller":"volume/util.go:495","msg":"fault in the result of query CNS for snapshot f6c8dcf6-0360-4257-b557-893557aea77d on volume 641f6d1d-13f1-415b-9071-3b8ca4e5c4d4: (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) \"641f6d1d-13f1-415b-9071-3b8ca4e5c4d4\"\n },\n SnapshotId: (types.CnsSnapshotId) {\n  DynamicData: (types.DynamicData) {\n  },\n  Id: (string) (len=36) \"f6c8dcf6-0360-4257-b557-893557aea77d\"\n }\n}\n","TraceId":"da36ab19-46f1-4af2-9a88-982806666b5c"}
{"level":"info","time":"2022-06-08T20:05:56.332745168Z","caller":"volume/manager.go:2160","msg":"DeleteSnapshot: Snapshot \"f6c8dcf6-0360-4257-b557-893557aea77d\" on volume \"641f6d1d-13f1-415b-9071-3b8ca4e5c4d4\" is confirmed to be deleted successfully","TraceId":"da36ab19-46f1-4af2-9a88-982806666b5c"}
{"level":"info","time":"2022-06-08T20:05:56.332786727Z","caller":"vanilla/controller.go:1782","msg":"DeleteSnapshot: successfully deleted snapshot \"641f6d1d-13f1-415b-9071-3b8ca4e5c4d4+f6c8dcf6-0360-4257-b557-893557aea77d\"","TraceId":"da36ab19-46f1-4af2-9a88-982806666b5c"}
{"level":"info","time":"2022-06-08T20:05:56.332803874Z","caller":"vanilla/controller.go:1793","msg":"Snapshot \"641f6d1d-13f1-415b-9071-3b8ca4e5c4d4+f6c8dcf6-0360-4257-b557-893557aea77d\" deleted successfully.","TraceId":"da36ab19-46f1-4af2-9a88-982806666b5c"}
{"level":"info","time":"2022-06-08T20:05:56.332969793Z","caller":"vanilla/controller.go:881","msg":"DeleteVolume: called with args: {VolumeId:641f6d1d-13f1-415b-9071-3b8ca4e5c4d4 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"76f1768d-a28f-4fe0-b1fc-649c457a7088"}
{"level":"info","time":"2022-06-08T20:05:56.335161841Z","caller":"common/vsphereutil.go:1095","msg":"volume: 641f6d1d-13f1-415b-9071-3b8ca4e5c4d4 is of type: BLOCK","TraceId":"76f1768d-a28f-4fe0-b1fc-649c457a7088"}
... skipping 69 lines ...
{"level":"info","time":"2022-06-08T20:05:56.438460926Z","caller":"volume/manager.go:1039","msg":"DeleteVolume: Volume deleted successfully. volumeID: \"c734522d-1be8-4d61-817f-5a90d308aed2\", opId: \"\"","TraceId":"614fe49f-6ecb-4f9e-9c9b-90a7e83e1381"}
{"level":"info","time":"2022-06-08T20:05:56.438489594Z","caller":"vanilla/controller.go:979","msg":"Volume \"c734522d-1be8-4d61-817f-5a90d308aed2\" deleted successfully.","TraceId":"614fe49f-6ecb-4f9e-9c9b-90a7e83e1381"}
--- PASS: TestCreateSnapshotWithManagedObjectNotFound (0.09s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/vanilla	2.294s
=== RUN   TestWCPCreateVolumeWithStoragePolicy
{"level":"error","time":"2022-06-08T20:05:56.807566843Z","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-08T20:05:57.25665981Z","caller":"vsphere/utils.go:189","msg":"Defaulting timeout for vCenter Client to 5 minutes"}
{"level":"info","time":"2022-06-08T20:05:57.256807921Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
{"level":"info","time":"2022-06-08T20:05:57.256830934Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
{"level":"info","time":"2022-06-08T20:05:57.256876418Z","caller":"vsphere/virtualcentermanager.go:122","msg":"Successfully registered VC \"127.0.0.1\""}
{"level":"info","time":"2022-06-08T20:05:57.267631706Z","caller":"vsphere/virtualcenter.go:183","msg":"New session ID for 'user' = 86592a23-9dae-4a9f-8845-1431728a36f0"}
{"level":"info","time":"2022-06-08T20:05:57.267910747Z","caller":"volume/manager.go:175","msg":"Initializing new defaultManager..."}
... skipping 5 lines ...
{"level":"info","time":"2022-06-08T20:05:57.31438425Z","caller":"volume/manager.go:1014","msg":"DeleteVolume: volumeID: \"87ab3847-9e49-4c69-a057-bd9dee609af9\", opId: \"\"","TraceId":"2413fd0c-e3ef-4b44-846f-20181c0c51d4"}
{"level":"info","time":"2022-06-08T20:05:57.314519412Z","caller":"volume/manager.go:1039","msg":"DeleteVolume: Volume deleted successfully. volumeID: \"87ab3847-9e49-4c69-a057-bd9dee609af9\", opId: \"\"","TraceId":"2413fd0c-e3ef-4b44-846f-20181c0c51d4"}
{"level":"info","time":"2022-06-08T20:05:57.314605178Z","caller":"wcp/controller.go:837","msg":"Volume \"87ab3847-9e49-4c69-a057-bd9dee609af9\" deleted successfully.","TraceId":"2413fd0c-e3ef-4b44-846f-20181c0c51d4"}
--- PASS: TestWCPCreateVolumeWithStoragePolicy (0.51s)
=== RUN   TestWCPCreateVolumeWithZonalLabelPresentButNoStorageTopoType
{"level":"info","time":"2022-06-08T20:05:57.321005869Z","caller":"wcp/controller.go:744","msg":"CreateVolume: called with args {Name:test-pvc-2a86723a-968c-4694-ad7f-3f32ae8e2664 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":"592e3897-eb51-49a7-9b32-e8c1999b533c"}
{"level":"error","time":"2022-06-08T20:05:57.321872325Z","caller":"wcp/controller.go:430","msg":"StorageTopologyType is unset while topology label is present","TraceId":"592e3897-eb51-49a7-9b32-e8c1999b533c","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:430\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:780\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:782\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.01s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/csi/service/wcp	0.739s
=== RUN   TestGuestClusterControllerFlow
{"level":"error","time":"2022-06-08T20:05:53.10395048Z","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-08T20:05:53.105365807Z","caller":"wcpguest/controller.go:232","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":"3f7bd375-5b84-4e2f-bf0d-cd077254542e"}
{"level":"info","time":"2022-06-08T20:05:53.105863209Z","caller":"wcpguest/controller_helper.go:261","msg":"Waiting up to 240 seconds for PersistentVolumeClaim -12345 in namespace test-namespace to have phase Bound","TraceId":"3f7bd375-5b84-4e2f-bf0d-cd077254542e"}
{"level":"info","time":"2022-06-08T20:05:58.109943053Z","caller":"wcpguest/controller_helper.go:277","msg":"PersistentVolumeClaim -12345 in namespace test-namespace is in state Bound","TraceId":"3f7bd375-5b84-4e2f-bf0d-cd077254542e"}
{"level":"info","time":"2022-06-08T20:05:58.110055951Z","caller":"wcpguest/controller.go:378","msg":"Volume created successfully. Volume Handle: \"-12345\", PV Name: \"pvc-12345\"","TraceId":"3f7bd375-5b84-4e2f-bf0d-cd077254542e"}
{"level":"info","time":"2022-06-08T20:05:58.110232928Z","caller":"wcpguest/controller.go:397","msg":"DeleteVolume: called with args: {VolumeId:-12345 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"1dedbe25-c32e-40ee-94ff-bbcc5315ef82"}
{"level":"info","time":"2022-06-08T20:05:58.110280341Z","caller":"wcpguest/controller.go:442","msg":"DeleteVolume: Volume deleted successfully. VolumeID: \"-12345\"","TraceId":"1dedbe25-c32e-40ee-94ff-bbcc5315ef82"}
... 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.228s
=== RUN   TestSyncerWorkflows
    syncer_test.go:161: TestSyncerWorkflows: start
{"level":"error","time":"2022-06-08T20:06:01.508962063Z","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-08T20:06:01.898447871Z","caller":"vsphere/utils.go:189","msg":"Defaulting timeout for vCenter Client to 5 minutes"}
{"level":"info","time":"2022-06-08T20:06:01.89886472Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
{"level":"info","time":"2022-06-08T20:06:01.898908241Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
{"level":"info","time":"2022-06-08T20:06:01.901332978Z","caller":"vsphere/virtualcentermanager.go:122","msg":"Successfully registered VC \"127.0.0.1\""}
{"level":"info","time":"2022-06-08T20:06:01.909307737Z","caller":"vsphere/virtualcenter.go:183","msg":"New session ID for 'user' = 23680646-d6ba-40eb-ac85-50b3b80d782a"}
{"level":"info","time":"2022-06-08T20:06:01.909595452Z","caller":"volume/manager.go:175","msg":"Initializing new defaultManager..."}
... skipping 158 lines ...
    --- PASS: TestValidatePVCAnnotationForVolumeHealth/TestUpdatePVCAnnVolumeHealthToInaccessibleByCSIServiceAccount (0.00s)
    --- PASS: TestValidatePVCAnnotationForVolumeHealth/TestUpdatePVCAnnVolumeHealthToAccessibleByCSIServiceAccount (0.00s)
    --- PASS: TestValidatePVCAnnotationForVolumeHealth/TestUpdatePVCRemoveAnnVolumeHealthByDevopsUser (0.00s)
    --- PASS: TestValidatePVCAnnotationForVolumeHealth/TestUpdatePVCRemoveAnnVolumeHealthByCSIServiceAccount (0.00s)
=== RUN   TestValidateStorageClassForAllowVolumeExpansion
{"level":"info","time":"2022-06-08T20:05:53.905127356Z","caller":"admissionhandler/validatestorageclass.go:77","msg":"Validating StorageClass: \"sc\""}
{"level":"error","time":"2022-06-08T20:05:53.905215218Z","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-08T20:05:53.907098216Z","caller":"admissionhandler/validatestorageclass.go:77","msg":"Validating StorageClass: \"sc\""}
{"level":"error","time":"2022-06-08T20:05:53.907214286Z","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-08T20:05:53.907465331Z","caller":"admissionhandler/validatestorageclass.go:77","msg":"Validating StorageClass: \"sc\""}
{"level":"error","time":"2022-06-08T20:05:53.907533332Z","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-08T20:05:53.908104664Z","caller":"admissionhandler/validatestorageclass.go:77","msg":"Validating StorageClass: \"sc\""}
{"level":"info","time":"2022-06-08T20:05:53.908170791Z","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-08T20:06:00.195055065Z","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-08T20:06:00.195484908Z","caller":"csinodetopology/csinodetopology_controller.go:342","msg":"Start reconciling the CSINodeTopology request test-csinodetopology-name in GUEST_CLUSTER"}
{"level":"info","time":"2022-06-08T20:06:00.195669413Z","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-08T20:06:00.195894888Z","caller":"csinodetopology/csinodetopology_controller.go:342","msg":"Start reconciling the CSINodeTopology request test-csinodetopology-name in GUEST_CLUSTER"}
{"level":"error","time":"2022-06-08T20:06:00.196298635Z","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-08T20:06:00.196741265Z","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.02s)
    --- PASS: TestCSINodeTopologyControllerForTKGSHA/TestWithVmStatusZoneEmpty (0.00s)
    --- PASS: TestCSINodeTopologyControllerForTKGSHA/TestWithGetVmFailure (0.01s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v2/pkg/syncer/cnsoperator/controller/csinodetopology	0.119s
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:347c5b39 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.0s

#2 [internal] load .dockerignore
... skipping 91 lines ...
#0 9.314 python3                  x86_64       3.10.0-3.ph4     photon-updates   3.44M 3605256
#0 9.314 ncurses                  x86_64       6.2-6.ph4        photon-updates 363.42k 372138
#0 9.314 expat                    x86_64       2.2.9-9.ph4      photon-updates  31.54k 32296
#0 9.314 pcre                     x86_64       8.44-2.ph4       photon-release 727.69k 745153
#0 9.314 libseccomp               x86_64       2.5.0-2.ph4      photon-release 167.72k 171743
#0 9.314 libmicrohttpd            x86_64       0.9.71-2.ph4     photon-release 148.80k 152368
#0 9.314 libgpg-error             x86_64       1.39-1.ph4       photon-release 223.29k 228654
#0 9.314 libacl                   x86_64       2.2.53-1.ph4     photon-release  39.69k 40642
#0 9.314 kmod                     x86_64       27-1.ph4         photon-release 266.29k 272681
#0 9.314 systemd-rpm-macros       noarch       247.11-2.ph4     photon-updates   5.45k 5581
#0 9.314 systemd-pam              x86_64       247.11-2.ph4     photon-updates 452.89k 463757
#0 9.314 systemd-libs             x86_64       247.11-2.ph4     photon-updates   1.60M 1673900
#0 9.314 elfutils                 x86_64       0.181-4.ph4      photon-updates   3.56M 3728253
... skipping 184 lines ...
#8 30.91 Installing/Updating: libselinux-3.3-1.ph4.x86_64
#8 30.93 Installing/Updating: coreutils-selinux-9.1-1.ph4.x86_64
#8 31.04 Installing/Updating: xz-5.2.5-2.ph4.x86_64
#8 31.07 Installing/Updating: cracklib-2.9.7-2.ph4.x86_64
#8 31.09 using empty dict to provide pw_dict
#8 31.10 Installing/Updating: gc-8.0.4-1.ph4.x86_64
#8 31.13 Installing/Updating: libgpg-error-1.39-1.ph4.x86_64
#8 31.16 Installing/Updating: libgcrypt-1.9.4-1.ph4.x86_64
#8 31.20 Installing/Updating: ncurses-6.2-6.ph4.x86_64
#8 31.21 Installing/Updating: libtirpc-1.2.6-2.ph4.x86_64
#8 31.23 Installing/Updating: libltdl-2.4.6-3.ph4.x86_64
#8 31.25 Installing/Updating: libunistring-0.9.10-1.ph4.x86_64
#8 31.32 Installing/Updating: pkg-config-0.29.2-4.ph4.x86_64
... skipping 189 lines ...
 ---> Running in cc94e5873a6d
Removing intermediate container cc94e5873a6d
 ---> b079fbd1ab3a
Successfully built b079fbd1ab3a
Successfully tagged gcr.io/cloud-provider-vsphere/csi/ci/syncer:347c5b39
tagging image gcr.io/cloud-provider-vsphere/csi/ci/syncer:347c5b39 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:347c5b39 for windows
#1 [internal] booting buildkit
#1 pulling image moby/buildkit:buildx-stable-1
#1 pulling image moby/buildkit:buildx-stable-1 3.8s done
#1 creating container buildx_buildkit_vsphere-csi-builder-win0
... skipping 213 lines ...
#18 DONE 9.3s
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:347c5b39 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.9s done
... skipping 190 lines ...

#18 exporting to image
#18 pushing layers 1.4s done
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-1809-amd64:347c5b39@sha256:f631e997a5e0d4d638e2f1e01af2223c82faf177cd8ce38792fc4c9f78cfd70c
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-1809-amd64:347c5b39@sha256:f631e997a5e0d4d638e2f1e01af2223c82faf177cd8ce38792fc4c9f78cfd70c 0.8s done
#18 DONE 6.4s
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:347c5b39 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 1.5s done
... skipping 228 lines ...

#18 exporting to image
#18 pushing layers 2.3s done
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-1903-amd64:347c5b39@sha256:758b7747736cb2fdf9a94dea743722afd2ee4952cecc52b4923f0267dee54825
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-1903-amd64:347c5b39@sha256:758b7747736cb2fdf9a94dea743722afd2ee4952cecc52b4923f0267dee54825 0.3s done
#18 DONE 11.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:347c5b39 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 245 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:347c5b39@sha256:058761f8355cfff12543dc09bdc4399ab4c0dc339b267421c22b172a0b88f016
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-1909-amd64:347c5b39@sha256:058761f8355cfff12543dc09bdc4399ab4c0dc339b267421c22b172a0b88f016 0.3s done
#18 DONE 4.8s
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:347c5b39 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 1.1s done
... skipping 244 lines ...

#18 exporting to image
#18 pushing layers 2.2s done
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-2004-amd64:347c5b39@sha256:30aa73ff9200583f672f7d316507393cfa45b33fb8534dc2ce24abbea0b8a2aa
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-2004-amd64:347c5b39@sha256:30aa73ff9200583f672f7d316507393cfa45b33fb8534dc2ce24abbea0b8a2aa 0.4s done
#18 DONE 10.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:347c5b39 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 258 lines ...

#18 exporting to image
#18 pushing layers 1.3s done
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-20h2-amd64:347c5b39@sha256:ba8c387ca6aa93373f383a1a444804ed4d711ff8cebfeeb2d46971af317d7513
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-20h2-amd64:347c5b39@sha256:ba8c387ca6aa93373f383a1a444804ed4d711ff8cebfeeb2d46971af317d7513 0.3s done
#18 DONE 4.8s
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:347c5b39 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 225 lines ...
#18 exporting to image
#18 pushing layers 2.5s done
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-ltsc2022-amd64:347c5b39@sha256:a11f22f72faa26c1117f41d4f6fcb658433a6bba8405fc71e28d63dacebb2ec1
#18 pushing manifest for gcr.io/cloud-provider-vsphere/csi/ci/driver-windows-ltsc2022-amd64:347c5b39@sha256:a11f22f72faa26c1117f41d4f6fcb658433a6bba8405fc71e28d63dacebb2ec1 0.4s done
#18 DONE 6.3s
building gcr.io/cloud-provider-vsphere/csi/ci/driver:347c5b39 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 202 lines ...
annotating gcr.io/cloud-provider-vsphere/csi/ci/driver:latest for 2004
fullversion for mcr.microsoft.com/windows/nanoserver:20H2 : 10.0.19042.1706
annotating gcr.io/cloud-provider-vsphere/csi/ci/driver:latest for 20H2
fullversion for mcr.microsoft.com/windows/nanoserver:ltsc2022 : 10.0.20348.707
annotating gcr.io/cloud-provider-vsphere/csi/ci/driver:latest for ltsc2022
pushing manifest for tag gcr.io/cloud-provider-vsphere/csi/ci/driver:latest
failed to mount blob cloud-provider-vsphere/csi/ci/driver-windows-2004-amd64@sha256:71cc8afeb0afa0a0438a67cd3e3af1a5045ad9c0239e2aab3764c23c85c86218 to gcr.io/cloud-provider-vsphere/csi/ci/driver:latest: 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