vsphere-csi-driver: after update to 2.2.0 volume provisioning fails due to vsphere user permissions (but user is Admin)

/kind bug

What happened: after updating csi to 2.2.0 : when creating a rwo volumeclaim vsphere-csi-controller throws

failed to create volume. Error: ServerFaultCode: createSpecs.datastores is empty

when creating a rwx volumeclaim vsphere-csi-controller throws

Internal desc = no datastores found to create file volume

the logs in DEVELOPMENT mode also show

2021-04-20T16:08:34.883Z	INFO	vanilla/controller.go:624	CreateVolume: called with args {Name:pvc-e801c81b-b1be-4bde-a37e-849189bb39ba CapacityRange:required_bytes:3221225472  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:MULTI_NODE_MULTI_WRITER > ] Parameters:map[StoragePolicyName:vSAN Default Storage Policy] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}	{"TraceId": "23162627-4958-42e5-ac9f-324e87044989"}
2021-04-20T16:08:34.884Z	DEBUG	vsphere/utils.go:364	Checking if vCenter version is of vsan 67u3 release	{"TraceId": "23162627-4958-42e5-ac9f-324e87044989"}
2021-04-20T16:08:34.884Z	DEBUG	vsphere/utils.go:370	vCenter version is :"vSAN 7.0U1"	{"TraceId": "23162627-4958-42e5-ac9f-324e87044989"}
2021-04-20T16:08:34.884Z	DEBUG	vanilla/controller.go:574	Filtered Datastores: map[]	{"TraceId": "23162627-4958-42e5-ac9f-324e87044989"}
2021-04-20T16:08:34.884Z	ERROR	vanilla/controller.go:581	no datastores found to create file volume	{"TraceId": "23162627-4958-42e5-ac9f-324e87044989"}
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla.(*controller).createFileVolume
	/build/pkg/csi/service/vanilla/controller.go:581
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla.(*controller).CreateVolume.func1
	/build/pkg/csi/service/vanilla/controller.go:641
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla.(*controller).CreateVolume
	/build/pkg/csi/service/vanilla/controller.go:646
github.com/container-storage-interface/spec/lib/go/csi._Controller_CreateVolume_Handler.func1
	/go/pkg/mod/github.com/container-storage-interface/spec@v1.2.0/lib/go/csi/csi.pb.go:5146
github.com/rexray/gocsi/middleware/serialvolume.(*interceptor).createVolume
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/serialvolume/serial_volume_locker.go:162
github.com/rexray/gocsi/middleware/serialvolume.(*interceptor).handle
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/serialvolume/serial_volume_locker.go:90
github.com/rexray/gocsi/utils.ChainUnaryServer.func2.1.1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:99
github.com/rexray/gocsi/middleware/specvalidator.(*interceptor).handleServer.func1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/specvalidator/spec_validator.go:178
github.com/rexray/gocsi/middleware/specvalidator.(*interceptor).handle
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/specvalidator/spec_validator.go:218
github.com/rexray/gocsi/middleware/specvalidator.(*interceptor).handleServer
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/specvalidator/spec_validator.go:177
github.com/rexray/gocsi/utils.ChainUnaryServer.func2.1.1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:99
github.com/rexray/gocsi.(*StoragePlugin).injectContext
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware.go:231
github.com/rexray/gocsi/utils.ChainUnaryServer.func2.1.1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:99
github.com/rexray/gocsi/utils.ChainUnaryServer.func2
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:106
github.com/container-storage-interface/spec/lib/go/csi._Controller_CreateVolume_Handler
	/go/pkg/mod/github.com/container-storage-interface/spec@v1.2.0/lib/go/csi/csi.pb.go:5148
