1948555 – A lot of events "rpc error: code = DeadlineExceeded desc = context deadline exceeded" were seen in azure disk csi driver verification test

Bug 1948555 - A lot of events "rpc error: code = DeadlineExceeded desc = context deadline exceeded" were seen in azure disk csi driver verification test

Summary: A lot of events "rpc error: code = DeadlineExceeded desc = context deadline e...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	OpenShift Container Platform
Classification:	Red Hat
Component:	Storage
Sub Component:
Version:	4.8
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	medium
Target Milestone:	---
Target Release:	4.8.0
Assignee:	Fabio Bertinatto
QA Contact:	Qin Ping
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2021-04-12 12:38 UTC by Qin Ping
Modified:	2021-07-27 22:59 UTC (History)
CC List:	3 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2021-07-27 22:59:25 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Github	openshift azure-disk-csi-driver-operator pull 13	0	None	open	Bug 1948555: Set timeouts according to upstream	2021-04-14 13:47:29 UTC
Red Hat Product Errata	RHSA-2021:2438	0	None	None	None	2021-07-27 22:59:46 UTC

Description Qin Ping 2021-04-12 12:38:51 UTC

Description of problem:
When using csi verification test tool to test azure disk csi driver, saw a lot of event like:
Events:
  Type     Reason                  Age                From                     Message
  ----     ------                  ----               ----                     -------
  Normal   Scheduled               39s                default-scheduler        Successfully assigned e2e-multivolume-2730/pod-15cba685-0bbc-4afa-a01b-7b3fed3d0193 to piqin-0412-z8dh9-worker-northcentralus-8jdwx
  Warning  FailedAttachVolume      13s (x5 over 23s)  attachdetach-controller  AttachVolume.Attach failed for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" : rpc error: code = DeadlineExceeded desc = context deadline exceeded
  Warning  FailedAttachVolume      5s (x6 over 23s)   attachdetach-controller  AttachVolume.Attach failed for volume "pvc-1ddaf3eb-23c1-4a72-86f7-cc3dbf79e465" : rpc error: code = DeadlineExceeded desc = context deadline exceeded
  Normal   SuccessfulAttachVolume  5s                 attachdetach-controller  AttachVolume.Attach succeeded for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4"



Version-Release number of selected component (if applicable):
4.8.0-0.nightly-2021-04-09-222447

How reproducible:

Steps to Reproduce:
1.
2.
3.

