AWS CSI driver deleted the volume for PV but has not updated the PV spec and it keep trying to attach this deleted volume to the node

[vpnachev]

/kind bug

What happened?
Together with @ialidzhikov we observed in our cluster multiple statefulset apps cannot start due to volume failed to be attached.

Warning  FailedAttachVolume  8m37s               attachdetach-controller  AttachVolume.Attach failed for volume "pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58" : rpc error: code = Internal desc = Could not get volume with ID "vol-009e0a5f5cf6dc220": InvalidVolume.NotFound: The volume 'vol-009e0a5f5cf6dc220' does not exist.

It turn out that the volume for the PV is actually deleted by the driver during the creation.

1. External provisioner is calling the CreateVolume
2. The driver starts creating the volume and then wait until it is available
3. During this time, the provisioner issued another CreateVolume request
4. The second CreateVolume request has seen the volume and returned the volume id.
5. The provisioner sets the volume id in the PV spec.
6. The first CreateVolume request now fails and send delete request (introduced with delete leaked volume if driver don't know the volume status #771) for the volume.
7. As the volume is deleted, the PV cannot be mounted to a node and then to a pod.

Here are the logs from the CSI components (external-attacher, aws-ebs-csi-driver, external-provisioner)

I 2021-06-02T18:20:44.634283Z CreateVolumeRequest {Name:pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 CapacityRange:required_bytes:85899345920  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[type:gp2] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} 
I 2021-06-02T18:20:44.634405Z GRPC request: {"accessibility_requirements":{"preferred":[{"segments":{"topology.ebs.csi.aws.com/zone":"us-east-1a","topology.kubernetes.io/zone":"us-east-1a"}}],"requisite":[{"segments":{"topology.ebs.csi.aws.com/zone":"us-east-1a","topology.kubernetes.io/zone":"us-east-1a"}}]},"capacity_range":{"required_bytes":85899345920},"name":"pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58","parameters":{"csi.storage.k8s.io/pv/name":"pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58","csi.storage.k8s.io/pvc/name":"main-etcd-etcd-main-0","csi.storage.k8s.io/pvc/namespace":"my-app-namespace","type":"gp2"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}}]} 
I 2021-06-02T18:20:44.668549Z CreateVolume: called with args {Name:pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 CapacityRange:required_bytes:85899345920  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 csi.storage.k8s.io/pvc/name:main-etcd-etcd-main-0 csi.storage.k8s.io/pvc/namespace:my-app-namespace type:gp2] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} 
I 2021-06-02T18:20:54.637654Z CreateVolumeRequest {Name:pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 CapacityRange:required_bytes:85899345920  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[type:gp2] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} 
I 2021-06-02T18:20:54.637760Z GRPC request: {"accessibility_requirements":{"preferred":[{"segments":{"topology.ebs.csi.aws.com/zone":"us-east-1a","topology.kubernetes.io/zone":"us-east-1a"}}],"requisite":[{"segments":{"topology.ebs.csi.aws.com/zone":"us-east-1a","topology.kubernetes.io/zone":"us-east-1a"}}]},"capacity_range":{"required_bytes":85899345920},"name":"pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58","parameters":{"csi.storage.k8s.io/pv/name":"pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58","csi.storage.k8s.io/pvc/name":"main-etcd-etcd-main-0","csi.storage.k8s.io/pvc/namespace":"my-app-namespace","type":"gp2"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}}]} 
I 2021-06-02T18:20:55.066873Z CreateVolume: called with args {Name:pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 CapacityRange:required_bytes:85899345920  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 csi.storage.k8s.io/pvc/name:main-etcd-etcd-main-0 csi.storage.k8s.io/pvc/namespace:my-app-namespace type:gp2] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} 
E 2021-06-02T18:20:55.066963999Z vol-009e0a5f5cf6dc220 failed to be deleted, this may cause volume leak 
I 2021-06-02T18:20:55.067007Z Node Service: volume="name:\"pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58\" capacity_range:<required_bytes:85899345920 > volume_capabilities:<mount:<fs_type:\"ext4\" > access_mode:<mode:SINGLE_NODE_WRITER > > parameters:<key:\"csi.storage.k8s.io/pv/name\" value:\"pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58\" > parameters:<key:\"csi.storage.k8s.io/pvc/name\" value:\"main-etcd-etcd-main-0\" > parameters:<key:\"csi.storage.k8s.io/pvc/namespace\" value:\"my-app-namespace\" > parameters:<key:\"type\" value:\"gp2\" > accessibility_requirements:<requisite:<segments:<key:\"topology.ebs.csi.aws.com/zone\" value:\"us-east-1a\" > segments:<key:\"topology.kubernetes.io/zone\" value:\"us-east-1a\" > > preferred:<segments:<key:\"topology.ebs.csi.aws.com/zone\" value:\"us-east-1a\" > segments:<key:\"topology.kubernetes.io/zone\" value:\"us-east-1a\" > > > " operation finished 
E 2021-06-02T18:20:55.067044Z GRPC error: rpc error: code = Internal desc = Could not create volume "pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58": failed to get an available volume in EC2: RequestCanceled: request context canceled 
I 2021-06-02T18:20:55.767132Z GRPC response: {"volume":{"accessible_topology":[{"segments":{"topology.ebs.csi.aws.com/zone":"us-east-1a","topology.kubernetes.io/zone":"us-east-1a"}}],"capacity_bytes":85899345920,"volume_id":"vol-009e0a5f5cf6dc220"}} 
I 2021-06-02T18:20:55.769378Z create volume rep: {CapacityBytes:85899345920 VolumeId:vol-009e0a5f5cf6dc220 VolumeContext:map[] ContentSource:<nil> AccessibleTopology:[segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > ] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} 
I 2021-06-02T18:20:55.769469Z successfully created PV pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 for PVC main-etcd-etcd-main-0 and csi volume name vol-009e0a5f5cf6dc220 
I 2021-06-02T18:20:55.769501Z successfully created PV {GCEPersistentDisk:nil AWSElasticBlockStore:&AWSElasticBlockStoreVolumeSource{VolumeID:vol-009e0a5f5cf6dc220,FSType:ext4,Partition:0,ReadOnly:false,} HostPath:nil Glusterfs:nil NFS:nil RBD:nil ISCSI:nil Cinder:nil CephFS:nil FC:nil Flocker:nil FlexVolume:nil AzureFile:nil VsphereVolume:nil Quobyte:nil AzureDisk:nil PhotonPersistentDisk:nil PortworxVolume:nil ScaleIO:nil Local:nil StorageOS:nil CSI:nil} 
I 2021-06-02T18:20:55.769573Z provision "my-app-namespace/main-etcd-etcd-main-0" class "gardener.cloud-fast": volume "pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58" provisioned 
I 2021-06-02T18:20:55.769651Z Saving volume pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 
I 2021-06-02T18:20:55.773360Z Volume pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 saved 
I 2021-06-02T18:20:55.774971Z Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"my-app-namespace", Name:"main-etcd-etcd-main-0", UID:"20ee2400-84a0-4afb-a2df-b5a7af0f0b58", APIVersion:"v1", ResourceVersion:"6352825115", FieldPath:""}): type: 'Normal' reason: 'ProvisioningSucceeded' Successfully provisioned volume pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 
I 2021-06-02T18:20:55.775888Z CreateVolumeRequest {Name:pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 CapacityRange:required_bytes:85899345920  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[type:gp2] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} 
I 2021-06-02T18:20:55.776006Z GRPC request: {"accessibility_requirements":{"preferred":[{"segments":{"topology.ebs.csi.aws.com/zone":"us-east-1a","topology.kubernetes.io/zone":"us-east-1a"}}],"requisite":[{"segments":{"topology.ebs.csi.aws.com/zone":"us-east-1a","topology.kubernetes.io/zone":"us-east-1a"}}]},"capacity_range":{"required_bytes":85899345920},"name":"pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58","parameters":{"csi.storage.k8s.io/pv/name":"pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58","csi.storage.k8s.io/pvc/name":"main-etcd-etcd-main-0","csi.storage.k8s.io/pvc/namespace":"my-app-namespace","type":"gp2"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}}]} 
I 2021-06-02T18:20:55.877271Z CreateVolume: called with args {Name:pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 CapacityRange:required_bytes:85899345920  VolumeCapabilities:[mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER > ] Parameters:map[csi.storage.k8s.io/pv/name:pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 csi.storage.k8s.io/pvc/name:main-etcd-etcd-main-0 csi.storage.k8s.io/pvc/namespace:my-app-namespace type:gp2] Secrets:map[] VolumeContentSource:<nil> AccessibilityRequirements:requisite:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > > preferred:<segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > >  XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} 
I 2021-06-02T18:20:56.168082Z GRPC response: {"volume":{"accessible_topology":[{"segments":{"topology.ebs.csi.aws.com/zone":"us-east-1a","topology.kubernetes.io/zone":"us-east-1a"}}],"capacity_bytes":85899345920,"volume_id":"vol-009e0a5f5cf6dc220"}} 
I 2021-06-02T18:20:56.170341Z create volume rep: {CapacityBytes:85899345920 VolumeId:vol-009e0a5f5cf6dc220 VolumeContext:map[] ContentSource:<nil> AccessibleTopology:[segments:<key:"topology.ebs.csi.aws.com/zone" value:"us-east-1a" > segments:<key:"topology.kubernetes.io/zone" value:"us-east-1a" > ] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} 
I 2021-06-02T18:20:56.170469Z successfully created PV pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 for PVC main-etcd-etcd-main-0 and csi volume name vol-009e0a5f5cf6dc220 
I 2021-06-02T18:20:56.170510Z successfully created PV {GCEPersistentDisk:nil AWSElasticBlockStore:&AWSElasticBlockStoreVolumeSource{VolumeID:vol-009e0a5f5cf6dc220,FSType:ext4,Partition:0,ReadOnly:false,} HostPath:nil Glusterfs:nil NFS:nil RBD:nil ISCSI:nil Cinder:nil CephFS:nil FC:nil Flocker:nil FlexVolume:nil AzureFile:nil VsphereVolume:nil Quobyte:nil AzureDisk:nil PhotonPersistentDisk:nil PortworxVolume:nil ScaleIO:nil Local:nil StorageOS:nil CSI:nil} 
I 2021-06-02T18:20:56.170577Z provision "my-app-namespace/main-etcd-etcd-main-0" class "gardener.cloud-fast": volume "pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58" provisioned 
I 2021-06-02T18:20:56.170622Z Saving volume pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 
I 2021-06-02T18:20:56.174790Z Volume pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 saved 
I 2021-06-02T18:20:56.175016Z Event(v1.ObjectReference{Kind:"PersistentVolumeClaim", Namespace:"my-app-namespace", Name:"main-etcd-etcd-main-0", UID:"20ee2400-84a0-4afb-a2df-b5a7af0f0b58", APIVersion:"v1", ResourceVersion:"6352827870", FieldPath:""}): type: 'Normal' reason: 'ProvisioningSucceeded' Successfully provisioned volume pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58 
I 2021-06-02T18:21:01.651906Z Adding finalizer to PV "pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58" 
I 2021-06-02T18:21:01.656661Z PV finalizer added to "pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58" 
I 2021-06-02T18:21:01.766132Z GRPC request: {"node_id":"i-08d173d49cb114806","volume_capability":{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}},"volume_context":{"partition":"0"},"volume_id":"vol-009e0a5f5cf6dc220"} 
I 2021-06-02T18:21:01.866599Z ControllerPublishVolume: called with args {VolumeId:vol-009e0a5f5cf6dc220 NodeId:i-08d173d49cb114806 VolumeCapability:mount:<fs_type:"ext4" > access_mode:<mode:SINGLE_NODE_WRITER >  Readonly:false Secrets:map[] VolumeContext:map[partition:0] XXX_NoUnkeyedLiteral:{} XXX_unrecognized:[] XXX_sizecache:0} 
I 2021-06-02T18:21:05.167281Z Releasing in-process attachment entry: /dev/xvdbh -> volume vol-009e0a5f5cf6dc220 
E 2021-06-02T18:21:05.167317Z GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-009e0a5f5cf6dc220" to node "i-08d173d49cb114806": could not attach volume "vol-009e0a5f5cf6dc220" to node "i-08d173d49cb114806": IncorrectState: vol-009e0a5f5cf6dc220 is not 'available'. 
I 2021-06-02T18:21:05.168531Z GRPC error: rpc error: code = Internal desc = Could not attach volume "vol-009e0a5f5cf6dc220" to node "i-08d173d49cb114806": could not attach volume "vol-009e0a5f5cf6dc220" to node "i-08d173d49cb114806": IncorrectState: vol-009e0a5f5cf6dc220 is not 'available'. 
I 2021-06-02T18:21:05.195101Z Error processing "csi-4ab704f02c9ec829ea1be71e873b23d5399889771155c8ef3fb2c720e9f6bad6": failed to attach: rpc error: code = Internal desc = Could not attach volume "vol-009e0a5f5cf6dc220" to node "i-08d173d49cb114806": could not attach volume "vol-009e0a5f5cf6dc220" to node "i-08d173d49cb114806": IncorrectState: vol-009e0a5f5cf6dc220 is not 'available'. 
I 2021-06-02T18:21:05.195237Z PV finalizer is already set on "pv-shoot--foo--bar-20ee2400-84a0-4afb-a2df-b5a7af0f0b58" 

