post-vsphere-csi-driver-deploy #1636042654263283712 Results

Error lines from build-log.txt

Raw build-log.txt
... skipping 121 lines ...
=== RUN   TestAddRemoveListView
{"level":"info","time":"2023-03-15T16:35:41.517941817Z","caller":"volume/listview.go:90","msg":"created listView object ListView:session[b2977649-80a9-40b0-9133-16f19117a2a1]489c5915-07d4-4592-bcf6-7c7ef840bfb2 for virtualCenter: VirtualCenter [Config: <nil>, Client: &{0xc000668b00 0xc0001f0370}, PbmClient: <nil>]","TraceId":"25c95606-b27f-4aae-b13c-31567ef80485"}
{"level":"info","time":"2023-03-15T16:35:41.519652181Z","caller":"volume/listview.go:197","msg":"connection to vc successful","TraceId":"25c95606-b27f-4aae-b13c-31567ef80485"}
{"level":"info","time":"2023-03-15T16:35:41.519730847Z","caller":"volume/listview.go:212","msg":"Starting listening for task updates...","TraceId":"25c95606-b27f-4aae-b13c-31567ef80485"}
    listview_test.go:51: createTask created: Task:task-66
{"level":"info","time":"2023-03-15T16:35:41.520022631Z","caller":"volume/listview.go:124","msg":"AddTask called for Task:task-66","TraceId":"25c95606-b27f-4aae-b13c-31567ef80485"}
{"level":"info","time":"2023-03-15T16:35:41.525312065Z","caller":"volume/listview.go:258","msg":"processTaskUpdate for property change update: {DynamicData:{} Name:info Op:assign Val:{DynamicData:{} Key:task-66 Task:Task:task-66 Description:<nil> Name:CnsCreateVolume DescriptionId:CnsVolumeManager.CnsCreateVolume Entity:CnsVolumeManager:cns-volume-manager EntityName:cns-volume-manager Locked:[] State:success Cancelled:false Cancelable:false Error:<nil> Result:{DynamicData:{} VolumeResults:[0xc000e84c00]} Progress:0 Reason:0xc000215ae0 QueueTime:2023-03-15 16:35:41.519642083 +0000 UTC StartTime:2023-03-15 16:35:41.519676442 +0000 UTC CompleteTime:2023-03-15 16:35:41.519887311 +0000 UTC EventChainId:0 ChangeTag: ParentTaskKey: RootTaskKey: ActivationId:}}","TraceId":"25c95606-b27f-4aae-b13c-31567ef80485"}
{"level":"error","time":"2023-03-15T16:35:41.525436169Z","caller":"volume/listview.go:270","msg":"failed to retrieve receiver channel for task Task:task-66","TraceId":"25c95606-b27f-4aae-b13c-31567ef80485","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/volume.(*ListViewImpl).processTaskUpdate\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/cns-lib/volume/listview.go:270"}
{"level":"info","time":"2023-03-15T16:35:41.528668287Z","caller":"volume/listview.go:129","msg":"task Task:task-66 added to listView","TraceId":"25c95606-b27f-4aae-b13c-31567ef80485"}
panic: test timed out after 10m0s
running tests:
	TestAddRemoveListView (10m0s)

goroutine 87 [running]:
... skipping 42 lines ...
net/http.(*Server).Serve(0xc00070c000, {0x2255da0, 0xc000b6c138})
	/usr/local/go/src/net/http/server.go:3059 +0x385
github.com/vmware/govmomi/simulator/internal.(*Server).goServe.func1()
	/home/prow/go/pkg/mod/github.com/vmware/govmomi@v0.30.0/simulator/internal/server.go:278 +0x6a
created by github.com/vmware/govmomi/simulator/internal.(*Server).goServe
	/home/prow/go/pkg/mod/github.com/vmware/govmomi@v0.30.0/simulator/internal/server.go:276 +0x6a
