Delete volume requests are sent twice with new sig-storage-lib-external-provisioner v10.0.1 because of the finalizer "external-provisioner.volume.kubernetes.io/finalizer" #176

zjuliuf · 2024-08-14T10:08:33Z

What happened:

When we try to delete volume using new new sig-storage-lib-external-provisioner v10.0.1, we still notice 2 or more volume deletion requests in the logs. As a result of which PV deleting costs more time.

What you expected to happen:

Only 1 volume deletion request during the pv deletion.

Simple analysis:

When volume related to the PV was deleted successfully, sig-storage-lib-external-provisioner begins to Delete PV，then PV object was updated with a deletionTimestamp, so that the PV was added to volumeQueue, then exec deleteVolumeOperation again because the finalizer "external-provisioner.volume.kubernetes.io/finalizer" exists. finally, 2 or more volume deletion requests was sent during the pv deletion.

Below is the code analysis:
(first time deletion) function 'shouldDelete' returns true ---> ctrl.provisioner.Delete deletes volume related to the PV ---> ctrl.client.CoreV1().PersistentVolumes().Delete deletes PV ---> PV was updated with adding deletionTimestamp ---> try to remove finalizer "external-provisioner.volume.kubernetes.io/finalizer"

(second time deletion) During the first time deletion, when PV was updated with adding deletionTimestamp(before removing finalizer), the PV was added to the volumeQueue again. Then the second time deletion began. Becuase the finalizer "external-provisioner.volume.kubernetes.io/finalizer" still existed and the PV status was Released, so the function 'shouldDelete' still returned 'true' and executed ctrl.provisioner.Delete again.

volumeHandler := cache.ResourceEventHandlerFuncs{
	AddFunc:    func(obj interface{}) { controller.enqueueVolume(obj) },
	UpdateFunc: func(oldObj, newObj interface{}) { controller.enqueueVolume(newObj) },
	DeleteFunc: func(obj interface{}) { controller.forgetVolume(obj) },
}

How to reproduce it:

Call NewProvisionController with an option AddFinalizer(true)
Create a storageclass and PVC
Delete PVC
Notice the status of PV and logs of provisioner

Environment:

Driver version:
Kubernetes version (use kubectl version): v1.28
OS (e.g. from /etc/os-release):
Kernel (e.g. uname -a):
Install tools:
Others: sig-storage-lib-external-provisioner v10.0.1

The text was updated successfully, but these errors were encountered:

Jainbrt · 2024-08-14T11:16:04Z

@zjuliuf you would need latest k8s release to verify the fix, such as 1.28.12.

zjuliuf · 2024-08-14T14:21:58Z

@Jainbrt Thanks a lot, I will try. By the way, which PR of k8s fixed this issue?

Jainbrt · 2024-08-14T14:28:03Z

kubernetes/kubernetes#125767

zjuliuf · 2024-08-14T14:33:47Z

@Jainbrt I watched the status of the PV, its status was changed to 'Released' from 'Bound' without 'Failed'.

Jainbrt · 2024-08-14T14:48:38Z

is this the issue you are talking about kubernetes-csi/external-provisioner#1184 ?

zjuliuf · 2024-08-15T02:35:55Z