Actual results:
Checked the kube-controller-manager log:
[piqin@preserve-storage-server1 ~]$ oc -n openshift-kube-controller-manager logs kube-controller-manager-piqin-0412-z8dh9-master-0|grep pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4|grep -i attach
I0412 12:21:30.612154       1 reconciler.go:295] attacherDetacher.AttachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") from node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
E0412 12:21:46.207525       1 csi_attacher.go:698] kubernetes.io/csi: attachment for /subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4 failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
E0412 12:21:46.207697       1 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4 podName: nodeName:}" failed. No retries permitted until 2021-04-12 12:21:46.707645641 +0000 UTC m=+18040.946811881 (durationBeforeRetry 500ms). Error: "AttachVolume.Attach failed for volume \"pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\" (UniqueName: \"kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\") from node \"piqin-0412-z8dh9-worker-northcentralus-8jdwx\" : rpc error: code = DeadlineExceeded desc = context deadline exceeded"
I0412 12:21:46.207803       1 event.go:291] "Event occurred" object="e2e-multivolume-2730/pod-15cba685-0bbc-4afa-a01b-7b3fed3d0193" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\" : rpc error: code = DeadlineExceeded desc = context deadline exceeded"
I0412 12:21:46.734422       1 reconciler.go:295] attacherDetacher.AttachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") from node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
E0412 12:21:47.278010       1 csi_attacher.go:698] kubernetes.io/csi: attachment for /subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4 failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0412 12:21:47.278044       1 actual_state_of_world.go:350] Volume "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" is already added to attachedVolume list to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx", update device path ""
E0412 12:21:47.278140       1 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4 podName: nodeName:}" failed. No retries permitted until 2021-04-12 12:21:48.278108804 +0000 UTC m=+18042.517275044 (durationBeforeRetry 1s). Error: "AttachVolume.Attach failed for volume \"pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\" (UniqueName: \"kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\") from node \"piqin-0412-z8dh9-worker-northcentralus-8jdwx\" : rpc error: code = DeadlineExceeded desc = context deadline exceeded"
I0412 12:21:47.278227       1 event.go:291] "Event occurred" object="e2e-multivolume-2730/pod-15cba685-0bbc-4afa-a01b-7b3fed3d0193" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\" : rpc error: code = DeadlineExceeded desc = context deadline exceeded"
I0412 12:21:48.344953       1 reconciler.go:295] attacherDetacher.AttachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") from node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
E0412 12:21:48.891491       1 csi_attacher.go:698] kubernetes.io/csi: attachment for /subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4 failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0412 12:21:48.891553       1 actual_state_of_world.go:350] Volume "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" is already added to attachedVolume list to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx", update device path ""
E0412 12:21:48.891730       1 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4 podName: nodeName:}" failed. No retries permitted until 2021-04-12 12:21:50.891678612 +0000 UTC m=+18045.130844952 (durationBeforeRetry 2s). Error: "AttachVolume.Attach failed for volume \"pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\" (UniqueName: \"kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\") from node \"piqin-0412-z8dh9-worker-northcentralus-8jdwx\" : rpc error: code = DeadlineExceeded desc = context deadline exceeded"
I0412 12:21:48.891826       1 event.go:291] "Event occurred" object="e2e-multivolume-2730/pod-15cba685-0bbc-4afa-a01b-7b3fed3d0193" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\" : rpc error: code = DeadlineExceeded desc = context deadline exceeded"
I0412 12:21:50.964350       1 reconciler.go:295] attacherDetacher.AttachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") from node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
E0412 12:21:51.518088       1 csi_attacher.go:698] kubernetes.io/csi: attachment for /subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4 failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0412 12:21:51.518135       1 actual_state_of_world.go:350] Volume "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" is already added to attachedVolume list to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx", update device path ""
E0412 12:21:51.518320       1 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4 podName: nodeName:}" failed. No retries permitted until 2021-04-12 12:21:55.518236809 +0000 UTC m=+18049.757403149 (durationBeforeRetry 4s). Error: "AttachVolume.Attach failed for volume \"pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\" (UniqueName: \"kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\") from node \"piqin-0412-z8dh9-worker-northcentralus-8jdwx\" : rpc error: code = DeadlineExceeded desc = context deadline exceeded"
I0412 12:21:51.518383       1 event.go:291] "Event occurred" object="e2e-multivolume-2730/pod-15cba685-0bbc-4afa-a01b-7b3fed3d0193" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\" : rpc error: code = DeadlineExceeded desc = context deadline exceeded"
I0412 12:21:55.592279       1 reconciler.go:295] attacherDetacher.AttachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") from node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
E0412 12:21:56.141228       1 csi_attacher.go:698] kubernetes.io/csi: attachment for /subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4 failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0412 12:21:56.141278       1 actual_state_of_world.go:350] Volume "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" is already added to attachedVolume list to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx", update device path ""
E0412 12:21:56.141396       1 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4 podName: nodeName:}" failed. No retries permitted until 2021-04-12 12:22:04.141364091 +0000 UTC m=+18058.380530331 (durationBeforeRetry 8s). Error: "AttachVolume.Attach failed for volume \"pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\" (UniqueName: \"kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\") from node \"piqin-0412-z8dh9-worker-northcentralus-8jdwx\" : rpc error: code = DeadlineExceeded desc = context deadline exceeded"
I0412 12:21:56.141504       1 event.go:291] "Event occurred" object="e2e-multivolume-2730/pod-15cba685-0bbc-4afa-a01b-7b3fed3d0193" kind="Pod" apiVersion="v1" type="Warning" reason="FailedAttachVolume" message="AttachVolume.Attach failed for volume \"pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\" : rpc error: code = DeadlineExceeded desc = context deadline exceeded"
I0412 12:22:04.158521       1 reconciler.go:295] attacherDetacher.AttachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") from node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
I0412 12:22:04.694228       1 operation_generator.go:368] AttachVolume.Attach succeeded for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") from node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
I0412 12:22:04.694309       1 actual_state_of_world.go:350] Volume "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" is already added to attachedVolume list to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx", update device path ""
I0412 12:22:04.694424       1 event.go:291] "Event occurred" object="e2e-multivolume-2730/pod-15cba685-0bbc-4afa-a01b-7b3fed3d0193" kind="Pod" apiVersion="v1" type="Normal" reason="SuccessfulAttachVolume" message="AttachVolume.Attach succeeded for volume \"pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4\" "
I0412 12:23:12.794719       1 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") on node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
E0412 12:23:28.294267       1 csi_attacher.go:713] kubernetes.io/csi: detachment for VolumeAttachment for volume [/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4] failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0412 12:23:28.831614       1 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") on node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
E0412 12:23:29.404720       1 csi_attacher.go:713] kubernetes.io/csi: detachment for VolumeAttachment for volume [/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4] failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0412 12:23:30.482325       1 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") on node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
E0412 12:23:31.036420       1 csi_attacher.go:713] kubernetes.io/csi: detachment for VolumeAttachment for volume [/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4] failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0412 12:23:33.042784       1 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") on node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
E0412 12:23:33.616369       1 csi_attacher.go:713] kubernetes.io/csi: detachment for VolumeAttachment for volume [/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4] failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0412 12:23:37.709010       1 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") on node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
E0412 12:23:38.259091       1 csi_attacher.go:713] kubernetes.io/csi: detachment for VolumeAttachment for volume [/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4] failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0412 12:23:46.321189       1 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") on node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 
E0412 12:23:46.906775       1 csi_attacher.go:713] kubernetes.io/csi: detachment for VolumeAttachment for volume [/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4] failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0412 12:24:02.973705       1 reconciler.go:219] attacherDetacher.DetachVolume started for volume "pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4" (UniqueName: "kubernetes.io/csi/disk.csi.azure.com^/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-b5e656bb-01bb-4ce5-bf11-ad04c46492a4") on node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" 