google.golang.org/grpc.(*Server).processUnaryRPC
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:1024
google.golang.org/grpc.(*Server).handleStream
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:1313
google.golang.org/grpc.(*Server).serveStreams.func1.1
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:722
2021-04-20T16:08:35.939Z	INFO	vanilla/controller.go:624	CreateVolume: called with args {Name:pvc-fc7db65e-0227-475c-8554-c796c8eaea32 CapacityRange:required_bytes:2147483648  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[StoragePolicyName:vSAN Default Storage Policy] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:<nil> XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0}	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.939Z	DEBUG	node/manager.go:235	Renewing VM VirtualMachine:vm-1436 [VirtualCenterHost: vcenter.ong.lab, UUID: 4219f156-2c15-e0f7-01f7-a382d0b2ba1b, Datacenter: Datacenter [Datacenter: Datacenter:datacenter-2, VirtualCenterHost: vcenter.ong.lab]] with new connection: nodeUUID 4219f156-2c15-e0f7-01f7-a382d0b2ba1b	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.946Z	DEBUG	node/manager.go:245	Updated VM VirtualMachine:vm-1436 [VirtualCenterHost: vcenter.ong.lab, UUID: 4219f156-2c15-e0f7-01f7-a382d0b2ba1b, Datacenter: Datacenter [Datacenter: Datacenter:datacenter-2, VirtualCenterHost: vcenter.ong.lab]] for node with nodeUUID 4219f156-2c15-e0f7-01f7-a382d0b2ba1b	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.946Z	DEBUG	node/manager.go:232	Renewing VM VirtualMachine:vm-1437 [VirtualCenterHost: vcenter.ong.lab, UUID: 42193b80-7571-5408-dd42-07a5f945881c, Datacenter: Datacenter [Datacenter: Datacenter:datacenter-2, VirtualCenterHost: vcenter.ong.lab]], no new connection needed: nodeUUID 42193b80-7571-5408-dd42-07a5f945881c	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.947Z	DEBUG	node/manager.go:245	Updated VM VirtualMachine:vm-1437 [VirtualCenterHost: vcenter.ong.lab, UUID: 42193b80-7571-5408-dd42-07a5f945881c, Datacenter: Datacenter [Datacenter: Datacenter:datacenter-2, VirtualCenterHost: vcenter.ong.lab]] for node with nodeUUID 42193b80-7571-5408-dd42-07a5f945881c	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.947Z	DEBUG	node/manager.go:232	Renewing VM VirtualMachine:vm-1438 [VirtualCenterHost: vcenter.ong.lab, UUID: 42196b23-97c0-c8a4-02da-9727d8f64762, Datacenter: Datacenter [Datacenter: Datacenter:datacenter-2, VirtualCenterHost: vcenter.ong.lab]], no new connection needed: nodeUUID 42196b23-97c0-c8a4-02da-9727d8f64762	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.947Z	DEBUG	node/manager.go:245	Updated VM VirtualMachine:vm-1438 [VirtualCenterHost: vcenter.ong.lab, UUID: 42196b23-97c0-c8a4-02da-9727d8f64762, Datacenter: Datacenter [Datacenter: Datacenter:datacenter-2, VirtualCenterHost: vcenter.ong.lab]] for node with nodeUUID 42196b23-97c0-c8a4-02da-9727d8f64762	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.948Z	DEBUG	vanilla/nodes.go:256	Getting accessible datastores for node VirtualMachine:vm-1436	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.960Z	DEBUG	vanilla/nodes.go:256	Getting accessible datastores for node VirtualMachine:vm-1437	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.976Z	DEBUG	vanilla/nodes.go:256	Getting accessible datastores for node VirtualMachine:vm-1438	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.997Z	DEBUG	vanilla/nodes.go:247	sharedDatastores : [Datastore: Datastore:datastore-26, datastore URL: ds:///vmfs/volumes/vsan:52f4f408fd0188ad-90147c7264cadbe1/ Datastore: Datastore:datastore-877, datastore URL: ds:///vmfs/volumes/db5f2d7a-7badab49/]	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.997Z	DEBUG	vanilla/controller.go:302	filterDatastores: dsMap map[] sharedDatastores [Datastore: Datastore:datastore-26, datastore URL: ds:///vmfs/volumes/vsan:52f4f408fd0188ad-90147c7264cadbe1/ Datastore: Datastore:datastore-877, datastore URL: ds:///vmfs/volumes/db5f2d7a-7badab49/]	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.997Z	DEBUG	vanilla/controller.go:308	filter out datastore Datastore: Datastore:datastore-26, datastore URL: ds:///vmfs/volumes/vsan:52f4f408fd0188ad-90147c7264cadbe1/ from create volume spec	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.997Z	DEBUG	vanilla/controller.go:308	filter out datastore Datastore: Datastore:datastore-877, datastore URL: ds:///vmfs/volumes/db5f2d7a-7badab49/ from create volume spec	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:35.997Z	DEBUG	vanilla/controller.go:311	filterDatastores: filteredDatastores []	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:36.070Z	DEBUG	common/vsphereutil.go:169	vSphere CSI driver creating volume pvc-fc7db65e-0227-475c-8554-c796c8eaea32 with create spec (*types.CnsVolumeCreateSpec)(0xc00037c0f0)({
 DynamicData: (types.DynamicData) {
 },
 Name: (string) (len=40) "pvc-fc7db65e-0227-475c-8554-c796c8eaea32",
 VolumeType: (string) (len=5) "BLOCK",
 Datastores: ([]types.ManagedObjectReference) <nil>,
 Metadata: (types.CnsVolumeMetadata) {
  DynamicData: (types.DynamicData) {
  },
  ContainerCluster: (types.CnsContainerCluster) {
   DynamicData: (types.DynamicData) {
   },
   ClusterType: (string) (len=10) "KUBERNETES",
   ClusterId: (string) (len=36) "da72680e-e16b-48d3-8898-4f46f797cade",
   VSphereUser: (string) (len=7) "ansible",
   ClusterFlavor: (string) (len=7) "VANILLA",
   ClusterDistribution: (string) ""
  },
  EntityMetadata: ([]types.BaseCnsEntityMetadata) <nil>,
  ContainerClusterArray: ([]types.CnsContainerCluster) (len=1 cap=1) {
   (types.CnsContainerCluster) {
    DynamicData: (types.DynamicData) {
    },
    ClusterType: (string) (len=10) "KUBERNETES",
    ClusterId: (string) (len=36) "da72680e-e16b-48d3-8898-4f46f797cade",
    VSphereUser: (string) (len=7) "ansible",
    ClusterFlavor: (string) (len=7) "VANILLA",
    ClusterDistribution: (string) ""
   }
  }
 },
 BackingObjectDetails: (*types.CnsBlockBackingDetails)(0xc000872690)({
  CnsBackingObjectDetails: (types.CnsBackingObjectDetails) {
   DynamicData: (types.DynamicData) {
   },
   CapacityInMb: (int64) 2048
  },
  BackingDiskId: (string) "",
  BackingDiskUrlPath: (string) ""
 }),
 Profile: ([]types.BaseVirtualMachineProfileSpec) (len=1 cap=1) {
  (*types.VirtualMachineDefinedProfileSpec)(0xc000791440)({
   VirtualMachineProfileSpec: (types.VirtualMachineProfileSpec) {
    DynamicData: (types.DynamicData) {
    }
   },
   ProfileId: (string) (len=36) "aa6d5a82-1c88-45da-85d3-3d74b91a5bad",
   ReplicationSpec: (*types.ReplicationSpec)(<nil>),
   ProfileData: (*types.VirtualMachineProfileRawData)(<nil>),
   ProfileParams: ([]types.KeyValue) <nil>
  })
 },
 CreateSpec: (types.BaseCnsBaseCreateSpec) <nil>
})
	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:36.077Z	DEBUG	volume/manager.go:184	Update VSphereUser from ansible to ONG.INTERN\ansible	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