FAIL	sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/volume	600.149s
=== RUN   TestFilterSuspendedDatastoresWhenDatastoreIsSuspended
{"level":"info","time":"2023-03-15T16:35:41.052697333Z","caller":"vsphere/utils.go:561","msg":"Ignoring datastore test-ds as it is suspended. Datastore moref: datastore:datastore-1"}
{"level":"error","time":"2023-03-15T16:35:41.052985996Z","caller":"vsphere/utils.go:579","msg":"No datastores are available after filtering suspended datastores","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/vsphere.FilterSuspendedDatastores\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/cns-lib/vsphere/utils.go:579\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/vsphere.TestFilterSuspendedDatastoresWhenDatastoreIsSuspended\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/cns-lib/vsphere/utils_test.go:35\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
--- PASS: TestFilterSuspendedDatastoresWhenDatastoreIsSuspended (0.00s)
=== RUN   TestFilterSuspendedDatastoresWhenDatastoreIsNotSuspended
{"level":"info","time":"2023-03-15T16:35:41.063399625Z","caller":"vsphere/utils.go:582","msg":"Filtered list of datastores after removing suspended ones are: [Datastore: <nil>, datastore URL: ]"}
--- PASS: TestFilterSuspendedDatastoresWhenDatastoreIsNotSuspended (0.01s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/cns-lib/vsphere	0.032s
=== RUN   TestValidateConfigWithNoNetPermissionParams
{"level":"info","time":"2023-03-15T16:35:41.058499359Z","caller":"config/config.go:404","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":"2023-03-15T16:35:41.088183012Z","caller":"config/config.go:415","msg":"Invalid value WRITE_ONLY for Permissions under NetPermission Config A","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config.validateConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:415\nsigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
--- PASS: TestValidateConfigWithInvalidPermissions (0.02s)
=== RUN   TestValidateConfigWithInvalidClusterId
{"level":"error","time":"2023-03-15T16:35:41.091966835Z","caller":"config/config.go:342","msg":"cluster id must not exceed 64 characters","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config.validateConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:342\nsigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
--- PASS: TestValidateConfigWithInvalidClusterId (0.00s)
=== RUN   TestSnapshotConfigWhenMaxUnspecified
{"level":"info","time":"2023-03-15T16:35:41.092276759Z","caller":"config/config.go:404","msg":"No Net Permissions given in Config. Using default permissions."}
--- PASS: TestSnapshotConfigWhenMaxUnspecified (0.00s)
=== RUN   TestSnapshotConfigWhenMaxSpecifiedAsEnv
{"level":"info","time":"2023-03-15T16:35:41.100550821Z","caller":"config/config.go:404","msg":"No Net Permissions given in Config. Using default permissions."}
--- PASS: TestSnapshotConfigWhenMaxSpecifiedAsEnv (0.01s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config	0.071s
=== RUN   TestQuerySnapshotsUtil
{"level":"error","time":"2023-03-15T16:35:42.634934376Z","caller":"config/config.go:333","msg":"no Virtual Center hosts defined","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config.validateConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:333\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config.FromEnv\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:317\nsigs.k8s.io/vsphere-csi-driver/v3/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/v3/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:74\nsync.(*Once).Do\n\t/usr/local/go/src/sync/once.go:65\nsigs.k8s.io/vsphere-csi-driver/v3/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/v3/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:1576"}
{"level":"info","time":"2023-03-15T16:35:43.022455832Z","caller":"vsphere/utils.go:189","msg":"Defaulting timeout for vCenter Client to 5 minutes"}
{"level":"info","time":"2023-03-15T16:35:43.022611071Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
{"level":"info","time":"2023-03-15T16:35:43.022653309Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
{"level":"info","time":"2023-03-15T16:35:43.022724523Z","caller":"vsphere/virtualcentermanager.go:123","msg":"Successfully registered VC 127.0.0.1:42707"}
{"level":"info","time":"2023-03-15T16:35:43.022865375Z","caller":"vsphere/virtualcenter.go:283","msg":"VirtualCenter.connect() creating new client"}
{"level":"info","time":"2023-03-15T16:35:43.058308532Z","caller":"vsphere/virtualcenter.go:202","msg":"New session ID for 'user' = 3be8a91b-a976-44f2-abbb-92b3c30f2395"}
... skipping 8 lines ...
    utils_test.go:165: Snapshots: 
--- PASS: TestQuerySnapshotsUtil (0.45s)
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList/CompatibleDatastoreFound
{"level":"info","time":"2023-03-15T16:35:43.100036536Z","caller":"utils/utils.go:262","msg":"compatible datastore found, dsURL = \"/tmp/govcsim-DC0-LocalDS_0-68153018\", dsRef = Datastore:datastore-52"}
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList/FailToFindGivenDatastoreInCompatibleList
{"level":"error","time":"2023-03-15T16:35:43.122550949Z","caller":"utils/utils.go:266","msg":"failed to find datastore with URL \"/tmp/govcsim-DC0-LocalDS_0-68153018\" from the input datastore list, [Datastore:datastore-54 Datastore:datastore-56]","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:266\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:256\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList/FailToFindGivenDatastoreInVC
{"level":"error","time":"2023-03-15T16:35:43.134286164Z","caller":"vsphere/datacenter.go:84","msg":"couldn't find Datastore given URL \"an-invalid-datastore-url\"","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/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:84\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:245\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:256\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:43.134477832Z","caller":"utils/utils.go:247","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/v3/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:247\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:256\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:43.134588244Z","caller":"utils/utils.go:256","msg":"failed to find datastore with URL \"an-invalid-datastore-url\" in VC \"127.0.0.1\"","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:256\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:256\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
=== RUN   TestGetDatastoreRefByURLFromGivenDatastoreList/EmptyDatastoreURLFromInput
{"level":"error","time":"2023-03-15T16:35:43.154492364Z","caller":"vsphere/datacenter.go:84","msg":"couldn't find Datastore given URL \"\"","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/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:84\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:245\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:256\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:43.154589409Z","caller":"utils/utils.go:247","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/v3/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:247\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:256\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:43.15463011Z","caller":"utils/utils.go:256","msg":"failed to find datastore with URL \"\" in VC \"127.0.0.1\"","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils.GetDatastoreRefByURLFromGivenDatastoreList\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils.go:256\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils.TestGetDatastoreRefByURLFromGivenDatastoreList.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/utils/utils_test.go:256\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
--- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList (0.07s)
    --- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList/CompatibleDatastoreFound (0.01s)
    --- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList/FailToFindGivenDatastoreInCompatibleList (0.02s)
    --- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList/FailToFindGivenDatastoreInVC (0.01s)
    --- PASS: TestGetDatastoreRefByURLFromGivenDatastoreList/EmptyDatastoreURLFromInput (0.02s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/utils	0.621s
=== RUN   TestUseVslmAPIsFuncForVC67Update3l
--- PASS: TestUseVslmAPIsFuncForVC67Update3l (0.00s)
=== RUN   TestUseVslmAPIsFuncForVC67Update3a
{"level":"error","time":"2023-03-15T16:35:45.321287116Z","caller":"common/common_controller_helper.go:211","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/v3/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:211\nsigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
    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.00s)
=== 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":"2023-03-15T16:35:45.332117904Z","caller":"common/vsphereutil.go:899","msg":"volume dummy-id was not found during QuerySnapshots, ignore volume.."}
--- PASS: TestQueryVolumeSnapshotsByVolumeIDWithQuerySnapshotsCnsVolumeNotFoundFault (0.00s)
=== RUN   TestQueryVolumeSnapshotsByVolumeIDWithQuerySnapshotsUnexpectedFault
{"level":"error","time":"2023-03-15T16:35:45.332769237Z","caller":"common/vsphereutil.go:902","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:0xc000422680} for volume: dummy-id","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/common.QueryVolumeSnapshotsByVolumeID\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/vsphereutil.go:902\nsigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
--- PASS: TestQueryVolumeSnapshotsByVolumeIDWithQuerySnapshotsUnexpectedFault (0.00s)
=== RUN   TestQueryVolumeSnapshotWithQuerySnapshotsCnsSnapshotNotFoundFault
{"level":"error","time":"2023-03-15T16:35:45.333311924Z","caller":"common/vsphereutil.go:758","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/v3/pkg/csi/service/common.QueryVolumeSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/vsphereutil.go:758\nsigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
--- PASS: TestQueryVolumeSnapshotWithQuerySnapshotsCnsSnapshotNotFoundFault (0.00s)
=== RUN   TestQueryVolumeSnapshotWithQuerySnapshotsUnexpectedFault
{"level":"error","time":"2023-03-15T16:35:45.333860227Z","caller":"common/vsphereutil.go:761","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/v3/pkg/csi/service/common.QueryVolumeSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/vsphereutil.go:761\nsigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
--- PASS: TestQueryVolumeSnapshotWithQuerySnapshotsUnexpectedFault (0.00s)
=== RUN   TestQueryAllVolumeSnapshotsWithQuerySnapshotsUnexpectedFault
{"level":"error","time":"2023-03-15T16:35:45.334596325Z","caller":"common/vsphereutil.go:825","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/v3/pkg/csi/service/common.QueryAllVolumeSnapshots\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common/vsphereutil.go:825\nsigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
--- PASS: TestQueryAllVolumeSnapshotsWithQuerySnapshotsUnexpectedFault (0.00s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/common	0.063s
=== RUN   TestIsFSSEnabledInGcWithSync
{"level":"info","time":"2023-03-15T16:35:47.281990648Z","caller":"k8sorchestrator/k8sorchestrator.go:1049","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":"2023-03-15T16:35:47.282369611Z","caller":"k8sorchestrator/k8sorchestrator.go:1049","msg":"volume-extend feature state set to false in internal-feature-states.csi.vsphere.vmware.com ConfigMap"}
{"level":"info","time":"2023-03-15T16:35:47.282454778Z","caller":"k8sorchestrator/k8sorchestrator.go:1070","msg":"volume-health feature state set to false in csi-feature-states ConfigMap"}
--- PASS: TestIsFSSEnabledInGcWithoutSync (0.00s)
=== RUN   TestIsFSSEnabledInGcWrongValues
{"level":"error","time":"2023-03-15T16:35:47.282605399Z","caller":"k8sorchestrator/k8sorchestrator.go:1043","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/v3/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:1043\nsigs.k8s.io/vsphere-csi-driver/v3/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:149\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
--- PASS: TestIsFSSEnabledInGcWrongValues (0.00s)
=== RUN   TestIsFSSEnabledInSV
{"level":"error","time":"2023-03-15T16:35:47.286689719Z","caller":"k8sorchestrator/k8sorchestrator.go:1026","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/v3/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:1026\nsigs.k8s.io/vsphere-csi-driver/v3/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:186\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
--- PASS: TestIsFSSEnabledInSV (0.00s)
=== RUN   TestIsFSSEnabledInVanilla
{"level":"error","time":"2023-03-15T16:35:47.288058706Z","caller":"k8sorchestrator/k8sorchestrator.go:1009","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/v3/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:1009\nsigs.k8s.io/vsphere-csi-driver/v3/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:225\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
--- PASS: TestIsFSSEnabledInVanilla (0.00s)
=== RUN   TestIsFSSEnabledWithWrongClusterFlavor
--- PASS: TestIsFSSEnabledWithWrongClusterFlavor (0.00s)
=== RUN   TestGetNodesForVolumes
--- PASS: TestGetNodesForVolumes (0.00s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/common/commonco/k8sorchestrator	0.137s
=== RUN   TestLogNewError
{"level":"error","time":"2023-03-15T16:35:47.202468682Z","caller":"logger/logger_test.go:27","msg":"Error Test","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
--- PASS: TestLogNewError (0.00s)
=== RUN   TestLogNewErrorf
{"level":"error","time":"2023-03-15T16:35:47.202862678Z","caller":"logger/logger_test.go:35","msg":"Error Test","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
--- PASS: TestLogNewErrorf (0.00s)
=== RUN   TestLogNewErrorCode
{"level":"error","time":"2023-03-15T16:35:47.203102374Z","caller":"logger/logger_test.go:43","msg":"Error Test","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
--- PASS: TestLogNewErrorCode (0.00s)
=== RUN   TestLogNewErrorCodef
{"level":"error","time":"2023-03-15T16:35:47.203285491Z","caller":"logger/logger_test.go:51","msg":"Error Test","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
--- PASS: TestLogNewErrorCodef (0.00s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/logger	0.052s
=== RUN   TestUnescape
=== RUN   TestUnescape/0
=== PAUSE TestUnescape/0
... skipping 4 lines ...
=== RUN   TestUnescape/3
=== PAUSE TestUnescape/3
=== CONT  TestUnescape/0
=== CONT  TestUnescape/2
=== CONT  TestUnescape/1
=== CONT  TestUnescape/3
{"level":"info","time":"2023-03-15T16:35:49.079160936Z","caller":"osutils/linux_os_utils.go:1091","msg":"Error parsing mount \"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/foo\\\\04\": invalid syntax"}
{"level":"info","time":"2023-03-15T16:35:49.079197776Z","caller":"osutils/linux_os_utils.go:1091","msg":"Error parsing mount \"/var/lib/kubelet/plugins/kubernetes.io/csi/pv/foo\\\\0bc\": invalid syntax"}
--- PASS: TestUnescape (0.00s)
    --- PASS: TestUnescape/2 (0.00s)
    --- PASS: TestUnescape/3 (0.00s)
    --- PASS: TestUnescape/1 (0.00s)
    --- PASS: TestUnescape/0 (0.01s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/osutils	0.081s
=== RUN   TestCreateVolumeWithStoragePolicy
{"level":"error","time":"2023-03-15T16:35:54.937904317Z","caller":"config/config.go:333","msg":"no Virtual Center hosts defined","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config.validateConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:333\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config.FromEnv\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:317\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.configFromEnvOrSim\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:166\nsigs.k8s.io/vsphere-csi-driver/v3/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:309\nsync.(*Once).doSlow\n\t/usr/local/go/src/sync/once.go:74\nsync.(*Once).Do\n\t/usr/local/go/src/sync/once.go:65\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.getControllerTest\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:306\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestCreateVolumeWithStoragePolicy\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:390\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"info","time":"2023-03-15T16:35:55.31204279Z","caller":"vsphere/utils.go:189","msg":"Defaulting timeout for vCenter Client to 5 minutes"}
{"level":"info","time":"2023-03-15T16:35:55.312216498Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
{"level":"info","time":"2023-03-15T16:35:55.312257629Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
{"level":"info","time":"2023-03-15T16:35:55.312297874Z","caller":"vsphere/virtualcentermanager.go:123","msg":"Successfully registered VC 127.0.0.1:46525"}
{"level":"info","time":"2023-03-15T16:35:55.312422544Z","caller":"vsphere/virtualcenter.go:283","msg":"VirtualCenter.connect() creating new client"}
{"level":"info","time":"2023-03-15T16:35:55.327276903Z","caller":"vsphere/virtualcenter.go:202","msg":"New session ID for 'user' = 32f8eccb-51ff-4e1d-9379-5ceb6c9c69a5"}
... skipping 81 lines ...
--- PASS: TestExtendVolume (0.07s)
=== RUN   TestMigratedExtendVolume
    controller_test.go:697: ControllerExpandVolume will be called with req +{[vsanDatastore] 08281a5f-a21d-1eff-62d6-02009d0f19a1/004dbb1694f14e3598abef852b113e3b.vmdk required_bytes:1024  map[] <nil> {} [] 0}
{"level":"info","time":"2023-03-15T16:35:55.519097612Z","caller":"vanilla/controller.go:2319","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":"9463a162-db01-4c79-bd1a-8755e1701bb2"}
{"level":"info","time":"2023-03-15T16:35:55.519122909Z","caller":"migration/migration.go:126","msg":"Initializing volume migration service...","TraceId":"9463a162-db01-4c79-bd1a-8755e1701bb2"}
{"level":"info","time":"2023-03-15T16:35:55.520625917Z","caller":"kubernetes/kubernetes.go:86","msg":"k8s client using in-cluster config","TraceId":"9463a162-db01-4c79-bd1a-8755e1701bb2"}
{"level":"error","time":"2023-03-15T16:35:55.520728658Z","caller":"kubernetes/kubernetes.go:89","msg":"InClusterConfig failed open /var/run/secrets/kubernetes.io/serviceaccount/token: no such file or directory","TraceId":"9463a162-db01-4c79-bd1a-8755e1701bb2","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/kubernetes.GetKubeConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/kubernetes/kubernetes.go:89\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/kubernetes.createCustomResourceDefinition\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/kubernetes/kubernetes.go:454\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/kubernetes.CreateCustomResourceDefinitionFromManifest\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/kubernetes/kubernetes.go:435\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/apis/migration.GetVolumeMigrationService\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/apis/migration/migration.go:129\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.initVolumeMigrationService\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2711\nsigs.k8s.io/vsphere-csi-driver/v3/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:2329\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).ControllerExpandVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2417\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestMigratedExtendVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:698\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:55.520775926Z","caller":"kubernetes/kubernetes.go:456","msg":"failed to get Kubernetes config. Err: open /var/run/secrets/kubernetes.io/serviceaccount/token: no such file or directory","TraceId":"9463a162-db01-4c79-bd1a-8755e1701bb2","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/kubernetes.createCustomResourceDefinition\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/kubernetes/kubernetes.go:456\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/kubernetes.CreateCustomResourceDefinitionFromManifest\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/kubernetes/kubernetes.go:435\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/apis/migration.GetVolumeMigrationService\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/apis/migration/migration.go:129\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.initVolumeMigrationService\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2711\nsigs.k8s.io/vsphere-csi-driver/v3/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:2329\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).ControllerExpandVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2417\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestMigratedExtendVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:698\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:55.520807409Z","caller":"migration/migration.go:133","msg":"failed to create volume migration CRD. Error: open /var/run/secrets/kubernetes.io/serviceaccount/token: no such file or directory","TraceId":"9463a162-db01-4c79-bd1a-8755e1701bb2","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/apis/migration.GetVolumeMigrationService\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/apis/migration/migration.go:133\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.initVolumeMigrationService\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2711\nsigs.k8s.io/vsphere-csi-driver/v3/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:2329\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).ControllerExpandVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2417\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestMigratedExtendVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:698\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:55.520843451Z","caller":"vanilla/controller.go:2715","msg":"failed to get migration service. Err: open /var/run/secrets/kubernetes.io/serviceaccount/token: no such file or directory","TraceId":"9463a162-db01-4c79-bd1a-8755e1701bb2","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.initVolumeMigrationService\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2715\nsigs.k8s.io/vsphere-csi-driver/v3/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:2329\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).ControllerExpandVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2417\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestMigratedExtendVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:698\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:55.520872336Z","caller":"vanilla/controller.go:2420","msg":"Operation failed, reporting failure status to Prometheus. Operation Type: \"expand-volume\", Volume Type: \"unknown\", Fault Type: \"csi.fault.Internal\"","TraceId":"9463a162-db01-4c79-bd1a-8755e1701bb2","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).ControllerExpandVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2420\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestMigratedExtendVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:698\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
    controller_test.go:700: Expected error received. migrated volume with VMDK path can not be expanded
--- PASS: TestMigratedExtendVolume (0.00s)
=== RUN   TestCompleteControllerFlow
{"level":"info","time":"2023-03-15T16:35:55.521191942Z","caller":"vanilla/controller.go:1805","msg":"CreateVolume: called with args {Name:test-pvc-2213f688-79b2-4074-a699-f57b271f4e4f 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":"64369c0e-4579-4ba0-8a0e-e5806da9ab7e"}
{"level":"info","time":"2023-03-15T16:35:55.531082898Z","caller":"volume/manager.go:403","msg":"CreateVolume: VolumeName: \"test-pvc-2213f688-79b2-4074-a699-f57b271f4e4f\", opId: \"\"","TraceId":"64369c0e-4579-4ba0-8a0e-e5806da9ab7e"}
{"level":"info","time":"2023-03-15T16:35:55.532035262Z","caller":"volume/util.go:330","msg":"Volume created successfully. VolumeName: \"test-pvc-2213f688-79b2-4074-a699-f57b271f4e4f\", volumeID: \"e08a887a-6d85-4e4f-9f7e-48b287a0c95c\"","TraceId":"64369c0e-4579-4ba0-8a0e-e5806da9ab7e"}
{"level":"info","time":"2023-03-15T16:35:55.532160846Z","caller":"vanilla/controller.go:1867","msg":"Volume created successfully. Volume Handle: \"e08a887a-6d85-4e4f-9f7e-48b287a0c95c\", PV Name: \"test-pvc-2213f688-79b2-4074-a699-f57b271f4e4f\"","TraceId":"64369c0e-4579-4ba0-8a0e-e5806da9ab7e"}
... skipping 38 lines ...
{"level":"info","time":"2023-03-15T16:35:55.584218808Z","caller":"utils/utils.go:114","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"40cf435f-10a5-4b02-a547-da63d396206b"}
{"level":"info","time":"2023-03-15T16:35:55.588156982Z","caller":"utils/utils.go:146","msg":"setting max iteration to 0 for total records count: 0","TraceId":"40cf435f-10a5-4b02-a547-da63d396206b"}
{"level":"info","time":"2023-03-15T16:35:55.588207461Z","caller":"utils/utils.go:166","msg":"0 more snapshots to be queried","TraceId":"40cf435f-10a5-4b02-a547-da63d396206b"}
{"level":"info","time":"2023-03-15T16:35:55.588262551Z","caller":"utils/utils.go:169","msg":"QuerySnapshots retrieved all records (0) for the SnapshotQuerySpec: {DynamicData:{} VolumeId:{DynamicData:{} Id:66db2473-dfb3-4c40-86be-f5bf9b0333b6} SnapshotId:<nil>} in 1 iterations","TraceId":"40cf435f-10a5-4b02-a547-da63d396206b"}
{"level":"info","time":"2023-03-15T16:35:55.588301098Z","caller":"utils/utils.go:202","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:66db2473-dfb3-4c40-86be-f5bf9b0333b6}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> HealthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"40cf435f-10a5-4b02-a547-da63d396206b"}
{"level":"info","time":"2023-03-15T16:35:55.589601976Z","caller":"utils/utils.go:209","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"40cf435f-10a5-4b02-a547-da63d396206b"}
{"level":"error","time":"2023-03-15T16:35:55.589801304Z","caller":"vanilla/controller.go:1968","msg":"volume: 66db2473-dfb3-4c40-86be-f5bf9b0333b6 with existing snapshots [size_bytes:1073741824 snapshot_id:\"66db2473-dfb3-4c40-86be-f5bf9b0333b6+1670b90a-7a31-4ed8-8299-11f2816d4f79\" source_volume_id:\"66db2473-dfb3-4c40-86be-f5bf9b0333b6\" creation_time:<seconds:1678898155 nanos:580283839 > ready_to_use:true ] cannot be deleted, please delete snapshots before deleting the volume","TraceId":"40cf435f-10a5-4b02-a547-da63d396206b","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/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:1968\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).DeleteVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:1998\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestDeleteVolumeWithSnapshots\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:898\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:55.589864855Z","caller":"vanilla/controller.go:2001","msg":"Operation failed, reporting failure status to Prometheus. Operation Type: \"delete-volume\", Volume Type: \"block\", Fault Type: \"csi.fault.Internal\"","TraceId":"40cf435f-10a5-4b02-a547-da63d396206b","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).DeleteVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2001\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestDeleteVolumeWithSnapshots\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:898\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
    controller_test.go:905: received error as expected when attempting to delete volume with snapshot, error: rpc error: code = FailedPrecondition desc = volume: 66db2473-dfb3-4c40-86be-f5bf9b0333b6 with existing snapshots [size_bytes:1073741824 snapshot_id:"66db2473-dfb3-4c40-86be-f5bf9b0333b6+1670b90a-7a31-4ed8-8299-11f2816d4f79" source_volume_id:"66db2473-dfb3-4c40-86be-f5bf9b0333b6" creation_time:<seconds:1678898155 nanos:580283839 > ready_to_use:true ] cannot be deleted, please delete snapshots before deleting the volume
--- PASS: TestDeleteVolumeWithSnapshots (0.02s)
=== RUN   TestCreateBlockVolumeSnapshotWithIdempotency
{"level":"info","time":"2023-03-15T16:35:55.591075269Z","caller":"vanilla/controller.go:1805","msg":"CreateVolume: called with args {Name:test-pvc-6a61b865-790c-4f66-b3d2-7d882bf02f35 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":"29972d6e-c471-4af7-865b-6b9971478782"}
{"level":"info","time":"2023-03-15T16:35:55.599539646Z","caller":"volume/manager.go:403","msg":"CreateVolume: VolumeName: \"test-pvc-6a61b865-790c-4f66-b3d2-7d882bf02f35\", opId: \"\"","TraceId":"29972d6e-c471-4af7-865b-6b9971478782"}
{"level":"info","time":"2023-03-15T16:35:55.600163686Z","caller":"volume/util.go:330","msg":"Volume created successfully. VolumeName: \"test-pvc-6a61b865-790c-4f66-b3d2-7d882bf02f35\", volumeID: \"7b1f672a-f8e9-4390-8f31-82d3c53bb801\"","TraceId":"29972d6e-c471-4af7-865b-6b9971478782"}
{"level":"info","time":"2023-03-15T16:35:55.600221198Z","caller":"vanilla/controller.go:1867","msg":"Volume created successfully. Volume Handle: \"7b1f672a-f8e9-4390-8f31-82d3c53bb801\", PV Name: \"test-pvc-6a61b865-790c-4f66-b3d2-7d882bf02f35\"","TraceId":"29972d6e-c471-4af7-865b-6b9971478782"}
... skipping 136 lines ...
{"level":"info","time":"2023-03-15T16:35:55.735233518Z","caller":"utils/utils.go:114","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"3deb18d2-e40b-4266-b270-9fc8c1f8504b"}
{"level":"info","time":"2023-03-15T16:35:55.739036078Z","caller":"utils/utils.go:146","msg":"setting max iteration to 0 for total records count: 0","TraceId":"3deb18d2-e40b-4266-b270-9fc8c1f8504b"}
{"level":"info","time":"2023-03-15T16:35:55.739083359Z","caller":"utils/utils.go:166","msg":"0 more snapshots to be queried","TraceId":"3deb18d2-e40b-4266-b270-9fc8c1f8504b"}
{"level":"info","time":"2023-03-15T16:35:55.739103965Z","caller":"utils/utils.go:169","msg":"QuerySnapshots retrieved all records (0) for the SnapshotQuerySpec: {DynamicData:{} VolumeId:{DynamicData:{} Id:b47a572e-b5ac-4e97-916c-1489f3ced642} SnapshotId:<nil>} in 1 iterations","TraceId":"3deb18d2-e40b-4266-b270-9fc8c1f8504b"}
{"level":"info","time":"2023-03-15T16:35:55.739129235Z","caller":"utils/utils.go:202","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:b47a572e-b5ac-4e97-916c-1489f3ced642}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> HealthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"3deb18d2-e40b-4266-b270-9fc8c1f8504b"}
{"level":"info","time":"2023-03-15T16:35:55.74048111Z","caller":"utils/utils.go:209","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"3deb18d2-e40b-4266-b270-9fc8c1f8504b"}
{"level":"error","time":"2023-03-15T16:35:55.740531429Z","caller":"vanilla/controller.go:2868","msg":"the number of snapshots on the source volume b47a572e-b5ac-4e97-916c-1489f3ced642 reaches the configured maximum (3)","TraceId":"3deb18d2-e40b-4266-b270-9fc8c1f8504b","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/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:2868\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).CreateSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2902\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestCreateBlockVolumeSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:1212\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:55.74058496Z","caller":"vanilla/controller.go:2904","msg":"Operation failed, reporting failure status to Prometheus. Operation Type: \"create-snapshot\", Volume Type: \"block\", Fault Type: \"NotComputed\"","TraceId":"3deb18d2-e40b-4266-b270-9fc8c1f8504b","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).CreateSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2904\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestCreateBlockVolumeSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:1212\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
    controller_test.go:1219: 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 b47a572e-b5ac-4e97-916c-1489f3ced642 reaches the configured maximum (3).
{"level":"info","time":"2023-03-15T16:35:55.74117301Z","caller":"vanilla/controller.go:2927","msg":"DeleteSnapshot: called with args {SnapshotId:b47a572e-b5ac-4e97-916c-1489f3ced642+0c41c85e-9805-4bf3-9c21-b2ba42901d12 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"4081f34b-04c1-40b4-8ce3-787dbdbbfa3f"}
{"level":"info","time":"2023-03-15T16:35:55.742021912Z","caller":"volume/util.go:430","msg":"Calling CnsClient.DeleteSnapshots: VolumeID [\"b47a572e-b5ac-4e97-916c-1489f3ced642\"] SnapshotID [\"0c41c85e-9805-4bf3-9c21-b2ba42901d12\"] cnsSnapshotDeleteSpecList [types.CnsSnapshotDeleteSpec{DynamicData:types.DynamicData{}, VolumeId:types.CnsVolumeId{DynamicData:types.DynamicData{}, Id:\"b47a572e-b5ac-4e97-916c-1489f3ced642\"}, SnapshotId:types.CnsSnapshotId{DynamicData:types.DynamicData{}, Id:\"0c41c85e-9805-4bf3-9c21-b2ba42901d12\"}}]","TraceId":"4081f34b-04c1-40b4-8ce3-787dbdbbfa3f"}
{"level":"info","time":"2023-03-15T16:35:55.744641085Z","caller":"volume/manager.go:2484","msg":"DeleteSnapshot: VolumeID: \"b47a572e-b5ac-4e97-916c-1489f3ced642\", SnapshotID: \"0c41c85e-9805-4bf3-9c21-b2ba42901d12\", opId: \"\"","TraceId":"4081f34b-04c1-40b4-8ce3-787dbdbbfa3f"}
{"level":"info","time":"2023-03-15T16:35:55.744698024Z","caller":"volume/manager.go:2540","msg":"DeleteSnapshot: Snapshot \"0c41c85e-9805-4bf3-9c21-b2ba42901d12\" on volume \"b47a572e-b5ac-4e97-916c-1489f3ced642\" is deleted successfully. opId: \"\"","TraceId":"4081f34b-04c1-40b4-8ce3-787dbdbbfa3f"}
{"level":"info","time":"2023-03-15T16:35:55.744741147Z","caller":"vanilla/controller.go:2966","msg":"DeleteSnapshot: successfully deleted snapshot \"b47a572e-b5ac-4e97-916c-1489f3ced642+0c41c85e-9805-4bf3-9c21-b2ba42901d12\"","TraceId":"4081f34b-04c1-40b4-8ce3-787dbdbbfa3f"}
{"level":"info","time":"2023-03-15T16:35:55.744763802Z","caller":"vanilla/controller.go:2980","msg":"Snapshot \"b47a572e-b5ac-4e97-916c-1489f3ced642+0c41c85e-9805-4bf3-9c21-b2ba42901d12\" deleted successfully.","TraceId":"4081f34b-04c1-40b4-8ce3-787dbdbbfa3f"}
... skipping 55 lines ...
{"level":"info","time":"2023-03-15T16:35:55.850229046Z","caller":"volume/manager.go:403","msg":"CreateVolume: VolumeName: \"test-pvc-d71a1646-1f43-4b9e-a241-d4742f1e7d1c\", opId: \"\"","TraceId":"9f08cad2-2c94-4b00-a8ee-b88bd6bc8c2d"}
{"level":"info","time":"2023-03-15T16:35:55.850939794Z","caller":"volume/util.go:330","msg":"Volume created successfully. VolumeName: \"test-pvc-d71a1646-1f43-4b9e-a241-d4742f1e7d1c\", volumeID: \"8026b245-2680-4acf-a1f4-8ccb33b602b5\"","TraceId":"9f08cad2-2c94-4b00-a8ee-b88bd6bc8c2d"}
{"level":"info","time":"2023-03-15T16:35:55.851004424Z","caller":"vanilla/controller.go:1867","msg":"Volume created successfully. Volume Handle: \"8026b245-2680-4acf-a1f4-8ccb33b602b5\", PV Name: \"test-pvc-d71a1646-1f43-4b9e-a241-d4742f1e7d1c\"","TraceId":"9f08cad2-2c94-4b00-a8ee-b88bd6bc8c2d"}
{"level":"info","time":"2023-03-15T16:35:55.851787315Z","caller":"vanilla/controller.go:1805","msg":"CreateVolume: called with args {Name:test-pvc-40d2e85b-64d7-4a89-90d6-e6fd6b83dfdf CapacityRange:required_bytes:2147483648  VolumeCapabilities:[access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[] Secrets:map[] VolumeContentSource:snapshot:<snapshot_id:\"9a2875e7-1e41-49bf-b793-9b74bd4d9665+df454df1-7c76-4c22-95b9-87dc89ac6783\" >  AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"c9d65267-170f-40e3-98dc-e58b6057d71c"}
{"level":"info","time":"2023-03-15T16:35:55.851857874Z","caller":"utils/utils.go:202","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:9a2875e7-1e41-49bf-b793-9b74bd4d9665}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> HealthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"c9d65267-170f-40e3-98dc-e58b6057d71c"}
{"level":"info","time":"2023-03-15T16:35:55.853128152Z","caller":"utils/utils.go:209","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"c9d65267-170f-40e3-98dc-e58b6057d71c"}
{"level":"error","time":"2023-03-15T16:35:55.853177598Z","caller":"vanilla/controller.go:594","msg":"size mismatches, requested volume size 2147483648 and source snapshot size 1073741824.Volume resizing while restoring from snapshot is currently unsupported.","TraceId":"c9d65267-170f-40e3-98dc-e58b6057d71c","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).createBlockVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:594\nsigs.k8s.io/vsphere-csi-driver/v3/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:1855\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).CreateVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:1858\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestCreateVolumeFromSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:1420\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:55.853235064Z","caller":"vanilla/controller.go:1861","msg":"Operation failed, reporting failure status to Prometheus. Operation Type: \"create-volume\", Volume Type: \"block\", Fault Type: \"csi.fault.InvalidArgument\"","TraceId":"c9d65267-170f-40e3-98dc-e58b6057d71c","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).CreateVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:1861\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestCreateVolumeFromSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:1420\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
    controller_test.go:1427: 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.Volume resizing while restoring from snapshot is currently unsupported.
{"level":"info","time":"2023-03-15T16:35:55.853454677Z","caller":"vanilla/controller.go:1885","msg":"DeleteVolume: called with args: {VolumeId:8026b245-2680-4acf-a1f4-8ccb33b602b5 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"bc4a465f-78d6-4aa4-a3a5-20db344c10d6"}
{"level":"info","time":"2023-03-15T16:35:55.854613406Z","caller":"common/vsphereutil.go:1087","msg":"volume: 8026b245-2680-4acf-a1f4-8ccb33b602b5 is of type: BLOCK","TraceId":"bc4a465f-78d6-4aa4-a3a5-20db344c10d6"}
{"level":"info","time":"2023-03-15T16:35:55.854667981Z","caller":"utils/utils.go:89","msg":"Invoking QuerySnapshots with spec: {DynamicData:{} VolumeId:{DynamicData:{} Id:8026b245-2680-4acf-a1f4-8ccb33b602b5} SnapshotId:<nil>}","TraceId":"bc4a465f-78d6-4aa4-a3a5-20db344c10d6"}
{"level":"info","time":"2023-03-15T16:35:55.854689146Z","caller":"utils/utils.go:114","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"bc4a465f-78d6-4aa4-a3a5-20db344c10d6"}
{"level":"info","time":"2023-03-15T16:35:55.85762672Z","caller":"utils/utils.go:127","msg":"QuerySnapshots retrieved no results for the spec: {DynamicData:{} VolumeId:{DynamicData:{} Id:8026b245-2680-4acf-a1f4-8ccb33b602b5} SnapshotId:<nil>}","TraceId":"bc4a465f-78d6-4aa4-a3a5-20db344c10d6"}
{"level":"info","time":"2023-03-15T16:35:55.857708077Z","caller":"utils/utils.go:146","msg":"setting max iteration to 0 for total records count: 0","TraceId":"bc4a465f-78d6-4aa4-a3a5-20db344c10d6"}
... skipping 468 lines ...
{"level":"info","time":"2023-03-15T16:35:56.202132777Z","caller":"utils/utils.go:114","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"4bd1a6a3-fbf2-485a-9ef8-f1ced992b9d2"}
{"level":"info","time":"2023-03-15T16:35:56.20619583Z","caller":"utils/utils.go:146","msg":"setting max iteration to 0 for total records count: 0","TraceId":"4bd1a6a3-fbf2-485a-9ef8-f1ced992b9d2"}
{"level":"info","time":"2023-03-15T16:35:56.206244354Z","caller":"utils/utils.go:166","msg":"0 more snapshots to be queried","TraceId":"4bd1a6a3-fbf2-485a-9ef8-f1ced992b9d2"}
{"level":"info","time":"2023-03-15T16:35:56.206267164Z","caller":"utils/utils.go:169","msg":"QuerySnapshots retrieved all records (0) for the SnapshotQuerySpec: {DynamicData:{} VolumeId:{DynamicData:{} Id:4b91230c-2474-4a1e-a3b1-512ea188fd56} SnapshotId:<nil>} in 1 iterations","TraceId":"4bd1a6a3-fbf2-485a-9ef8-f1ced992b9d2"}
{"level":"info","time":"2023-03-15T16:35:56.206297635Z","caller":"utils/utils.go:202","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:4b91230c-2474-4a1e-a3b1-512ea188fd56}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> HealthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"4bd1a6a3-fbf2-485a-9ef8-f1ced992b9d2"}
{"level":"info","time":"2023-03-15T16:35:56.207659788Z","caller":"utils/utils.go:209","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"4bd1a6a3-fbf2-485a-9ef8-f1ced992b9d2"}
{"level":"error","time":"2023-03-15T16:35:56.207736549Z","caller":"vanilla/controller.go:2383","msg":"volume: 4b91230c-2474-4a1e-a3b1-512ea188fd56 with existing snapshots [size_bytes:1073741824 snapshot_id:\"4b91230c-2474-4a1e-a3b1-512ea188fd56+d1a7e2fa-585f-41e7-98f6-1c2c51b8d494\" source_volume_id:\"4b91230c-2474-4a1e-a3b1-512ea188fd56\" creation_time:<seconds:1678898156 nanos:198873926 > ready_to_use:true ] cannot be expanded. Please delete snapshots before expanding the volume","TraceId":"4bd1a6a3-fbf2-485a-9ef8-f1ced992b9d2","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/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:2383\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).ControllerExpandVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2417\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestExpandVolumeWithSnapshots\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:2004\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:56.207783868Z","caller":"vanilla/controller.go:2420","msg":"Operation failed, reporting failure status to Prometheus. Operation Type: \"expand-volume\", Volume Type: \"block\", Fault Type: \"csi.fault.InvalidArgument\"","TraceId":"4bd1a6a3-fbf2-485a-9ef8-f1ced992b9d2","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.(*controller).ControllerExpandVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller.go:2420\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla.TestExpandVolumeWithSnapshots\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla/controller_test.go:2004\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
    controller_test.go:2011: received error as expected when attempting to expand volume with snapshot, error: rpc error: code = FailedPrecondition desc = volume: 4b91230c-2474-4a1e-a3b1-512ea188fd56 with existing snapshots [size_bytes:1073741824 snapshot_id:"4b91230c-2474-4a1e-a3b1-512ea188fd56+d1a7e2fa-585f-41e7-98f6-1c2c51b8d494" source_volume_id:"4b91230c-2474-4a1e-a3b1-512ea188fd56" creation_time:<seconds:1678898156 nanos:198873926 > ready_to_use:true ] cannot be expanded. Please delete snapshots before expanding the volume
{"level":"info","time":"2023-03-15T16:35:56.207966799Z","caller":"vanilla/controller.go:2927","msg":"DeleteSnapshot: called with args {SnapshotId:4b91230c-2474-4a1e-a3b1-512ea188fd56+d1a7e2fa-585f-41e7-98f6-1c2c51b8d494 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"42ea98c6-0a9c-47bd-93b4-6a2e6884f4d4"}
{"level":"info","time":"2023-03-15T16:35:56.208702479Z","caller":"volume/util.go:430","msg":"Calling CnsClient.DeleteSnapshots: VolumeID [\"4b91230c-2474-4a1e-a3b1-512ea188fd56\"] SnapshotID [\"d1a7e2fa-585f-41e7-98f6-1c2c51b8d494\"] cnsSnapshotDeleteSpecList [types.CnsSnapshotDeleteSpec{DynamicData:types.DynamicData{}, VolumeId:types.CnsVolumeId{DynamicData:types.DynamicData{}, Id:\"4b91230c-2474-4a1e-a3b1-512ea188fd56\"}, SnapshotId:types.CnsSnapshotId{DynamicData:types.DynamicData{}, Id:\"d1a7e2fa-585f-41e7-98f6-1c2c51b8d494\"}}]","TraceId":"42ea98c6-0a9c-47bd-93b4-6a2e6884f4d4"}
{"level":"info","time":"2023-03-15T16:35:56.211454451Z","caller":"volume/manager.go:2484","msg":"DeleteSnapshot: VolumeID: \"4b91230c-2474-4a1e-a3b1-512ea188fd56\", SnapshotID: \"d1a7e2fa-585f-41e7-98f6-1c2c51b8d494\", opId: \"\"","TraceId":"42ea98c6-0a9c-47bd-93b4-6a2e6884f4d4"}
{"level":"info","time":"2023-03-15T16:35:56.211502072Z","caller":"volume/manager.go:2540","msg":"DeleteSnapshot: Snapshot \"d1a7e2fa-585f-41e7-98f6-1c2c51b8d494\" on volume \"4b91230c-2474-4a1e-a3b1-512ea188fd56\" is deleted successfully. opId: \"\"","TraceId":"42ea98c6-0a9c-47bd-93b4-6a2e6884f4d4"}
{"level":"info","time":"2023-03-15T16:35:56.211530584Z","caller":"vanilla/controller.go:2966","msg":"DeleteSnapshot: successfully deleted snapshot \"4b91230c-2474-4a1e-a3b1-512ea188fd56+d1a7e2fa-585f-41e7-98f6-1c2c51b8d494\"","TraceId":"42ea98c6-0a9c-47bd-93b4-6a2e6884f4d4"}
{"level":"info","time":"2023-03-15T16:35:56.211553955Z","caller":"vanilla/controller.go:2980","msg":"Snapshot \"4b91230c-2474-4a1e-a3b1-512ea188fd56+d1a7e2fa-585f-41e7-98f6-1c2c51b8d494\" deleted successfully.","TraceId":"42ea98c6-0a9c-47bd-93b4-6a2e6884f4d4"}
... skipping 15 lines ...
=== RUN   TestDeleteBlockVolumeSnapshotWithManagedObjectNotFound
{"level":"info","time":"2023-03-15T16:35:56.221231259Z","caller":"vanilla/controller.go:1805","msg":"CreateVolume: called with args {Name:test-pvc-a5edae31-74e3-41a9-8f54-48178e4c93f6 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":"bf1f6ff5-e89c-4a7b-a639-11d01c47225b"}
{"level":"info","time":"2023-03-15T16:35:56.234309029Z","caller":"volume/manager.go:403","msg":"CreateVolume: VolumeName: \"test-pvc-a5edae31-74e3-41a9-8f54-48178e4c93f6\", opId: \"\"","TraceId":"bf1f6ff5-e89c-4a7b-a639-11d01c47225b"}
{"level":"info","time":"2023-03-15T16:35:56.235168886Z","caller":"volume/util.go:330","msg":"Volume created successfully. VolumeName: \"test-pvc-a5edae31-74e3-41a9-8f54-48178e4c93f6\", volumeID: \"9caea420-18d9-4a0a-8cd0-fb53430f5120\"","TraceId":"bf1f6ff5-e89c-4a7b-a639-11d01c47225b"}
{"level":"info","time":"2023-03-15T16:35:56.235280959Z","caller":"vanilla/controller.go:1867","msg":"Volume created successfully. Volume Handle: \"9caea420-18d9-4a0a-8cd0-fb53430f5120\", PV Name: \"test-pvc-a5edae31-74e3-41a9-8f54-48178e4c93f6\"","TraceId":"bf1f6ff5-e89c-4a7b-a639-11d01c47225b"}
{"level":"info","time":"2023-03-15T16:35:56.23683533Z","caller":"vanilla/controller.go:2927","msg":"DeleteSnapshot: called with args {SnapshotId:9caea420-18d9-4a0a-8cd0-fb53430f5120+19efbed4-f157-43d3-99ce-cdd2ddb383c6 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"a5b576df-0bf7-442c-a879-8fb8b7342c1e"}
{"level":"info","time":"2023-03-15T16:35:56.240323428Z","caller":"volume/manager.go:2458","msg":"Snapshot \"19efbed4-f157-43d3-99ce-cdd2ddb383c6\" on volume \"9caea420-18d9-4a0a-8cd0-fb53430f5120\" might have already been deleted with the error ServerFaultCode: ManagedObjectNotFound. Calling CNS QuerySnapshots API to confirm it","TraceId":"a5b576df-0bf7-442c-a879-8fb8b7342c1e"}
{"level":"info","time":"2023-03-15T16:35:56.24457013Z","caller":"volume/util.go:510","msg":"fault in the result of query CNS for snapshot 19efbed4-f157-43d3-99ce-cdd2ddb383c6 on volume 9caea420-18d9-4a0a-8cd0-fb53430f5120: (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) \"9caea420-18d9-4a0a-8cd0-fb53430f5120\"\n },\n SnapshotId: (types.CnsSnapshotId) {\n  DynamicData: (types.DynamicData) {\n  },\n  Id: (string) (len=36) \"19efbed4-f157-43d3-99ce-cdd2ddb383c6\"\n }\n}\n","TraceId":"a5b576df-0bf7-442c-a879-8fb8b7342c1e"}
{"level":"info","time":"2023-03-15T16:35:56.244705315Z","caller":"volume/manager.go:2469","msg":"DeleteSnapshot: Snapshot \"19efbed4-f157-43d3-99ce-cdd2ddb383c6\" on volume \"9caea420-18d9-4a0a-8cd0-fb53430f5120\" is confirmed to be deleted successfully","TraceId":"a5b576df-0bf7-442c-a879-8fb8b7342c1e"}
{"level":"info","time":"2023-03-15T16:35:56.244787934Z","caller":"vanilla/controller.go:2966","msg":"DeleteSnapshot: successfully deleted snapshot \"9caea420-18d9-4a0a-8cd0-fb53430f5120+19efbed4-f157-43d3-99ce-cdd2ddb383c6\"","TraceId":"a5b576df-0bf7-442c-a879-8fb8b7342c1e"}
{"level":"info","time":"2023-03-15T16:35:56.244841144Z","caller":"vanilla/controller.go:2980","msg":"Snapshot \"9caea420-18d9-4a0a-8cd0-fb53430f5120+19efbed4-f157-43d3-99ce-cdd2ddb383c6\" deleted successfully.","TraceId":"a5b576df-0bf7-442c-a879-8fb8b7342c1e"}
{"level":"info","time":"2023-03-15T16:35:56.245038745Z","caller":"vanilla/controller.go:1885","msg":"DeleteVolume: called with args: {VolumeId:9caea420-18d9-4a0a-8cd0-fb53430f5120 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"e054a252-0acc-45ef-b726-71e360d556f6"}
{"level":"info","time":"2023-03-15T16:35:56.246703104Z","caller":"common/vsphereutil.go:1087","msg":"volume: 9caea420-18d9-4a0a-8cd0-fb53430f5120 is of type: BLOCK","TraceId":"e054a252-0acc-45ef-b726-71e360d556f6"}
... skipping 69 lines ...
{"level":"info","time":"2023-03-15T16:35:56.340578302Z","caller":"volume/manager.go:1286","msg":"DeleteVolume: Volume deleted successfully. volumeID: \"7a0851dd-f8d2-488a-bd55-756aaa9e2701\", opId: \"\"","TraceId":"f054fbb3-4ebe-46f3-b51a-02127ab29928"}
{"level":"info","time":"2023-03-15T16:35:56.340612311Z","caller":"vanilla/controller.go:2007","msg":"Volume \"7a0851dd-f8d2-488a-bd55-756aaa9e2701\" deleted successfully.","TraceId":"f054fbb3-4ebe-46f3-b51a-02127ab29928"}
--- PASS: TestCreateSnapshotWithManagedObjectNotFound (0.08s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/vanilla	1.451s
=== RUN   TestWCPCreateVolumeWithStoragePolicy
{"level":"error","time":"2023-03-15T16:35:57.337219161Z","caller":"config/config.go:333","msg":"no Virtual Center hosts defined","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config.validateConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:333\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config.FromEnv\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:317\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.configFromEnvOrSim\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:140\nsigs.k8s.io/vsphere-csi-driver/v3/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:150\nsync.(*Once).doSlow\n\t/usr/local/go/src/sync/once.go:74\nsync.(*Once).Do\n\t/usr/local/go/src/sync/once.go:65\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.getControllerTest\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:147\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.TestWCPCreateVolumeWithStoragePolicy\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:285\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"info","time":"2023-03-15T16:35:57.693442959Z","caller":"vsphere/utils.go:189","msg":"Defaulting timeout for vCenter Client to 5 minutes"}
{"level":"info","time":"2023-03-15T16:35:57.693592311Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
{"level":"info","time":"2023-03-15T16:35:57.69362625Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
{"level":"info","time":"2023-03-15T16:35:57.693681375Z","caller":"vsphere/virtualcentermanager.go:123","msg":"Successfully registered VC 127.0.0.1:44235"}
{"level":"info","time":"2023-03-15T16:35:57.693793579Z","caller":"vsphere/virtualcenter.go:283","msg":"VirtualCenter.connect() creating new client"}
{"level":"info","time":"2023-03-15T16:35:57.709372967Z","caller":"vsphere/virtualcenter.go:202","msg":"New session ID for 'user' = e5fc886a-7ede-4925-a9ca-bec98ed65008"}
... skipping 17 lines ...
{"level":"info","time":"2023-03-15T16:35:57.751781344Z","caller":"volume/manager.go:1260","msg":"DeleteVolume: volumeID: \"9e9d69fd-9227-4218-9f09-912956f39643\", opId: \"\"","TraceId":"6c399d0d-0c6e-43e8-999f-be1c1d1ca047"}
{"level":"info","time":"2023-03-15T16:35:57.751827915Z","caller":"volume/manager.go:1286","msg":"DeleteVolume: Volume deleted successfully. volumeID: \"9e9d69fd-9227-4218-9f09-912956f39643\", opId: \"\"","TraceId":"6c399d0d-0c6e-43e8-999f-be1c1d1ca047"}
{"level":"info","time":"2023-03-15T16:35:57.751856433Z","caller":"wcp/controller.go:955","msg":"Volume \"9e9d69fd-9227-4218-9f09-912956f39643\" deleted successfully.","TraceId":"6c399d0d-0c6e-43e8-999f-be1c1d1ca047"}
--- PASS: TestWCPCreateVolumeWithStoragePolicy (0.42s)
=== RUN   TestWCPCreateVolumeWithZonalLabelPresentButNoStorageTopoType
{"level":"info","time":"2023-03-15T16:35:57.758826788Z","caller":"wcp/controller.go:824","msg":"CreateVolume: called with args {Name:test-pvc-9d207662-9c53-4132-a10b-0b0b458b41d4 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":"8c54d440-90ac-4767-ba72-b9c389ad7306"}
{"level":"error","time":"2023-03-15T16:35:57.759356395Z","caller":"wcp/controller.go:457","msg":"StorageTopologyType is unset while topology label is present","TraceId":"8c54d440-90ac-4767-ba72-b9c389ad7306","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.(*controller).createBlockVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:457\nsigs.k8s.io/vsphere-csi-driver/v3/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:861\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.(*controller).CreateVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:863\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.TestWCPCreateVolumeWithZonalLabelPresentButNoStorageTopoType\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:452\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:57.759408621Z","caller":"wcp/controller.go:867","msg":"Operation failed, reporting failure status to Prometheus. Operation Type: \"create-volume\", Volume Type: \"block\", Fault Type: \"csi.fault.InvalidArgument\"","TraceId":"8c54d440-90ac-4767-ba72-b9c389ad7306","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.(*controller).CreateVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:867\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.TestWCPCreateVolumeWithZonalLabelPresentButNoStorageTopoType\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:452\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
    controller_test.go:454: expected error is thrown: rpc error: code = InvalidArgument desc = StorageTopologyType is unset while topology label is present
--- PASS: TestWCPCreateVolumeWithZonalLabelPresentButNoStorageTopoType (0.01s)
=== RUN   TestWCPCreateDeleteSnapshot
{"level":"info","time":"2023-03-15T16:35:57.767618909Z","caller":"wcp/controller.go:824","msg":"CreateVolume: called with args {Name:test-pvc-da0a828a-a2b8-4bf7-ae6d-86eeae0142d1 CapacityRange:required_bytes:1073741824  VolumeCapabilities:[access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[storagepolicyid:aa6d5a82-1c88-45da-85d3-3d74b91a5bad] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements: XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"e0fe126a-bc81-4249-9b7e-8c2ce0cdb91d"}
{"level":"info","time":"2023-03-15T16:35:57.791770459Z","caller":"volume/manager.go:403","msg":"CreateVolume: VolumeName: \"test-pvc-da0a828a-a2b8-4bf7-ae6d-86eeae0142d1\", opId: \"\"","TraceId":"e0fe126a-bc81-4249-9b7e-8c2ce0cdb91d"}
{"level":"info","time":"2023-03-15T16:35:57.792391207Z","caller":"volume/util.go:330","msg":"Volume created successfully. VolumeName: \"test-pvc-da0a828a-a2b8-4bf7-ae6d-86eeae0142d1\", volumeID: \"5c716386-91ac-4d1d-b4f1-d18be382b5ab\"","TraceId":"e0fe126a-bc81-4249-9b7e-8c2ce0cdb91d"}
{"level":"info","time":"2023-03-15T16:35:57.792448224Z","caller":"wcp/controller.go:873","msg":"Volume created successfully. Volume Handle: \"5c716386-91ac-4d1d-b4f1-d18be382b5ab\", PV Name: \"test-pvc-da0a828a-a2b8-4bf7-ae6d-86eeae0142d1\"","TraceId":"e0fe126a-bc81-4249-9b7e-8c2ce0cdb91d"}
... skipping 500 lines ...
{"level":"info","time":"2023-03-15T16:35:58.105861564Z","caller":"volume/manager.go:403","msg":"CreateVolume: VolumeName: \"test-pvc-90515fbb-519d-4622-b6a8-5e4cb7ea80c8\", opId: \"\"","TraceId":"ecb1f085-5697-4eb0-a74a-6aa4bbef7428"}
{"level":"info","time":"2023-03-15T16:35:58.106605365Z","caller":"volume/util.go:330","msg":"Volume created successfully. VolumeName: \"test-pvc-90515fbb-519d-4622-b6a8-5e4cb7ea80c8\", volumeID: \"13857b89-69b4-47ac-b4ae-51f01350cc78\"","TraceId":"ecb1f085-5697-4eb0-a74a-6aa4bbef7428"}
{"level":"info","time":"2023-03-15T16:35:58.106659055Z","caller":"wcp/controller.go:873","msg":"Volume created successfully. Volume Handle: \"13857b89-69b4-47ac-b4ae-51f01350cc78\", PV Name: \"test-pvc-90515fbb-519d-4622-b6a8-5e4cb7ea80c8\"","TraceId":"ecb1f085-5697-4eb0-a74a-6aa4bbef7428"}
{"level":"info","time":"2023-03-15T16:35:58.107659588Z","caller":"wcp/controller.go:824","msg":"CreateVolume: called with args {Name:test-pvc-e698e441-2480-4523-808d-41114110aeb2 CapacityRange:required_bytes:2147483648  VolumeCapabilities:[access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[] Secrets:map[] VolumeContentSource:snapshot:<snapshot_id:\"115be390-f5ac-487d-b2bc-ae1631ae42d8+701b9572-b1c2-4883-9a55-c6c59cea7ebd\" >  AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"470ca627-b67e-4de4-be75-619a15d888dd"}
{"level":"info","time":"2023-03-15T16:35:58.119926681Z","caller":"utils/utils.go:202","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:115be390-f5ac-487d-b2bc-ae1631ae42d8}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> HealthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"470ca627-b67e-4de4-be75-619a15d888dd"}
{"level":"info","time":"2023-03-15T16:35:58.121327728Z","caller":"utils/utils.go:209","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"470ca627-b67e-4de4-be75-619a15d888dd"}
{"level":"error","time":"2023-03-15T16:35:58.121400848Z","caller":"wcp/controller.go:582","msg":"requested volume size: 2147483648 must be the same as source snapshot size: 1073741824","TraceId":"470ca627-b67e-4de4-be75-619a15d888dd","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.(*controller).createBlockVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:582\nsigs.k8s.io/vsphere-csi-driver/v3/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:861\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.(*controller).CreateVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:863\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.TestCreateVolumeFromSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:1313\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:58.121455334Z","caller":"wcp/controller.go:867","msg":"Operation failed, reporting failure status to Prometheus. Operation Type: \"create-volume\", Volume Type: \"block\", Fault Type: \"csi.fault.InvalidArgument\"","TraceId":"470ca627-b67e-4de4-be75-619a15d888dd","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.(*controller).CreateVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:867\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.TestCreateVolumeFromSnapshot\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:1313\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
    controller_test.go:1320: received error as expected when attempting to create volume from snapshot, error: rpc error: code = InvalidArgument desc = requested volume size: 2147483648 must be the same as source snapshot size: 1073741824
{"level":"info","time":"2023-03-15T16:35:58.12165126Z","caller":"wcp/controller.go:892","msg":"DeleteVolume: called with args: {VolumeId:13857b89-69b4-47ac-b4ae-51f01350cc78 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"badf23bf-aea3-46ef-8613-ddd45edd44a1"}
{"level":"info","time":"2023-03-15T16:35:58.123166008Z","caller":"common/vsphereutil.go:1087","msg":"volume: 13857b89-69b4-47ac-b4ae-51f01350cc78 is of type: BLOCK","TraceId":"badf23bf-aea3-46ef-8613-ddd45edd44a1"}
{"level":"info","time":"2023-03-15T16:35:58.123242968Z","caller":"utils/utils.go:89","msg":"Invoking QuerySnapshots with spec: {DynamicData:{} VolumeId:{DynamicData:{} Id:13857b89-69b4-47ac-b4ae-51f01350cc78} SnapshotId:<nil>}","TraceId":"badf23bf-aea3-46ef-8613-ddd45edd44a1"}
{"level":"info","time":"2023-03-15T16:35:58.123258052Z","caller":"utils/utils.go:114","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"badf23bf-aea3-46ef-8613-ddd45edd44a1"}
{"level":"info","time":"2023-03-15T16:35:58.127475057Z","caller":"utils/utils.go:127","msg":"QuerySnapshots retrieved no results for the spec: {DynamicData:{} VolumeId:{DynamicData:{} Id:13857b89-69b4-47ac-b4ae-51f01350cc78} SnapshotId:<nil>}","TraceId":"badf23bf-aea3-46ef-8613-ddd45edd44a1"}
{"level":"info","time":"2023-03-15T16:35:58.127536198Z","caller":"utils/utils.go:146","msg":"setting max iteration to 0 for total records count: 0","TraceId":"badf23bf-aea3-46ef-8613-ddd45edd44a1"}
... skipping 55 lines ...
{"level":"info","time":"2023-03-15T16:35:58.181150841Z","caller":"utils/utils.go:114","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"2bb95d51-2744-4c48-aa35-320cd480c45f"}
{"level":"info","time":"2023-03-15T16:35:58.185529287Z","caller":"utils/utils.go:146","msg":"setting max iteration to 0 for total records count: 0","TraceId":"2bb95d51-2744-4c48-aa35-320cd480c45f"}
{"level":"info","time":"2023-03-15T16:35:58.185583079Z","caller":"utils/utils.go:166","msg":"0 more snapshots to be queried","TraceId":"2bb95d51-2744-4c48-aa35-320cd480c45f"}
{"level":"info","time":"2023-03-15T16:35:58.185602078Z","caller":"utils/utils.go:169","msg":"QuerySnapshots retrieved all records (0) for the SnapshotQuerySpec: {DynamicData:{} VolumeId:{DynamicData:{} Id:32f239f3-ccd5-4fbb-99f7-14090f28ea2c} SnapshotId:<nil>} in 1 iterations","TraceId":"2bb95d51-2744-4c48-aa35-320cd480c45f"}
{"level":"info","time":"2023-03-15T16:35:58.185632333Z","caller":"utils/utils.go:202","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:32f239f3-ccd5-4fbb-99f7-14090f28ea2c}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> HealthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"2bb95d51-2744-4c48-aa35-320cd480c45f"}
{"level":"info","time":"2023-03-15T16:35:58.187030346Z","caller":"utils/utils.go:209","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"2bb95d51-2744-4c48-aa35-320cd480c45f"}
{"level":"error","time":"2023-03-15T16:35:58.187125033Z","caller":"wcp/controller.go:931","msg":"volume: 32f239f3-ccd5-4fbb-99f7-14090f28ea2c with existing snapshots [size_bytes:1073741824 snapshot_id:\"32f239f3-ccd5-4fbb-99f7-14090f28ea2c+f9535400-e399-4383-9acb-7526dcdc0f66\" source_volume_id:\"32f239f3-ccd5-4fbb-99f7-14090f28ea2c\" creation_time:<seconds:1678898158 nanos:173464016 > ready_to_use:true ] cannot be deleted, please delete snapshots before deleting the volume","TraceId":"2bb95d51-2744-4c48-aa35-320cd480c45f","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.(*controller).DeleteVolume.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:931\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.(*controller).DeleteVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:945\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.TestWCPDeleteVolumeWithSnapshots\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:1394\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:58.187181157Z","caller":"wcp/controller.go:949","msg":"Operation failed, reporting failure status to Prometheus. Operation Type: \"delete-volume\", Volume Type: \"block\", Fault Type: \"csi.fault.Internal\"","TraceId":"2bb95d51-2744-4c48-aa35-320cd480c45f","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.(*controller).DeleteVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:949\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.TestWCPDeleteVolumeWithSnapshots\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:1394\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
    controller_test.go:1401: received error as expected when attempting to delete volume with snapshot, error: rpc error: code = FailedPrecondition desc = volume: 32f239f3-ccd5-4fbb-99f7-14090f28ea2c with existing snapshots [size_bytes:1073741824 snapshot_id:"32f239f3-ccd5-4fbb-99f7-14090f28ea2c+f9535400-e399-4383-9acb-7526dcdc0f66" source_volume_id:"32f239f3-ccd5-4fbb-99f7-14090f28ea2c" creation_time:<seconds:1678898158 nanos:173464016 > ready_to_use:true ] cannot be deleted, please delete snapshots before deleting the volume
{"level":"info","time":"2023-03-15T16:35:58.187387398Z","caller":"wcp/controller.go:1595","msg":"DeleteSnapshot: called with args {SnapshotId:32f239f3-ccd5-4fbb-99f7-14090f28ea2c+f9535400-e399-4383-9acb-7526dcdc0f66 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"fef29ced-442d-47bb-a975-649062b0c948"}
{"level":"info","time":"2023-03-15T16:35:58.188097426Z","caller":"volume/util.go:430","msg":"Calling CnsClient.DeleteSnapshots: VolumeID [\"32f239f3-ccd5-4fbb-99f7-14090f28ea2c\"] SnapshotID [\"f9535400-e399-4383-9acb-7526dcdc0f66\"] cnsSnapshotDeleteSpecList [types.CnsSnapshotDeleteSpec{DynamicData:types.DynamicData{}, VolumeId:types.CnsVolumeId{DynamicData:types.DynamicData{}, Id:\"32f239f3-ccd5-4fbb-99f7-14090f28ea2c\"}, SnapshotId:types.CnsSnapshotId{DynamicData:types.DynamicData{}, Id:\"f9535400-e399-4383-9acb-7526dcdc0f66\"}}]","TraceId":"fef29ced-442d-47bb-a975-649062b0c948"}
{"level":"info","time":"2023-03-15T16:35:58.190718328Z","caller":"volume/manager.go:2484","msg":"DeleteSnapshot: VolumeID: \"32f239f3-ccd5-4fbb-99f7-14090f28ea2c\", SnapshotID: \"f9535400-e399-4383-9acb-7526dcdc0f66\", opId: \"\"","TraceId":"fef29ced-442d-47bb-a975-649062b0c948"}
{"level":"info","time":"2023-03-15T16:35:58.190763816Z","caller":"volume/manager.go:2540","msg":"DeleteSnapshot: Snapshot \"f9535400-e399-4383-9acb-7526dcdc0f66\" on volume \"32f239f3-ccd5-4fbb-99f7-14090f28ea2c\" is deleted successfully. opId: \"\"","TraceId":"fef29ced-442d-47bb-a975-649062b0c948"}
{"level":"info","time":"2023-03-15T16:35:58.190787705Z","caller":"wcp/controller.go:1611","msg":"DeleteSnapshot: successfully deleted snapshot \"32f239f3-ccd5-4fbb-99f7-14090f28ea2c+f9535400-e399-4383-9acb-7526dcdc0f66\"","TraceId":"fef29ced-442d-47bb-a975-649062b0c948"}
{"level":"info","time":"2023-03-15T16:35:58.190798386Z","caller":"wcp/controller.go:1619","msg":"Snapshot \"32f239f3-ccd5-4fbb-99f7-14090f28ea2c+f9535400-e399-4383-9acb-7526dcdc0f66\" deleted successfully.","TraceId":"fef29ced-442d-47bb-a975-649062b0c948"}
... skipping 41 lines ...
{"level":"info","time":"2023-03-15T16:35:58.237225797Z","caller":"utils/utils.go:114","msg":"invoking QuerySnapshots in iteration: 1 with offset: 0 and limit: 128, current total results: 0","TraceId":"9778fc85-e9b7-432c-ba20-4d1bf5d68872"}
{"level":"info","time":"2023-03-15T16:35:58.239778576Z","caller":"utils/utils.go:146","msg":"setting max iteration to 0 for total records count: 0","TraceId":"9778fc85-e9b7-432c-ba20-4d1bf5d68872"}
{"level":"info","time":"2023-03-15T16:35:58.239812651Z","caller":"utils/utils.go:166","msg":"0 more snapshots to be queried","TraceId":"9778fc85-e9b7-432c-ba20-4d1bf5d68872"}
{"level":"info","time":"2023-03-15T16:35:58.23982723Z","caller":"utils/utils.go:169","msg":"QuerySnapshots retrieved all records (0) for the SnapshotQuerySpec: {DynamicData:{} VolumeId:{DynamicData:{} Id:c86026fe-57f2-4fa8-9832-dcf1f387279d} SnapshotId:<nil>} in 1 iterations","TraceId":"9778fc85-e9b7-432c-ba20-4d1bf5d68872"}
{"level":"info","time":"2023-03-15T16:35:58.239844662Z","caller":"utils/utils.go:202","msg":"Invoking QueryAllVolumeUtil with Filter: {DynamicData:{} VolumeIds:[{DynamicData:{} Id:c86026fe-57f2-4fa8-9832-dcf1f387279d}] Names:[] ContainerClusterIds:[] StoragePolicyId: Datastores:[] Labels:[] ComplianceStatus: DatastoreAccessibilityStatus: Cursor:<nil> HealthStatus:}, Selection: {DynamicData:{} Names:[BACKING_OBJECT_DETAILS VOLUME_TYPE DATASTORE_URL]}","TraceId":"9778fc85-e9b7-432c-ba20-4d1bf5d68872"}
{"level":"info","time":"2023-03-15T16:35:58.240801707Z","caller":"utils/utils.go:209","msg":"Number of results from QueryAllVolumeUtil: 1","TraceId":"9778fc85-e9b7-432c-ba20-4d1bf5d68872"}
{"level":"error","time":"2023-03-15T16:35:58.24087203Z","caller":"wcp/controller.go:1719","msg":"volume: c86026fe-57f2-4fa8-9832-dcf1f387279d with existing snapshots [size_bytes:1073741824 snapshot_id:\"c86026fe-57f2-4fa8-9832-dcf1f387279d+203a1a35-c2ff-43eb-a813-c091908d9e2e\" source_volume_id:\"c86026fe-57f2-4fa8-9832-dcf1f387279d\" creation_time:<seconds:1678898158 nanos:233461669 > ready_to_use:true ] cannot be expanded, please delete snapshots before deleting the volume","TraceId":"9778fc85-e9b7-432c-ba20-4d1bf5d68872","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.(*controller).ControllerExpandVolume.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:1719\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.(*controller).ControllerExpandVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:1761\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.TestWCPExpandVolumeWithSnapshots\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:1505\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
{"level":"error","time":"2023-03-15T16:35:58.240913849Z","caller":"wcp/controller.go:1765","msg":"Operation failed, reporting failure status to Prometheus. Operation Type: \"expand-volume\", Volume Type: \"block\", Fault Type: \"csi.fault.Internal\"","TraceId":"9778fc85-e9b7-432c-ba20-4d1bf5d68872","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.(*controller).ControllerExpandVolume\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller.go:1765\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp.TestWCPExpandVolumeWithSnapshots\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/wcp/controller_test.go:1505\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
    controller_test.go:1512: received error as expected when attempting to expand volume with snapshot, error: rpc error: code = FailedPrecondition desc = volume: c86026fe-57f2-4fa8-9832-dcf1f387279d with existing snapshots [size_bytes:1073741824 snapshot_id:"c86026fe-57f2-4fa8-9832-dcf1f387279d+203a1a35-c2ff-43eb-a813-c091908d9e2e" source_volume_id:"c86026fe-57f2-4fa8-9832-dcf1f387279d" creation_time:<seconds:1678898158 nanos:233461669 > ready_to_use:true ] cannot be expanded, please delete snapshots before deleting the volume
{"level":"info","time":"2023-03-15T16:35:58.241117084Z","caller":"wcp/controller.go:1595","msg":"DeleteSnapshot: called with args {SnapshotId:c86026fe-57f2-4fa8-9832-dcf1f387279d+203a1a35-c2ff-43eb-a813-c091908d9e2e Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"ab07b6fc-123b-4169-afac-ef49a62d7ed8"}
{"level":"info","time":"2023-03-15T16:35:58.241817559Z","caller":"volume/util.go:430","msg":"Calling CnsClient.DeleteSnapshots: VolumeID [\"c86026fe-57f2-4fa8-9832-dcf1f387279d\"] SnapshotID [\"203a1a35-c2ff-43eb-a813-c091908d9e2e\"] cnsSnapshotDeleteSpecList [types.CnsSnapshotDeleteSpec{DynamicData:types.DynamicData{}, VolumeId:types.CnsVolumeId{DynamicData:types.DynamicData{}, Id:\"c86026fe-57f2-4fa8-9832-dcf1f387279d\"}, SnapshotId:types.CnsSnapshotId{DynamicData:types.DynamicData{}, Id:\"203a1a35-c2ff-43eb-a813-c091908d9e2e\"}}]","TraceId":"ab07b6fc-123b-4169-afac-ef49a62d7ed8"}
{"level":"info","time":"2023-03-15T16:35:58.243880938Z","caller":"volume/manager.go:2484","msg":"DeleteSnapshot: VolumeID: \"c86026fe-57f2-4fa8-9832-dcf1f387279d\", SnapshotID: \"203a1a35-c2ff-43eb-a813-c091908d9e2e\", opId: \"\"","TraceId":"ab07b6fc-123b-4169-afac-ef49a62d7ed8"}
{"level":"info","time":"2023-03-15T16:35:58.243936916Z","caller":"volume/manager.go:2540","msg":"DeleteSnapshot: Snapshot \"203a1a35-c2ff-43eb-a813-c091908d9e2e\" on volume \"c86026fe-57f2-4fa8-9832-dcf1f387279d\" is deleted successfully. opId: \"\"","TraceId":"ab07b6fc-123b-4169-afac-ef49a62d7ed8"}
{"level":"info","time":"2023-03-15T16:35:58.244000545Z","caller":"wcp/controller.go:1611","msg":"DeleteSnapshot: successfully deleted snapshot \"c86026fe-57f2-4fa8-9832-dcf1f387279d+203a1a35-c2ff-43eb-a813-c091908d9e2e\"","TraceId":"ab07b6fc-123b-4169-afac-ef49a62d7ed8"}
{"level":"info","time":"2023-03-15T16:35:58.244020475Z","caller":"wcp/controller.go:1619","msg":"Snapshot \"c86026fe-57f2-4fa8-9832-dcf1f387279d+203a1a35-c2ff-43eb-a813-c091908d9e2e\" deleted successfully.","TraceId":"ab07b6fc-123b-4169-afac-ef49a62d7ed8"}
... skipping 12 lines ...
{"level":"info","time":"2023-03-15T16:35:58.2527007Z","caller":"volume/manager.go:1286","msg":"DeleteVolume: Volume deleted successfully. volumeID: \"c86026fe-57f2-4fa8-9832-dcf1f387279d\", opId: \"\"","TraceId":"dee77fdb-8e7d-414f-9351-f27222051c99"}
{"level":"info","time":"2023-03-15T16:35:58.252732439Z","caller":"wcp/controller.go:955","msg":"Volume \"c86026fe-57f2-4fa8-9832-dcf1f387279d\" deleted successfully.","TraceId":"dee77fdb-8e7d-414f-9351-f27222051c99"}
--- PASS: TestWCPExpandVolumeWithSnapshots (0.05s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v3/pkg/csi/service/wcp	0.975s
=== RUN   TestGuestClusterControllerFlow
{"level":"error","time":"2023-03-15T16:35:57.354783374Z","caller":"config/config.go:626","msg":"no Supervisor Cluster endpoint defined in Guest Cluster config","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config.validateGCConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:626\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config.FromEnvToGC\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:566\nsigs.k8s.io/vsphere-csi-driver/v3/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/v3/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:74\nsync.(*Once).Do\n\t/usr/local/go/src/sync/once.go:65\nsigs.k8s.io/vsphere-csi-driver/v3/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/v3/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:1576"}
{"level":"info","time":"2023-03-15T16:35:57.355739437Z","caller":"wcpguest/controller.go:247","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":"654a40fd-dc13-4e4b-a32a-cd730d8929a8"}
{"level":"info","time":"2023-03-15T16:35:57.355980861Z","caller":"wcpguest/controller_helper.go:290","msg":"Waiting up to 240 seconds for PersistentVolumeClaim -12345 in namespace test-namespace to have phase Bound","TraceId":"654a40fd-dc13-4e4b-a32a-cd730d8929a8"}
{"level":"info","time":"2023-03-15T16:35:58.355216974Z","caller":"wcpguest/controller_helper.go:314","msg":"PersistentVolumeClaim -12345 in namespace test-namespace is in state Bound","TraceId":"654a40fd-dc13-4e4b-a32a-cd730d8929a8"}
{"level":"info","time":"2023-03-15T16:35:58.355302011Z","caller":"wcpguest/controller.go:432","msg":"Volume created successfully. Volume Handle: \"-12345\", PV Name: \"pvc-12345\"","TraceId":"654a40fd-dc13-4e4b-a32a-cd730d8929a8"}
{"level":"info","time":"2023-03-15T16:35:58.355484319Z","caller":"wcpguest/controller.go:451","msg":"DeleteVolume: called with args: {VolumeId:-12345 Secrets:map[] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}","TraceId":"1ade6769-7c73-4175-a098-9ed1317757eb"}
{"level":"info","time":"2023-03-15T16:35:58.355543502Z","caller":"wcpguest/controller.go:496","msg":"DeleteVolume: Volume deleted successfully. VolumeID: \"-12345\"","TraceId":"1ade6769-7c73-4175-a098-9ed1317757eb"}
... 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/v3/pkg/csi/service/wcpguest	6.080s
=== RUN   TestSyncerWorkflows
    syncer_test.go:161: TestSyncerWorkflows: start
{"level":"error","time":"2023-03-15T16:36:00.867374276Z","caller":"config/config.go:333","msg":"no Virtual Center hosts defined","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config.validateConfig\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:333\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/common/config.FromEnv\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/common/config/config.go:317\nsigs.k8s.io/vsphere-csi-driver/v3/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/v3/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:1576"}
{"level":"info","time":"2023-03-15T16:36:01.254041702Z","caller":"vsphere/utils.go:189","msg":"Defaulting timeout for vCenter Client to 5 minutes"}
{"level":"info","time":"2023-03-15T16:36:01.254184927Z","caller":"vsphere/virtualcentermanager.go:74","msg":"Initializing defaultVirtualCenterManager..."}
{"level":"info","time":"2023-03-15T16:36:01.254221719Z","caller":"vsphere/virtualcentermanager.go:76","msg":"Successfully initialized defaultVirtualCenterManager"}
{"level":"info","time":"2023-03-15T16:36:01.254262439Z","caller":"vsphere/virtualcentermanager.go:123","msg":"Successfully registered VC 127.0.0.1:33851"}
{"level":"info","time":"2023-03-15T16:36:01.254409926Z","caller":"vsphere/virtualcenter.go:283","msg":"VirtualCenter.connect() creating new client"}
{"level":"info","time":"2023-03-15T16:36:01.271296329Z","caller":"vsphere/virtualcenter.go:202","msg":"New session ID for 'user' = f2527977-a79a-46b8-a551-ae01edcb6a65"}
... skipping 92 lines ...
    syncer_test.go:258: TestSyncerWorkflows: end
--- PASS: TestSyncerWorkflows (12.69s)
=== RUN   TestGetVCForTopologySegments
=== RUN   TestGetVCForTopologySegments/Higher-level_topology_label_present_in_more_than_one_VC
{"level":"info","time":"2023-03-15T16:36:13.556205764Z","caller":"syncer/metadatasyncer.go:870","msg":"Topology segment(s) map[topology.csi.vmware.com/region:[region-1] topology.csi.vmware.com/zone:[zone-2]] belong to VC: \"10.100.100.1\""}
=== RUN   TestGetVCForTopologySegments/Invalid_topology_label_given_as_input
{"level":"error","time":"2023-03-15T16:36:13.556516058Z","caller":"syncer/metadatasyncer.go:853","msg":"Topology label \"topology.csi.vmware.com/zone:zone-3\" not found in topology to VC mapping.","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/syncer.getVCForTopologySegments\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/metadatasyncer.go:853\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/syncer.TestGetVCForTopologySegments.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/syncer_test.go:1019\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
=== RUN   TestGetVCForTopologySegments/Topology_label_belongs_to_more_than_one_VC
{"level":"error","time":"2023-03-15T16:36:13.55674103Z","caller":"syncer/metadatasyncer.go:867","msg":"Topology segment(s) map[topology.csi.vmware.com/region:[region-1] topology.csi.vmware.com/zone:[zone-1]] belong to more than one VC: [10.100.100.0 10.100.100.1]","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/syncer.getVCForTopologySegments\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/metadatasyncer.go:867\nsigs.k8s.io/vsphere-csi-driver/v3/pkg/syncer.TestGetVCForTopologySegments.func1\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/syncer_test.go:1019\ntesting.tRunner\n\t/usr/local/go/src/testing/testing.go:1576"}
=== RUN   TestGetVCForTopologySegments/Leaf-level_topology_label_present_in_more_than_one_VC
{"level":"info","time":"2023-03-15T16:36:13.556965627Z","caller":"syncer/metadatasyncer.go:870","msg":"Topology segment(s) map[topology.csi.vmware.com/region:[region-2] topology.csi.vmware.com/zone:[zone-1]] belong to VC: \"10.100.100.1\""}
=== RUN   TestGetVCForTopologySegments/Topology_labels_distinct_across_VCs
{"level":"info","time":"2023-03-15T16:36:13.557175Z","caller":"syncer/metadatasyncer.go:870","msg":"Topology segment(s) map[topology.csi.vmware.com/city:[city-2] topology.csi.vmware.com/region:[region-2] topology.csi.vmware.com/zone:[zone-2]] belong to VC: \"10.100.100.1\""}
=== RUN   TestGetVCForTopologySegments/Multiple_values_for_same_topology_key
{"level":"info","time":"2023-03-15T16:36:13.557384395Z","caller":"syncer/metadatasyncer.go:870","msg":"Topology segment(s) map[topology.csi.vmware.com/region:[region-1 region-2] topology.csi.vmware.com/zone:[zone-1]] belong to VC: \"10.100.100.0\""}
... skipping 89 lines ...
{"level":"info","time":"2023-03-15T16:36:00.882048746Z","caller":"admissionhandler/validatestorageclass.go:76","msg":"Validating StorageClass: \"sc\""}
{"level":"info","time":"2023-03-15T16:36:00.882083645Z","caller":"admissionhandler/validatestorageclass.go:90","msg":"Validation of StorageClass: \"sc\" Passed"}
    validatestorageclass_test.go:55: TestValidateStorageClassForAllowVolumeExpansion Passed
--- PASS: TestValidateStorageClassForAllowVolumeExpansion (0.00s)
=== RUN   TestValidateStorageClassForMigrationParameter
{"level":"info","time":"2023-03-15T16:36:00.882213057Z","caller":"admissionhandler/validatestorageclass.go:76","msg":"Validating StorageClass: \"sc\""}
{"level":"error","time":"2023-03-15T16:36:00.882229993Z","caller":"admissionhandler/validatestorageclass.go:92","msg":"validation of StorageClass: \"sc\" Failed","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/syncer/admissionhandler.validateStorageClass\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/admissionhandler/validatestorageclass.go:92\nsigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
{"level":"info","time":"2023-03-15T16:36:00.882301194Z","caller":"admissionhandler/validatestorageclass.go:76","msg":"Validating StorageClass: \"sc\""}
{"level":"error","time":"2023-03-15T16:36:00.882315112Z","caller":"admissionhandler/validatestorageclass.go:92","msg":"validation of StorageClass: \"sc\" Failed","stacktrace":"sigs.k8s.io/vsphere-csi-driver/v3/pkg/syncer/admissionhandler.validateStorageClass\n\t/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver/pkg/syncer/admissionhandler/validatestorageclass.go:92\nsigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
    validatestorageclass_test.go:98: TestValidateStorageClassForMigrationParameter Passed
--- PASS: TestValidateStorageClassForMigrationParameter (0.00s)
=== RUN   TestValidateStorageClassForValidStorageClass
{"level":"info","time":"2023-03-15T16:36:00.882436489Z","caller":"admissionhandler/validatestorageclass.go:76","msg":"Validating StorageClass: \"sc\""}
{"level":"info","time":"2023-03-15T16:36:00.88245219Z","caller":"admissionhandler/validatestorageclass.go:90","msg":"Validation of StorageClass: \"sc\" Passed"}
    validatestorageclass_test.go:120: TestValidateStorageClassForValidStorageClass Passed
... skipping 6 lines ...
{"level":"info","time":"2023-03-15T16:36:00.867105765Z","caller":"csinodetopology/csinodetopology_controller.go:403","msg":"Successfully updated topology labels for worker \"test-csinodetopology-name\" in GUEST_CLUSTER"}
=== RUN   TestCSINodeTopologyControllerForTKGSHA/TestWithVmStatusZoneEmpty
{"level":"info","time":"2023-03-15T16:36:00.868528845Z","caller":"csinodetopology/csinodetopology_controller.go:349","msg":"Start reconciling the CSINodeTopology request test-csinodetopology-name in GUEST_CLUSTER"}
{"level":"info","time":"2023-03-15T16:36:00.868903636Z","caller":"csinodetopology/csinodetopology_controller.go:403","msg":"Successfully updated topology labels for worker \"test-csinodetopology-name\" in GUEST_CLUSTER"}
=== RUN   TestCSINodeTopologyControllerForTKGSHA/TestWithGetVmFailure
{"level":"info","time":"2023-03-15T16:36:00.869131025Z","caller":"csinodetopology/csinodetopology_controller.go:349","msg":"Start reconciling the CSINodeTopology request test-csinodetopology-name in GUEST_CLUSTER"}
{"level":"error","time":"2023-03-15T16:36:00.869288867Z","caller":"csinodetopology/csinodetopology_controller.go:420","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/v3/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:420\nsigs.k8s.io/vsphere-csi-driver/v3/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:380\nsigs.k8s.io/vsphere-csi-driver/v3/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:226\nsigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
{"level":"error","time":"2023-03-15T16:36:00.869350541Z","caller":"csinodetopology/csinodetopology_controller.go:384","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/v3/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:384\nsigs.k8s.io/vsphere-csi-driver/v3/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:226\nsigs.k8s.io/vsphere-csi-driver/v3/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:1576"}
--- PASS: TestCSINodeTopologyControllerForTKGSHA (0.01s)
    --- PASS: TestCSINodeTopologyControllerForTKGSHA/TestWithVmStatusZonePopulated (0.00s)
    --- PASS: TestCSINodeTopologyControllerForTKGSHA/TestWithVmStatusZoneEmpty (0.00s)
    --- PASS: TestCSINodeTopologyControllerForTKGSHA/TestWithGetVmFailure (0.00s)
PASS
ok  	sigs.k8s.io/vsphere-csi-driver/v3/pkg/syncer/cnsoperator/controller/csinodetopology	0.052s
FAIL
make[1]: *** [Makefile:282: unit-test] Error 1
make[1]: Leaving directory '/home/prow/go/src/sigs.k8s.io/vsphere-csi-driver'
make: *** [Makefile:197: deploy] Error 2
Result	FAILURE
Tests	0 failed / 0 succeeded
Started	2023-03-15 16:32
Elapsed	13m17s
Revision	c59a98e68fb407c5dda6158be515abf66b4330a0
post-vsphere-csi-driver-deploy #1636042654263283712

No Test Failures!

Error lines from build-log.txt