Check external csi attacher log:
[piqin@preserve-storage-server1 azure]$ oc -n openshift-cluster-csi-drivers  logs azure-disk-csi-driver-controller-7d95c9f67b-79c2q -c csi-driver|grep pvc-6c949e01-f463-45d0-9842-e322811d27f2|grep -i attach
I0412 12:08:10.605638       1 controllerserver.go:391] GetDiskLun returned: <nil>. Initiating attaching volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx".
I0412 12:08:10.741585       1 controllerserver.go:406] Trying to attach volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx"
I0412 12:08:25.615951       1 controllerserver.go:391] GetDiskLun returned: <nil>. Initiating attaching volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx".
I0412 12:08:25.615999       1 controllerserver.go:406] Trying to attach volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx"
I0412 12:08:25.641744       1 azure_controller_common.go:248] azureDisk - duplicated attach disk(/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourcegroups/piqin-0412-z8dh9-rg/providers/microsoft.compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2) request on node(piqin-0412-z8dh9-worker-northcentralus-8jdwx)
I0412 12:08:26.437658       1 azure_controller_common.go:222] Trying to attach volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" lun 1 to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx", diskMap: map[/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourcegroups/piqin-0412-z8dh9-rg/providers/microsoft.compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2:%!s(*azure.AttachDiskOptions=&{1 true pvc-6c949e01-f463-45d0-9842-e322811d27f2 ReadOnly  false})]
I0412 12:08:26.437730       1 azure_controller_standard.go:107] azureDisk - update(piqin-0412-z8dh9-rg): vm(piqin-0412-z8dh9-worker-northcentralus-8jdwx) - attach disk list(map[/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourcegroups/piqin-0412-z8dh9-rg/providers/microsoft.compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2:%!s(*azure.AttachDiskOptions=&{1 true pvc-6c949e01-f463-45d0-9842-e322811d27f2 ReadOnly  false})])
I0412 12:08:40.632916       1 controllerserver.go:391] GetDiskLun returned: <nil>. Initiating attaching volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx".
I0412 12:08:40.633097       1 controllerserver.go:406] Trying to attach volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx"
I0412 12:08:40.657126       1 azure_controller_common.go:169] found dangling volume /subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2 attached to node piqin-0412-z8dh9-worker-northcentralus-8jdwx
W0412 12:08:40.657173       1 controllerserver.go:413] volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" is already attached to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx", try detach first
I0412 12:08:41.854373       1 azure_controller_standard.go:127] azureDisk - update(piqin-0412-z8dh9-rg): vm(piqin-0412-z8dh9-worker-northcentralus-8jdwx) - attach disk list(map[/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourcegroups/piqin-0412-z8dh9-rg/providers/microsoft.compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2:%!s(*azure.AttachDiskOptions=&{1 true pvc-6c949e01-f463-45d0-9842-e322811d27f2 ReadOnly  false})]) returned with <nil>
I0412 12:08:41.854436       1 controllerserver.go:410] Attach operation successful: volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" attached to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx".
I0412 12:08:41.854451       1 controllerserver.go:425] attach volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" successfully
I0412 12:08:41.882309       1 azure_controller_common.go:222] Trying to attach volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" lun 1 to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx", diskMap: map[]
I0412 12:08:41.882355       1 controllerserver.go:410] Attach operation successful: volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" attached to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx".
I0412 12:08:41.882375       1 controllerserver.go:425] attach volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" successfully
I0412 12:08:55.643086       1 controllerserver.go:391] GetDiskLun returned: <nil>. Initiating attaching volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx".
I0412 12:08:55.643137       1 controllerserver.go:400] Attach operation is successful. volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" is already attached to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" at lun 1.
I0412 12:08:57.240317       1 controllerserver.go:417] Trying to attach volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" again
I0412 12:09:02.727084       1 azure_controller_common.go:222] Trying to attach volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" lun 1 to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx", diskMap: map[/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourcegroups/piqin-0412-z8dh9-rg/providers/microsoft.compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2:%!s(*azure.AttachDiskOptions=&{1 true pvc-6c949e01-f463-45d0-9842-e322811d27f2 ReadOnly  false})]
I0412 12:09:02.727155       1 azure_controller_standard.go:107] azureDisk - update(piqin-0412-z8dh9-rg): vm(piqin-0412-z8dh9-worker-northcentralus-8jdwx) - attach disk list(map[/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourcegroups/piqin-0412-z8dh9-rg/providers/microsoft.compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2:%!s(*azure.AttachDiskOptions=&{1 true pvc-6c949e01-f463-45d0-9842-e322811d27f2 ReadOnly  false})])
I0412 12:09:13.100431       1 azure_controller_standard.go:127] azureDisk - update(piqin-0412-z8dh9-rg): vm(piqin-0412-z8dh9-worker-northcentralus-8jdwx) - attach disk list(map[/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourcegroups/piqin-0412-z8dh9-rg/providers/microsoft.compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2:%!s(*azure.AttachDiskOptions=&{1 true pvc-6c949e01-f463-45d0-9842-e322811d27f2 ReadOnly  false})]) returned with <nil>
I0412 12:09:13.100492       1 controllerserver.go:425] attach volume "/subscriptions/53b8f551-f0fc-4bea-8cba-6d1fefd54c8a/resourceGroups/piqin-0412-z8dh9-rg/providers/Microsoft.Compute/disks/pvc-6c949e01-f463-45d0-9842-e322811d27f2" to node "piqin-0412-z8dh9-worker-northcentralus-8jdwx" successfully