2021-04-20T16:08:36.092Z	ERROR	volume/manager.go:210	CNS CreateVolume failed from vCenter "vcenter.ong.lab" with err: ServerFaultCode: createSpecs.datastores is empty	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
sigs.k8s.io/vsphere-csi-driver/pkg/common/cns-lib/volume.(*defaultManager).CreateVolume.func1
	/build/pkg/common/cns-lib/volume/manager.go:210
sigs.k8s.io/vsphere-csi-driver/pkg/common/cns-lib/volume.(*defaultManager).CreateVolume
	/build/pkg/common/cns-lib/volume/manager.go:310
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common.CreateBlockVolumeUtil
	/build/pkg/csi/service/common/vsphereutil.go:170
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla.(*controller).createBlockVolume
	/build/pkg/csi/service/vanilla/controller.go:454
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla.(*controller).CreateVolume.func1
	/build/pkg/csi/service/vanilla/controller.go:644
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla.(*controller).CreateVolume
	/build/pkg/csi/service/vanilla/controller.go:646
github.com/container-storage-interface/spec/lib/go/csi._Controller_CreateVolume_Handler.func1
	/go/pkg/mod/github.com/container-storage-interface/spec@v1.2.0/lib/go/csi/csi.pb.go:5146
github.com/rexray/gocsi/middleware/serialvolume.(*interceptor).createVolume
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/serialvolume/serial_volume_locker.go:162
github.com/rexray/gocsi/middleware/serialvolume.(*interceptor).handle
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/serialvolume/serial_volume_locker.go:90
github.com/rexray/gocsi/utils.ChainUnaryServer.func2.1.1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:99
github.com/rexray/gocsi/middleware/specvalidator.(*interceptor).handleServer.func1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/specvalidator/spec_validator.go:178
github.com/rexray/gocsi/middleware/specvalidator.(*interceptor).handle
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/specvalidator/spec_validator.go:218
github.com/rexray/gocsi/middleware/specvalidator.(*interceptor).handleServer
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/specvalidator/spec_validator.go:177
github.com/rexray/gocsi/utils.ChainUnaryServer.func2.1.1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:99
github.com/rexray/gocsi.(*StoragePlugin).injectContext
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware.go:231
github.com/rexray/gocsi/utils.ChainUnaryServer.func2.1.1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:99
github.com/rexray/gocsi/utils.ChainUnaryServer.func2
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:106
github.com/container-storage-interface/spec/lib/go/csi._Controller_CreateVolume_Handler
	/go/pkg/mod/github.com/container-storage-interface/spec@v1.2.0/lib/go/csi/csi.pb.go:5148
