Duplicate ControllerUnpublish calls

[jsafrane]

There is a race in the external-attacher that can cause ControllerUnpublish to be called twice.

Scenario:

1. A pod with an attached volume is deleted, the attacher gets an event that a VolumeAttachment got DeletionTimestamp
2. The attacher calls ControllerUnpublish, gets success from the CSI driver. The attacher marks the VolumeAttachment Status as detached and removes attacher's finalizer. Notice two PATCH calls are needed:

   external-attacher/pkg/controller/util.go

   Lines 82 to 106 in 8e7b49f

   	logger.V(4).Info("Marking as detached")
   	clone := va.DeepCopy()
   	clone.Status.Attached = false
   	clone.Status.DetachError = nil
   	clone.Status.AttachmentMetadata = nil
   	patch, err := createMergePatch(va, clone)
   	if err != nil {
   	return va, err
   	}
   	newVA, err := client.StorageV1().VolumeAttachments().Patch(ctx, va.Name, types.MergePatchType, patch, metav1.PatchOptions{}, "status")
   	if err != nil {
   	return va, err
   	}
   	// As Finalizers is not in the status subresource it must be patched separately. It is removed after the status update so the resource is not prematurely deleted.
   	clone = newVA.DeepCopy()
   	clone.Finalizers = newFinalizers
   	patch, err = createMergePatch(newVA, clone)
   	if err != nil {
   	return newVA, err
   	}
   	newVA, err = client.StorageV1().VolumeAttachments().Patch(ctx, newVA.Name, types.MergePatchType, patch, metav1.PatchOptions{}, "")
   	if err != nil {
   	return newVA, err
   	}

3. The attacher's informer gets an event about the first PATCH - the volume is marked as detached + has DeletionTimestap, but the finalizer is still there. The attacher does not know what's the state of the attachment and calls ControllerUnpublish again.

If lucky enough, the CSI driver is idempotent, returns success and the attacher tries to mark the VolumeAattachment as detached + tries to remove the finalizer. This usually fails, because the VolumeAttachment gets deleted in the API server.

Logs, the first detach:

I0916 12:34:39.148636       1 csi_handler.go:285] "Starting detach operation" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"
I0916 12:34:39.148655       1 csi_handler.go:292] "Detaching" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"
I0916 12:34:39.148683       1 connection.go:264] "GRPC call" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b" method="/csi.v1.Controller/ControllerUnpublishVolume" request="{\"node_id\":\"423d4603-e2cb-8d46-961a-b35ac7cdd7dc\",\"volume_id\":\"353f8051-d712-4a64-aac7-e601f356487e\"}"
I0916 12:34:39.579698       1 connection.go:270] "GRPC response" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b" response="{}" err=null
I0916 12:34:39.579858       1 csi_handler.go:595] "Detached" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"
I0916 12:34:39.579991       1 util.go:82] "Marking as detached" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"
I0916 12:34:43.547409       1 round_trippers.go:553] PATCH https://172.30.0.1:443/apis/storage.k8s.io/v1/volumeattachments/csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b/status 200 OK in 13 milliseconds
I0916 12:34:47.153097       1 round_trippers.go:553] PATCH https://172.30.0.1:443/apis/storage.k8s.io/v1/volumeattachments/csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b 200 OK in 19 milliseconds
I0916 12:34:47.153360       1 util.go:107] "Finalizer removed" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"
I0916 12:34:47.153382       1 csi_handler.go:305] "Fully detached" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"

Second detach:

I0916 12:34:47.153422       1 controller.go:213] "Started VolumeAttachment processing" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"
I0916 12:34:47.153433       1 csi_handler.go:233] "CSIHandler: processing VolumeAttachment" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"
I0916 12:34:47.153440       1 csi_handler.go:285] "Starting detach operation" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"
I0916 12:34:47.153472       1 csi_handler.go:292] "Detaching" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"
I0916 12:34:47.153521       1 connection.go:264] "GRPC call" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b" method="/csi.v1.Controller/ControllerUnpublishVolume" request="{\"node_id\":\"423d4603-e2cb-8d46-961a-b35ac7cdd7dc\",\"volume_id\":\"353f8051-d712-4a64-aac7-e601f356487e\"}"
I0916 12:34:47.648399       1 connection.go:270] "GRPC response" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b" response="{}" err=null
I0916 12:34:47.648425       1 csi_handler.go:595] "Detached" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"
I0916 12:34:47.648452       1 util.go:82] "Marking as detached" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"
I0916 12:34:50.740640       1 round_trippers.go:553] PATCH https://172.30.0.1:443/apis/storage.k8s.io/v1/volumeattachments/csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b/status 404 Not Found in 5 milliseconds
I0916 12:34:50.740784       1 csi_handler.go:623] "Saving detach error" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b"
I0916 12:34:53.541033       1 round_trippers.go:553] PATCH https://172.30.0.1:443/apis/storage.k8s.io/v1/volumeattachments/csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b/status 404 Not Found in 6 milliseconds
I0916 12:34:53.541197       1 csi_handler.go:299] "Failed to save detach error to VolumeAttachment" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b" err="volumeattachments.storage.k8s.io \"csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b\" not found"
I0916 12:34:53.541225       1 csi_handler.go:243] "Error processing" VolumeAttachment="csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b" err="failed to detach: could not mark as detached: volumeattachments.storage.k8s.io \"csi-372e0b9ee6cac3018b9a8ecf01d2d80795586c97512830f11e62648ecc13267b\" not found"

All this is relatively harmless, just some CSI drivers don't like to be called multiple times. For example, while vsphere-csi-driver is idempotent, it calls CnsClient.DetachVolume() on every ControllerUnpublish. It only checks its error code to ensure idempotency. The failed DetachVolume call is then visible in list of tasks as failed in vCenter and vSphere admins may get an alert.

[jsafrane]

Thinking out loud.

The external attacher currently does not have any internal state about a VolumeAttachment. At step 3. above, it only sees the VolumeAttachment object and it can be indistinguishable from VolumeAttachment that failed attach with a non-final error + the attacher failed to save the error to VolumeAttachment. Its Pod was deleted and the volume should be detached now. The attacher should call ControllerUnpublish to make sure a pending ControllerPublish is cancelled and the volume is detached in the end.

• The attacher could remove the finalizer from the VolumeAttachment first, and then update status to attached=false. But there is a chance that the VolumeAttachment gets deleted in between.

• The attacher could issue an GET call to get a fresh VolumeAttachment before calling ControllerUnpublish, to see if both PATCHes were applied and then it could skip detach. That could load the API server.

• The attacher could save the updated VolumeAttachments after both PATCHes in informer's cache.

  • Tried this, when a VolumeAttachment is saved to the informer cache after the second PATCH, then the informer ignores Delete event and the attachment remains in the cache. Saving the attachment after the first PATCH works and I can't reproduce the race, however, it looks very... intricate.

• The attacher could remember a detached volume for few minutes after a volume has been detached. And check this cache before issuing ControllerUnpublish.

• In the 1st Patch, when setting status.attached=false, the attacher could set something else in the status, so a subsequent reconciliation would see that the volume is really detached and just remove the finalizer. attached=false itself is not enough, it can be a VolumeAttachment which timed out attach and now we need to confirm the volume is really detached.

[jsafrane]

Another ideas:

• Add ListVolumes call before ControllerUnpublish, if it's supported by the CSI driver.