Expected results:
Didn't see other storage drivers/plugins have so many similar events, and from the log, looks like reports "context deadline exceeded" error every second, a little weird.

Master Log:

Node Log (of failed PODs):

PV Dump:

PVC Dump:

StorageClass Dump (if StorageClass used by PV/PVC):

Additional info:

Comment 3 Fabio Bertinatto 2021-04-22 13:19:16 UTC

It seems like adjusting the timeouts of the sidecars [0] has helped. I looked at this mustgather [1] from a recent test run I was unable to find those errors.

There are still things to fix in the Azure CSI Driver (namely snapshots), but I believe this issue is resolved for now. 

[0] https://github.com/openshift/azure-disk-csi-driver-operator/pull/13
[1] https://gcsweb-ci.apps.ci.l2s4.p1.openshiftapps.com/gcs/origin-ci-test/pr-logs/pull/openshift_azure-disk-csi-driver-operator/16/pull-ci-openshift-azure-disk-csi-driver-operator-master-e2e-azure-csi/1384810087981256704/artifacts/e2e-azure-csi/gather-must-gather/artifacts/

Comment 5 Qin Ping 2021-04-24 12:19:09 UTC

Verified with: 4.8.0-0.nightly-2021-04-22-182303

Comment 8 errata-xmlrpc 2021-07-27 22:59:25 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Moderate: OpenShift Container Platform 4.8.2 bug fix and security update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2021:2438

Note You need to log in before you can comment on or make changes to this bug.