google.golang.org/grpc.(*Server).processUnaryRPC
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:1024
google.golang.org/grpc.(*Server).handleStream
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:1313
google.golang.org/grpc.(*Server).serveStreams.func1.1
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:722
2021-04-20T16:08:36.092Z	ERROR	common/vsphereutil.go:172	failed to create disk pvc-fc7db65e-0227-475c-8554-c796c8eaea32 with error ServerFaultCode: createSpecs.datastores is empty	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/common.CreateBlockVolumeUtil
	/build/pkg/csi/service/common/vsphereutil.go:172
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla.(*controller).createBlockVolume
	/build/pkg/csi/service/vanilla/controller.go:454
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla.(*controller).CreateVolume.func1
	/build/pkg/csi/service/vanilla/controller.go:644
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla.(*controller).CreateVolume
	/build/pkg/csi/service/vanilla/controller.go:646
github.com/container-storage-interface/spec/lib/go/csi._Controller_CreateVolume_Handler.func1
	/go/pkg/mod/github.com/container-storage-interface/spec@v1.2.0/lib/go/csi/csi.pb.go:5146
github.com/rexray/gocsi/middleware/serialvolume.(*interceptor).createVolume
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/serialvolume/serial_volume_locker.go:162
github.com/rexray/gocsi/middleware/serialvolume.(*interceptor).handle
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/serialvolume/serial_volume_locker.go:90
github.com/rexray/gocsi/utils.ChainUnaryServer.func2.1.1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:99
github.com/rexray/gocsi/middleware/specvalidator.(*interceptor).handleServer.func1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/specvalidator/spec_validator.go:178
github.com/rexray/gocsi/middleware/specvalidator.(*interceptor).handle
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/specvalidator/spec_validator.go:218
github.com/rexray/gocsi/middleware/specvalidator.(*interceptor).handleServer
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/specvalidator/spec_validator.go:177
github.com/rexray/gocsi/utils.ChainUnaryServer.func2.1.1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:99
github.com/rexray/gocsi.(*StoragePlugin).injectContext
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware.go:231
github.com/rexray/gocsi/utils.ChainUnaryServer.func2.1.1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:99
github.com/rexray/gocsi/utils.ChainUnaryServer.func2
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:106
github.com/container-storage-interface/spec/lib/go/csi._Controller_CreateVolume_Handler
	/go/pkg/mod/github.com/container-storage-interface/spec@v1.2.0/lib/go/csi/csi.pb.go:5148