What you expected to happen?
The PV should not be left in a broken state where the referenced volume is deleted.

How to reproduce it (as minimally and precisely as possible)?
Not applicable, but see the steps above that describe the race condition.

Anything else we need to know?:

Environment

• Kubernetes version (use kubectl version): v1.18.16
• Driver version: v0.10.1
• External provisioner: v1.6.0

[ialidzhikov]

I am cc-ing the folks that were involved with #771 (as this is PR that introduces the race condition)
/cc @AndyXiangLi @wongma7 @ayberk

[wongma7]

The inFlight requests map is intended to insulate us from races like this. Haven't had a chance to dig deep yet but I will be checking that first.

[ialidzhikov]

The inFlight requests map is intended to insulate us from races like this. Haven't had a chance to dig deep yet but I will be checking that first.

If by the inFlight requests map, you mean the logic in pkg/driver/controller.go#L220-L225

aws-ebs-csi-driver/pkg/driver/controller.go

Lines 220 to 225 in f678406

	// check if a request is already in-flight because the CreateVolume API is not idempotent
	if ok := d.inFlight.Insert(req.String()); !ok {
	msg := fmt.Sprintf("Create volume request for %s is already in progress", volName)
	return nil, status.Error(codes.Aborted, msg)
	}
	defer d.inFlight.Delete(req.String())

