Repository: kubernetes-csi/external-attacher (go)

Issue:
Retry on attach error does not respect exponential backoff
Attacher version: v2.2.1
K8S version: 1.18

When ControllerPublishVolume call returns an error, attacher should requeue the VA and retry in an exponential backoff, if I understand correctly. On k8s prior to 1.18, this mechanism is respected.

However, on k8s whose version greater than 1.18, attacher behaves just like the following loop when attach error occurs:

pseudo-code:

```go
for j := 0; ; j++ {
    for i := 0; i < 10; i++ {
       if err := processVA(); err == nil {
       	    return
        }
       time.Sleep(time.Second)
    }
    time.Sleep(wait.Jitter(j*2*time.Minute))
}
```

In brief words, attacher retrys the VA processing for about ten times with interval≈1s, and stays idle for several minutes, and again begins dense retry, idle... until the ControllerPublishVolume call succeeds.

Here is a example (filtered logs from attacher)

```
$ kubectl -n kube-system logs csi-cdsplugin-controller-server-585f44b8d7-4rbnh -c csi-attacher | grep csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c | grep -E '(Start|Error|Fully)'
I1208 13:43:43.564088       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:43.564122       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:44.558764       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Unavailable desc = [39dacf1c-3a9e-4c09-b0df-2c12203a8e30] volume is not available for attaching, status: Creating
I1208 13:43:44.558802       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:44.558819       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:45.500493       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Unavailable desc = [85a699f7-eb4f-49db-9c2d-33a2d0b5a090] volume is not available for attaching, status: Creating
I1208 13:43:45.500514       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:45.500530       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:46.446287       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Unavailable desc = [6cd725ea-8d4c-49d7-8f2b-e999abc1b997] volume is not available for attaching, status: Creating
I1208 13:43:46.446317       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:46.446333       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:47.391840       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Unavailable desc = [2badb158-74e6-43ac-b387-220333fe2195] volume is not available for attaching, status: Creating
I1208 13:43:47.391860       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:47.391883       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:48.380912       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Unavailable desc = [e9b1ab52-0c36-46bb-82c0-e4fda0d31491] volume is not available for attaching, status: Creating
I1208 13:43:48.380950       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:48.380975       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:49.318782       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Unavailable desc = [6fae6a83-0273-4913-bb93-7e8ca5dea53f] volume is not available for attaching, status: Creating
I1208 13:43:49.318990       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:49.319011       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:50.274826       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Unavailable desc = [4c60d0be-4ebb-4550-8c8b-96c29d03694c] volume is not available for attaching, status: Creating
I1208 13:43:50.274847       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:50.274876       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:51.226678       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Unavailable desc = [8dd8827a-683d-4e59-aff5-8063e7bcf286] volume is not available for attaching, status: Creating
I1208 13:43:51.226699       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:51.226714       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:52.157179       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Unavailable desc = [ba6fb684-abe3-47dd-bb0b-ae5f28d49ce6] volume is not available for attaching, status: Creating
I1208 13:43:52.157197       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:52.157224       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:53.098529       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Unavailable desc = [c7d7cb46-673f-4ef8-a6fa-77075be1711b] volume is not available for attaching, status: Creating
I1208 13:43:53.098576       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:53.098592       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:54.074977       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Unavailable desc = [621ea846-2d05-4726-8af4-a6044a5c7953] volume is not available for attaching, status: Creating
I1208 13:43:54.075003       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:54.075020       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:43:54.992725       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Unavailable desc = [eb8df527-c940-4bb2-ac53-e7ff1d3513b7] volume is not available for attaching, status: Creating
I1208 13:45:59.226804       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:45:59.226842       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:46:00.809435       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Aborted desc = [cf78bfbc-9edd-4f80-91ea-e34be4182656] volume is attaching
I1208 13:46:00.809464       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:46:00.809479       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:46:02.196672       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Aborted desc = [dd50ac84-ee1c-4674-98b2-d3ba0491881c] volume is attaching
I1208 13:46:02.196983       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:46:02.197004       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:46:03.174379       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Aborted desc = [47ccc72d-fe2f-4bbc-b0f1-f0d6ffe09a30] volume is attaching
I1208 13:46:03.174398       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:46:03.174414       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:46:04.140333       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Aborted desc = [a1148f8b-df16-4530-89e4-33a93c7adbef] volume is attaching
I1208 13:46:04.140355       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:46:04.140370       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:46:05.055452       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Aborted desc = [8ebc54f3-232f-4d98-8d5f-72833ba1de0b] volume is attaching
I1208 13:46:05.055700       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:46:05.055716       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:46:05.978060       1 csi_handler.go:219] Error processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c": failed to attach: rpc error: code = Aborted desc = [827a95e5-faf8-44bb-af07-ae8b5166d0f2] volume is attaching
I1208 13:51:00.809627       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:51:00.809668       1 csi_handler.go:396] Starting attach operation for "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:51:01.793166       1 csi_handler.go:255] Fully attached "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:51:01.793481       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
I1208 13:52:24.446678       1 controller.go:198] Started VA processing "csi-799541531defa250c0078203727cf4a5215e24f06c0219e38e10bb8dfe17917c"
```