google.golang.org/grpc.(*Server).processUnaryRPC
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:1024
google.golang.org/grpc.(*Server).handleStream
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:1313
google.golang.org/grpc.(*Server).serveStreams.func1.1
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:722
2021-04-20T16:08:36.092Z	ERROR	vanilla/controller.go:457	failed to create volume. Error: ServerFaultCode: createSpecs.datastores is empty	{"TraceId": "5c10d3fd-e2df-4aac-9ec4-a8b6d083a7c3"}
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla.(*controller).createBlockVolume
	/build/pkg/csi/service/vanilla/controller.go:457
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla.(*controller).CreateVolume.func1
	/build/pkg/csi/service/vanilla/controller.go:644
sigs.k8s.io/vsphere-csi-driver/pkg/csi/service/vanilla.(*controller).CreateVolume
	/build/pkg/csi/service/vanilla/controller.go:646
github.com/container-storage-interface/spec/lib/go/csi._Controller_CreateVolume_Handler.func1
	/go/pkg/mod/github.com/container-storage-interface/spec@v1.2.0/lib/go/csi/csi.pb.go:5146
github.com/rexray/gocsi/middleware/serialvolume.(*interceptor).createVolume
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/serialvolume/serial_volume_locker.go:162
github.com/rexray/gocsi/middleware/serialvolume.(*interceptor).handle
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/serialvolume/serial_volume_locker.go:90
github.com/rexray/gocsi/utils.ChainUnaryServer.func2.1.1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:99
github.com/rexray/gocsi/middleware/specvalidator.(*interceptor).handleServer.func1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/specvalidator/spec_validator.go:178
github.com/rexray/gocsi/middleware/specvalidator.(*interceptor).handle
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/specvalidator/spec_validator.go:218
github.com/rexray/gocsi/middleware/specvalidator.(*interceptor).handleServer
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware/specvalidator/spec_validator.go:177
github.com/rexray/gocsi/utils.ChainUnaryServer.func2.1.1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:99
github.com/rexray/gocsi.(*StoragePlugin).injectContext
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/middleware.go:231
github.com/rexray/gocsi/utils.ChainUnaryServer.func2.1.1
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:99
github.com/rexray/gocsi/utils.ChainUnaryServer.func2
	/go/pkg/mod/github.com/rexray/gocsi@v1.2.2/utils/utils_middleware.go:106
github.com/container-storage-interface/spec/lib/go/csi._Controller_CreateVolume_Handler
	/go/pkg/mod/github.com/container-storage-interface/spec@v1.2.0/lib/go/csi/csi.pb.go:5148
google.golang.org/grpc.(*Server).processUnaryRPC
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:1024
google.golang.org/grpc.(*Server).handleStream
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:1313
google.golang.org/grpc.(*Server).serveStreams.func1.1
	/go/pkg/mod/google.golang.org/grpc@v1.26.0/server.go:722