then this logic is executed after the "early exit" for already existing volume (pkg/driver/controller.go#L212-L218)

aws-ebs-csi-driver/pkg/driver/controller.go

Lines 212 to 218 in f678406

	// volume exists already
	if disk != nil {
	if disk.SnapshotID != snapshotID {
	return nil, status.Errorf(codes.AlreadyExists, "Volume already exists, but was restored from a different snapshot than %s", snapshotID)
	}
	return newCreateVolumeResponse(disk), nil
	}

So that's why I think that the inFlight requests map is not helping here.

I guess one potential fix could be in the "early exit" for already existing volume - when the volume is not available, then aws-ebs-driver should not execute the "early exit" logic. Because right now the "early exit" logic does not consider the volume state at all, while on the other side the CreateVolume func waits until volume is available - and respectively it deletes the volume when it is not getting available. WDYT?

[ialidzhikov]

/priority important-soon

[AndyXiangLi]

@wongma7 I think either

1. move the inFlight insertion operation before the volume exists check,
2. check the volume status before exits.
   First one makes more sense to me, if previous request is still in progress, we should not assume the volume is ready and check if volume is exist or not
   Let me know.

[wongma7]

1. sounds simplest to me!

in fact it's probably safer to do the same for ALL functions that, according to the spec, MUST be idempotent. i.e. wrap DeleteVolume, Create/DeleteSnapshot, etc. Otherwise it's too hard for us to avoid all potential race conditions when multiple calls are in flight. We cannot trust kubelet/external-provisioner/external-attacher to keep track of multiple calls, they can restart at any time and lose track, and the spec only says they "SHOULD ensure that there are no other calls", so the responsibility falls on the driver to keep trakc.