After some tracing, I found the `managedFields` added in 1.18 may be to blame, which breaks the [`shouldEnqueueVAChange`](https://github.com/kubernetes-csi/external-attacher/blob/642bf047b1bb70807f87a1e42ba53a1af36179c3/pkg/controller/controller.go#L276) logic:

```
// shouldEnqueueVAChange checks if a changed VolumeAttachment should be enqueued.
// It filters out changes in Status.Attach/DetachError - these were posted by the controller
// just few moments ago. If they were enqueued, Attach()/Detach() would be called again,
// breaking exponential backoff.
func shouldEnqueueVAChange(old, new *storage.VolumeAttachment) bool {
	if old.ResourceVersion == new.ResourceVersion {
		// This is most probably periodic sync, enqueue it
		return true
	}
	if new.Status.AttachError == nil && new.Status.DetachError == nil && old.Status.AttachError == nil && old.Status.DetachError == nil {
		// The difference between old and new must be elsewhere than Status.Attach/DetachError
		return true
	}

	sanitized := new.DeepCopy()
	sanitized.ResourceVersion = old.ResourceVersion
	sanitized.Status.AttachError = old.Status.AttachError
	sanitized.Status.DetachError = old.Status.DetachError

	if equality.Semantic.DeepEqual(old, sanitized) {
		// The objects are the same except Status.Attach/DetachError.
		// Don't enqueue them.
		return false
	}
	return true
}

```

This function is meant to check if a VA update is a change attacher should concern. It sanitizes the fields that is known setting by attacher itself before comparison to avoid unnecessary retry. However, for k8s greater than 1.18, the managedFields should also be sanitized since they would be updated by attacher after error occurs:

```yaml
apiVersion: storage.k8s.io/v1
kind: VolumeAttachment
metadata:
  annotations:
    csi.alpha.kubernetes.io/node-id: i-u4ihinLC
  creationTimestamp: "2021-12-08T14:10:06Z"
  finalizers:
  - external-attacher/csi-cdsplugin
  managedFields:
  - apiVersion: storage.k8s.io/v1
    fieldsType: FieldsV1
    fieldsV1:
      f:spec:
        f:attacher: {}
        f:nodeName: {}
        f:source:
          f:persistentVolumeName: {}
    manager: kube-controller-manager
    operation: Update
    time: "2021-12-08T14:10:06Z"
  - apiVersion: storage.k8s.io/v1beta1
    fieldsType: FieldsV1
    fieldsV1:
      f:metadata:
        f:annotations:
          .: {}
          f:csi.alpha.kubernetes.io/node-id: {}
        f:finalizers:
          .: {}
          v:"external-attacher/csi-cdsplugin": {}
      f:status:
        f:attached: {}
        f:attachmentMetadata:
          .: {}
          f:devName: {}
          f:serial: {}
    manager: csi-attacher
    operation: Update
    time: "2021-12-08T14:12:23Z"
  name: csi-c92894811af69850dd1f01af3f987d36d2ff8bce3856c03624834660c76dfaf9
```

And the first batch of retries exhaust the tokens in the bucket, so there's a long idle before another batch of retries.

One thing i didn't figure out yet:
The attacher stop the dense retry after a short period (~5-10 times), for the last retry within, what stops attacher from the next retry.

Pull request:
Skip processing of ManagedFields changes
<!--  Thanks for sending a pull request!  Here are some tips for you:

1. If this is your first time, please read our contributor guidelines: https://git.k8s.io/community/contributors/guide#your-first-contribution and developer guide https://git.k8s.io/community/contributors/devel/development.md#development-guide
2. Follow the instructions for writing a release note: https://git.k8s.io/community/contributors/guide/release-notes.md
3. If the PR is unfinished, see how to mark it: https://git.k8s.io/community/contributors/guide/pull-requests.md#marking-unfinished-pull-requests
-->

**What type of PR is this?**

> /kind bug

**What this PR does / why we need it**:

Respect exponential backoff when attach/detach error occurs.

**Which issue(s) this PR fixes**:
<!--
*Automatically closes linked issue when PR is merged.
Usage: `Fixes #<issue number>`, or `Fixes (paste link of issue)`.
_If PR is about `failing-tests or flakes`, please post the related issues/tests in a comment and do not use `Fixes`_*
-->
Fixes #337

**Special notes for your reviewer**:

**Does this PR introduce a user-facing change?**:
<!--
If no, just write "NONE" in the release-note block below.
If yes, a release note is required:
Enter your extended release note in the block below. If the PR requires additional action from users switching to the new release, include the string "action required".
-->
```release-note
NONE
```


Patch:
diff --git a/pkg/controller/controller.go b/pkg/controller/controller.go
index b17e064f..953f8bf3 100644
--- a/pkg/controller/controller.go
+++ b/pkg/controller/controller.go
@@ -291,6 +291,7 @@ func shouldEnqueueVAChange(old, new *storage.VolumeAttachment) bool {
 	sanitized.ResourceVersion = old.ResourceVersion
 	sanitized.Status.AttachError = old.Status.AttachError
 	sanitized.Status.DetachError = old.Status.DetachError
+	sanitized.ManagedFields = old.ManagedFields
 
 	if equality.Semantic.DeepEqual(old, sanitized) {
 		// The objects are the same except Status.Attach/DetachError.


Test patch:
diff --git a/pkg/controller/controller_test.go b/pkg/controller/controller_test.go
index 10a8c592..296f925a 100644
--- a/pkg/controller/controller_test.go
+++ b/pkg/controller/controller_test.go
@@ -73,6 +73,19 @@ func TestShouldEnqueueVAChange(t *testing.T) {
 		Time:    metav1.Time{},
 	}
 
+	va2AppendManagedFields := va1.DeepCopy()
+	va2AppendManagedFields.ResourceVersion = "2"
+	va2AppendManagedFields.ManagedFields = append(va2AppendManagedFields.ManagedFields,
+		metav1.ManagedFieldsEntry{
+			APIVersion: "storage.k8s.io/v1beta1",
+			Manager:    "csi-attacher",
+			Operation:  "Update",
+			FieldsType: "FieldsV1",
+			FieldsV1: &metav1.FieldsV1{
+				Raw: []byte(`{"f:metadata":{"f:annotations":{".":{},"f:csi.alpha.kubernetes.io/node-id":{}},"f:finalizers":{".":{},"v:\\\"external-attacher/csi-cdsplugin\\\"":{}}},"f:status":{"f:attached":{},"f:attachmentMetadata":{".":{},"f:devName":{},"f:serial":{}}}}`),
+			},
+		})
+
 	tests := []struct {
 		name           string
 		oldVA, newVA   *storage.VolumeAttachment
@@ -120,6 +133,12 @@ func TestShouldEnqueueVAChange(t *testing.T) {
 			newVA:          va2ChangedDetachError,
 			expectedResult: false,
 		},
+		{
+			name:           "appended managedFields",
+			oldVA:          va1,
+			newVA:          va2AppendManagedFields,
+			expectedResult: false,
+		},
 	}
 
 	for _, test := range tests {