2021-04-20T16:11:06.528Z	DEBUG	common/authmanager.go:125	auth manager: refreshDatastoreMapForBlockVolumes is triggered	{"TraceId": "e03323b3-84d9-41f1-abec-45ec4c01ff35"}
2021-04-20T16:11:06.530Z	DEBUG	common/authmanager.go:141	auth manager: refreshDatastoreMapForFileVolumes is triggered	{"TraceId": "ae777cec-1e57-44b2-868a-1abc39f30176"}
2021-04-20T16:11:06.563Z	DEBUG	common/authmanager.go:294	auth manager: file - dsURLs [ds:///vmfs/volumes/5e284959-79eda84d-b493-00fcbae86042/ ds:///vmfs/volumes/5e2703dd-bc5ab81f-88cf-843dc66fea3c/ ds:///vmfs/volumes/vsan:52f4f408fd0188ad-90147c7264cadbe1/ ds:///vmfs/volumes/c836da57-642e0329/ ds:///vmfs/volumes/db5f2d7a-7badab49/ ds:///vmfs/volumes/5e284912-d8102a0b-3208-843dc66fd3f2/ ds:///vmfs/volumes/5e28492d-f0216a15-f90e-843dc6ebd894/] dsInfos [Datastore: Datastore:datastore-114, datastore URL: ds:///vmfs/volumes/5e284959-79eda84d-b493-00fcbae86042/ Datastore: Datastore:datastore-23, datastore URL: ds:///vmfs/volumes/5e2703dd-bc5ab81f-88cf-843dc66fea3c/ Datastore: Datastore:datastore-26, datastore URL: ds:///vmfs/volumes/vsan:52f4f408fd0188ad-90147c7264cadbe1/ Datastore: Datastore:datastore-3465, datastore URL: ds:///vmfs/volumes/c836da57-642e0329/ Datastore: Datastore:datastore-877, datastore URL: ds:///vmfs/volumes/db5f2d7a-7badab49/ Datastore: Datastore:datastore-112, datastore URL: ds:///vmfs/vol...
2021-04-20T16:11:06.581Z	DEBUG	common/authmanager.go:331	Computing the cluster to file service status (enabled/disabled) map.	{"TraceId": "ae777cec-1e57-44b2-868a-1abc39f30176"}
2021-04-20T16:11:06.608Z	DEBUG	common/authmanager.go:309	auth manager: HasUserPrivilegeOnEntities returns [{{} Datastore:datastore-114 [{{} Datastore.FileManagement false} {{} System.Read false}]} {{} Datastore:datastore-23 [{{} Datastore.FileManagement false} {{} System.Read false}]} {{} Datastore:datastore-26 [{{} Datastore.FileManagement false} {{} System.Read false}]} {{} Datastore:datastore-3465 [{{} Datastore.FileManagement false} {{} System.Read false}]} {{} Datastore:datastore-877 [{{} Datastore.FileManagement false} {{} System.Read false}]} {{} Datastore:datastore-112 [{{} Datastore.FileManagement false} {{} System.Read false}]} {{} Datastore:datastore-113 [{{} Datastore.FileManagement false} {{} System.Read false}]}] when checking privileges [Datastore.FileManagement System.Read] on entities [Datastore:datastore-114 Datastore:datastore-23 Datastore:datastore-26 Datastore:datastore-3465 Datastore:datastore-877 Datastore:datastore-112 Datastore:datastore-113] for user ansible	{"TraceId": "e03323b3-...
2021-04-20T16:11:06.608Z	DEBUG	common/authmanager.go:131	auth manager: datastoreMapForBlockVolumes is updated to map[]	{"TraceId": "e03323b3-84d9-41f1-abec-45ec4c01ff35"}
2021-04-20T16:11:06.668Z	DEBUG	common/authmanager.go:373	auth manager: HasUserPrivilegeOnEntities returns [{{} ClusterComputeResource:domain-c7 [{{} Host.Config.Storage false}]}] when checking privileges [Host.Config.Storage] on entities [ClusterComputeResource:domain-c7] for user ansible	{"TraceId": "ae777cec-1e57-44b2-868a-1abc39f30176"}
2021-04-20T16:11:06.668Z	DEBUG	common/authmanager.go:389	Clusters with priv: Host.Config.Storage are : []	{"TraceId": "ae777cec-1e57-44b2-868a-1abc39f30176"}
2021-04-20T16:11:06.668Z	DEBUG	common/authmanager.go:267	dsToFileServiceEnabledMap is map[]	{"TraceId": "ae777cec-1e57-44b2-868a-1abc39f30176"}
2021-04-20T16:11:06.668Z	DEBUG	common/authmanager.go:283	File service is not enabled on the datastore: ds:///vmfs/volumes/vsan:52f4f408fd0188ad-90147c7264cadbe1/	{"TraceId": "ae777cec-1e57-44b2-868a-1abc39f30176"}
2021-04-20T16:11:06.668Z	DEBUG	common/authmanager.go:243	dsURLToInfoMap is map[]	{"TraceId": "ae777cec-1e57-44b2-868a-1abc39f30176"}
2021-04-20T16:11:06.668Z	DEBUG	common/authmanager.go:147	auth manager: datastoreMapForFileVolumes is updated to map[]	{"TraceId": "ae777cec-1e57-44b2-868a-1abc39f30176"}

What you expected to happen: volume to be created and bound to the request.

How to reproduce it (as minimally and precisely as possible): upgrade to 2.2.0

Anything else we need to know?: i delete some pvcs. the csi-attacher fails to remove the volumeattachments.

Environment:

csi-vsphere version: 2.2.0
vsphere-cloud-controller-manager version:
Kubernetes version: v1.19.0+2f3101c
vSphere version: 7.0.1
OS (e.g. from /etc/os-release):
Kernel (e.g. uname -a):
Install tools:
Others:

About this issue

Original URL
State: closed
Created 3 years ago
Comments: 18 (9 by maintainers)

Most upvoted comments

@divyenpatel Thanks for the help! With the csi-auth-check set to true, the datastores get filtered out (filteredDatastores []). When it is set to false, the volume creation succeeds.

Here is what I saw when I enabled the debug log:

2021-06-10T19:19:25.220Z	DEBUG	vanilla/controller.go:302	filterDatastores: dsMap map[] sharedDatastores [Datastore: Datastore:datastore-52403, datastore URL: ds:///vmfs/volumes/6a41acca-b9ff1064-bfda-f4027008609e/ Datastore: Datastore:datastore-70217, datastore URL: ds:///vmfs/volumes/3e3ecb08-a1f2f96c-108e-d8d09072acc1/]	{"TraceId": "970c920b-2749-41e8-801f-b0c82918c526"}
2021-06-10T19:19:25.220Z	DEBUG	vanilla/controller.go:308	filter out datastore Datastore: Datastore:datastore-52403, datastore URL: ds:///vmfs/volumes/6a41acca-b9ff1064-bfda-f4027008609e/ from create volume spec	{"TraceId": "970c920b-2749-41e8-801f-b0c82918c526"}
2021-06-10T19:19:25.220Z	DEBUG	vanilla/controller.go:308	filter out datastore Datastore: Datastore:datastore-70217, datastore URL: ds:///vmfs/volumes/3e3ecb08-a1f2f96c-108e-d8d09072acc1/ from create volume spec	{"TraceId": "970c920b-2749-41e8-801f-b0c82918c526"}
2021-06-10T19:19:25.220Z	DEBUG	vanilla/controller.go:311	filterDatastores: filteredDatastores []	{"TraceId": "970c920b-2749-41e8-801f-b0c82918c526"}
2021-06-10T19:19:25.300Z	DEBUG	common/vsphereutil.go:169	vSphere CSI driver creating volume pvc-45f54360-b1f5-40df-88a5-9d4c43055c65 with create spec (*types.CnsVolumeCreateSpec)(0xc0004261e0)({
<TRUNCATED>
2021-06-10T19:19:25.304Z	DEBUG	volume/manager.go:184	Update VSphereUser from REDACTED_USER to VSPHERE.LOCAL\REDACTED_USER	{"TraceId": "970c920b-2749-41e8-801f-b0c82918c526"}
2021-06-10T19:19:25.317Z	ERROR	volume/manager.go:210	CNS CreateVolume failed from vCenter "128.8.66.170" with err: ServerFaultCode: createSpecs.datastores is empty	{"TraceId": "970c920b-2749-41e8-801f-b0c82918c526"}

This is with debug enabled and csi-auth-check set to false.

2021-06-10T19:35:53.641Z	DEBUG	vanilla/nodes.go:256	Getting accessible datastores for node VirtualMachine:vm-134742	{"TraceId": "9360d199-f0b2-443d-983d-93e2dd06d0cb"}
2021-06-10T19:35:53.650Z	DEBUG	vanilla/nodes.go:256	Getting accessible datastores for node VirtualMachine:vm-134743	{"TraceId": "9360d199-f0b2-443d-983d-93e2dd06d0cb"}
2021-06-10T19:35:53.655Z	DEBUG	vanilla/nodes.go:256	Getting accessible datastores for node VirtualMachine:vm-134744	{"TraceId": "9360d199-f0b2-443d-983d-93e2dd06d0cb"}
2021-06-10T19:35:53.659Z	DEBUG	vanilla/nodes.go:247	sharedDatastores : [Datastore: Datastore:datastore-52403, datastore URL: ds:///vmfs/volumes/6a41acca-b9ff1064-bfda-f4027008609e/ Datastore: Datastore:datastore-70217, datastore URL: ds:///vmfs/volumes/3e3ecb08-a1f2f96c-108e-d8d09072acc1/]	{"TraceId": "9360d199-f0b2-443d-983d-93e2dd06d0cb"}
2021-06-10T19:35:53.739Z	DEBUG	common/vsphereutil.go:169	vSphere CSI driver creating volume pvc-45f54360-b1f5-40df-88a5-9d4c43055c65 with create spec (*types.CnsVolumeCreateSpec)(0xc0000f01e0)({
<TRUNCATED>
2021-06-10T19:35:53.743Z	DEBUG	volume/manager.go:184	Update VSphereUser from REDACTED_USER to VSPHERE.LOCAL\REDACTED_USER	{"TraceId": "9360d199-f0b2-443d-983d-93e2dd06d0cb"}
2021-06-10T19:35:56.223Z	INFO	volume/manager.go:243	CreateVolume: VolumeName: "pvc-45f54360-b1f5-40df-88a5-9d4c43055c65", opId: "dac5d8bd"	{"TraceId": "9360d199-f0b2-443d-983d-93e2dd06d0cb"}
2021-06-10T19:35:56.225Z	INFO	volume/manager.go:302	CreateVolume: Volume created successfully. VolumeName: "pvc-45f54360-b1f5-40df-88a5-9d4c43055c65", opId: "dac5d8bd", volumeID: "09431f3b-d82b-4a5c-bbc2-045864975e28"	{"TraceId": "9360d199-f0b2-443d-983d-93e2dd06d0cb"}

So, this is most likely a bug?

mohideen on Jun 10, 2021

@gohilankit I didn’t found an entry for dsURLToInfoMap is..., but however something that has dsURLs:

2021-05-31T06:49:00.532Z        DEBUG   common/authmanager.go:294       auth manager: file - dsURLs [ds:///vmfs/volumes/5f044157-8fcec500-dcdd-d06726bd0936/ ds:///vmfs/volumes/5f044140-2655c752-4487-d06726bd0936/ ds:///vmfs/volumes/5f0440a0-e7f7cb76-64c5-9440c919a5f6/ ds:///vmfs/volumes/5f0440b9-a867f38c-18c3-9440c919a5f6/ ds:///vmfs/volumes/5f0440de-607479ac-8f95-9440c919bbb6/ ds:///vmfs/volumes/5f04410b-511080be-8860-9440c919bbb6/] dsInfos [Datastore: Datastore:datastore-998, datastore URL: ds:///vmfs/volumes/5f044157-8fcec500-dcdd-d06726bd0936/ Datastore: Datastore:datastore-997, datastore URL: ds:///vmfs/volumes/5f044140-2655c752-4487-d06726bd0936/ Datastore: Datastore:datastore-883, datastore URL: ds:///vmfs/volumes/5f0440a0-e7f7cb76-64c5-9440c919a5f6/ Datastore: Datastore:datastore-884, datastore URL: ds:///vmfs/volumes/5f0440b9-a867f38c-18c3-9440c919a5f6/ Datastore: Datastore:datastore-945, datastore URL: ds:///vmfs/volumes/5f0440de-607479ac-8f95-9440c919bbb6/ Datastore: Datastore:datastore-946, datastore URL: ds:///vmfs/volumes/5f04410b-511080be-8860-9440c919bbb6/]       {"TraceId": "eba6e674-fdd3-4d1a-bcd0-6dad64a7dc31"}

and some lines later there is something like this:

2021-05-31T06:49:00.551Z        DEBUG   common/authmanager.go:309       auth manager: HasUserPrivilegeOnEntities returns [] when checking privileges [Datastore.FileManagement System.Read] on entities [Datastore:datastore-998 Datastore:datastore-997 Datastore:datastore-883 Datastore:datastore-884 Datastore:datastore-945 Datastore:datastore-946] for user myuser   {"TraceId": "eba6e674-fdd3-4d1a-bcd0-6dad64a7dc31"}
2021-05-31T06:49:00.551Z        DEBUG   common/authmanager.go:131       auth manager: datastoreMapForBlockVolumes is updated to map[]   {"TraceId": "eba6e674-fdd3-4d1a-bcd0-6dad64a7dc31"}

I’m not sure if this looks like expected. The Datastores.FileManagement and System.Read privileges are present on the datastores. By the way, I’m using the volume topology feature.

owwweiha on May 31, 2021