@Jainbrt Looks like the same problem.
I checked the code about 'syncVolume' in sig-storage-lib-external-provisioner v10.0.1 and watched the status of the PV. Because of the changing of PV object, sig-storage-lib-external-provisioner received multiple updating events, so that function 'syncVolume' executed multiple times, and then function 'shouldDelete' return 'true' because "external-provisioner.volume.kubernetes.io/finalizer" still exists in PV(this finalizer removed successfully finally) so that another volume deletion request was sent to the volume provisioner. Volume and PV can be deleted succefully finallly, only the deletion process will be executed more than 2 times(This doesn't happen every time and I guess because events of PV sometimes merge).

zjuliuf · 2024-08-15T07:59:25Z

In order to reduce redundant deletion processes when 'addFinalizer' is true, can we modify the code like below? In the codes below, If only the DeletionTimestamp and Finalizers of pv change, the pv will not be added to the queue.
@jsafrane @xing-yang @Jainbrt

volumeHandler := cache.ResourceEventHandlerFuncs{
	AddFunc:    func(obj interface{}) { controller.enqueueVolume(obj) },
	UpdateFunc: func(oldObj, newObj interface{}) {
		if controller.addFinalizer {
			oldPv, ok := oldObj.(*v1.PersistentVolume)
			if !ok {
				return
			}
			newPv, ok := newObj.(*v1.PersistentVolume)
			if !ok {
				return
			}
			newPv.ResourceVersion = oldPv.ResourceVersion
			newPv.ManagedFields = oldPv.ManagedFields
			newPv.DeletionTimestamp = oldPv.DeletionTimestamp
			newPv.DeletionGracePeriodSeconds = oldPv.DeletionGracePeriodSeconds
			if len(newPv.Finalizers) <= len(oldPv.Finalizers) {
				newPv.Finalizers = oldPv.Finalizers
			}
			if equality.Semantic.DeepEqual(oldPv, newPv) {
				klog.V(2).Infof("debug, no changes except deletionTimestamp and finalizers")
				return
			}
		}
		controller.enqueueVolume(newObj)
	},
	DeleteFunc: func(obj interface{}) { controller.forgetVolume(obj) },
}

Chaunceyctx · 2024-08-15T08:05:20Z

same problem occurs in my production environment

jsafrane · 2024-08-16T09:17:15Z

I checked the code about 'syncVolume' in sig-storage-lib-external-provisioner v10.0.1 and watched the status of the PV. Because of the changing of PV object, sig-storage-lib-external-provisioner received multiple updating events, so that function 'syncVolume' executed multiple times, and then function 'shouldDelete' return 'true' because "external-provisioner.volume.kubernetes.io/finalizer" still exists in PV

What events did the provisioner receive and who / what caused them? You can either get a diff in UpdateFunc in the provisioner or get it from the API server audit logs. It looks like something is racy here.

I would prefer to see what causes these events before we start ignoring them.

ConnorJC3 · 2024-11-07T15:11:37Z

Hi - I've been investigating this issue because we've also been seeing it in the EBS CSI Driver. Our driver is correctly idempotent, but these requets result in a lot of extra unnecessary API spam when deleting volumes - based on our testing this issue will occur on roughly one third of volume deletions.

This issue is called by the HonorPVReclaimPolicy feature (or, to be more specific to this repo, it is caused when the controller is initialized with AddFinalizer: https://github.com/kubernetes-sigs/sig-storage-lib-external-provisioner/blob/a6d1dc518aca508e2452724e86ca775003bcd23e/controller/controller.go#L565C6-L565C18

When the PV finalizer is enabled, we first removes the finalizer and then deletes the volume (after it successfully deletes a volume through the provisioner). That first change - removing the finalizer, triggers an additional update to the volume that goes through syncPVC, resulting in multiple DeleteVolume calls.

zjuliuf · 2024-11-13T13:22:02Z

I checked the code about 'syncVolume' in sig-storage-lib-external-provisioner v10.0.1 and watched the status of the PV. Because of the changing of PV object, sig-storage-lib-external-provisioner received multiple updating events, so that function 'syncVolume' executed multiple times, and then function 'shouldDelete' return 'true' because "external-provisioner.volume.kubernetes.io/finalizer" still exists in PV

What events did the provisioner receive and who / what caused them? You can either get a diff in UpdateFunc in the provisioner or get it from the API server audit logs. It looks like something is racy here.

I would prefer to see what causes these events before we start ignoring them.

@jsafrane
pv has 2 finalizers.

after successful deleting volume, the provisioner exec func ctrl.client.CoreV1().PersistentVolumes().Delete to delete pv. so generated the following event

the provisioner began to remove finalizer "external-provisioner.volume.kubernetes.io/finalizer" of pv after successful deleting volume. so generated the following event

pv-protection-controller began to remove finalizer "kubernetes.io/pv-protection" of pv after pv received DELETE req. so generated the following event

Added some print logs to the provisioner as follows

because of the events of pv, after the volume was successfully deleted, the function UpdateFunc was executed twice more

first time:
new pv: {"metadata":{"name":"pvc-7109fd69-f0c9-41c5-812d-6b2f391b43e6","uid":"5d4cbfe5-7376-4823-b2d2-4cbcabdcf95a","resourceVersion":"1538004","creationTimestamp":"2024-11-13T12:26:16Z","deletionTimestamp":"2024-11-13T12:32:18Z","deletionGracePeriodSeconds":0,"labels":{"failure-domain.beta.kubernetes.io/region":"fake-region","failure-domain.beta.kubernetes.io/zone":"fake-az"},"annotations":{"pv.kubernetes.io/provisioned-by":"csiaddon-csi-provisioner"},"finalizers":["external-provisioner.volume.kubernetes.io/finalizer","kubernetes.io/pv-protection"],

===> this time caused the second time deleting volume because there was still finalizer "external-provisioner.volume.kubernetes.io/finalizer"

second time:
new pv: {"metadata":{"name":"pvc-7109fd69-f0c9-41c5-812d-6b2f391b43e6","uid":"5d4cbfe5-7376-4823-b2d2-4cbcabdcf95a","resourceVersion":"1538006","creationTimestamp":"2024-11-13T12:26:16Z","deletionTimestamp":"2024-11-13T12:32:18Z","deletionGracePeriodSeconds":0,"labels":{"failure-domain.beta.kubernetes.io/region":"fake-region","failure-domain.beta.kubernetes.io/zone":"fake-az"},"annotations":{"pv.kubernetes.io/provisioned-by":"csiaddon-csi-provisioner"},"finalizers":["kubernetes.io/pv-protection"],

zjuliuf mentioned this issue Aug 14, 2024

Delete volume requests are sent twice with new provisioner version v5.0.1 kubernetes-csi/external-provisioner#1235

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Delete volume requests are sent twice with new sig-storage-lib-external-provisioner v10.0.1 because of the finalizer "external-provisioner.volume.kubernetes.io/finalizer" #176

Delete volume requests are sent twice with new sig-storage-lib-external-provisioner v10.0.1 because of the finalizer "external-provisioner.volume.kubernetes.io/finalizer" #176

zjuliuf commented Aug 14, 2024 •

edited

Loading

Jainbrt commented Aug 14, 2024

zjuliuf commented Aug 14, 2024

Jainbrt commented Aug 14, 2024

zjuliuf commented Aug 14, 2024

Jainbrt commented Aug 14, 2024

zjuliuf commented Aug 15, 2024 •

edited

Loading

zjuliuf commented Aug 15, 2024 •

edited

Loading

Chaunceyctx commented Aug 15, 2024

jsafrane commented Aug 16, 2024 •

edited

Loading

ConnorJC3 commented Nov 7, 2024

zjuliuf commented Nov 13, 2024 •

edited

Loading

Delete volume requests are sent twice with new sig-storage-lib-external-provisioner v10.0.1 because of the finalizer "external-provisioner.volume.kubernetes.io/finalizer" #176

Delete volume requests are sent twice with new sig-storage-lib-external-provisioner v10.0.1 because of the finalizer "external-provisioner.volume.kubernetes.io/finalizer" #176

Comments

zjuliuf commented Aug 14, 2024 • edited Loading

What happened:

What you expected to happen:

Simple analysis:

How to reproduce it:

Environment:

Jainbrt commented Aug 14, 2024

zjuliuf commented Aug 14, 2024

Jainbrt commented Aug 14, 2024

zjuliuf commented Aug 14, 2024

Jainbrt commented Aug 14, 2024

zjuliuf commented Aug 15, 2024 • edited Loading

zjuliuf commented Aug 15, 2024 • edited Loading

Chaunceyctx commented Aug 15, 2024

jsafrane commented Aug 16, 2024 • edited Loading

ConnorJC3 commented Nov 7, 2024

zjuliuf commented Nov 13, 2024 • edited Loading

zjuliuf commented Aug 14, 2024 •

edited

Loading

zjuliuf commented Aug 15, 2024 •

edited

Loading

zjuliuf commented Aug 15, 2024 •

edited

Loading

jsafrane commented Aug 16, 2024 •

edited

Loading

zjuliuf commented Nov 13, 2024 •

edited

Loading