fix(controller): Fix race of csi controller calls on the same volume #588

Lucaber · 2024-09-17T15:39:46Z

Why is this PR required? What issue does it fix?:

When a CreateVolume requests takes longer then 10 seconds the request runs into a client-side timeout and gets retied by kubelet. While processing the new request, the old request is still being canceled on the server-side and the created ZFSVolume CR gets deleted.

1	2
CreateVolume call
ZFSVolume CR created
waiting for volume creation
client timeout + context cancel
	CreateVolume call
	ZFSVolume CR already exists
ZFSVolume CR deleted
Return ERR	Return OK without creating a ZFSVolume

I0916 15:01:49.227721       1 grpc.go:72] GRPC call: /csi.v1.Controller/CreateVolume requests {"accessibility_requirements":{"preferred":[{"segments":{"beta.kubernetes.io/arch":"amd64","beta.kubernetes.io/os":"linux","kubernetes.io/arch":"amd64","kubernetes.io/hostname":"i04-1-b-node-i041b-0-0","kubernetes.io/os":"linux","m3.services/cluster":"i04-1-b","m3.services/worker-group":"i041b-0","node.systems.mittwald.cloud/placement-group":"i041b-0","openebs.io/nodeid":"i04-1-b-node-i041b-0-0","openebs.io/nodename":"i04-1-b-node-i041b-0-0"}}],"requisite":[{"segments":{"beta.kubernetes.io/arch":"amd64","beta.kubernetes.io/os":"linux","kubernetes.io/arch":"amd64","kubernetes.io/hostname":"i04-1-b-node-i041b-0-0","kubernetes.io/os":"linux","m3.services/cluster":"i04-1-b","m3.services/worker-group":"i041b-0","node.systems.mittwald.cloud/placement-group":"i041b-0","openebs.io/nodeid":"i04-1-b-node-i041b-0-0","openebs.io/nodename":"i04-1-b-node-i041b-0-0"}}]},"capacity_range":{"required_bytes":5368709120},"name":"pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457","parameters":{"compression":"off","csi.storage.k8s.io/pv/name":"pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457","csi.storage.k8s.io/pvc/name":"test-pvc0","csi.storage.k8s.io/pvc/namespace":"default","dedup":"off","fstype":"zfs","poolname":"kluster-pool/i04-1-b-128k","recordsize":"128k","shared":"yes","thinprovision":"yes"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"zfs"}},"access_mode":{"mode":1}}]}
I0916 15:01:58.853180       1 controller.go:289] zfs: trying volume creation kluster-pool/i04-1-b-128k/pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457 on node [i04-1-b-node-i041b-0-0]
I0916 15:01:59.104207       1 volume.go:139] zfs: waiting for volume kluster-pool/i04-1-b-128k/pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457 to be created on nodeid i04-1-b-node-i041b-0-0
I0916 15:02:00.105273       1 volume.go:170] zfs: volume kluster-pool/i04-1-b-128k/pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457 provisioning failed on nodeid i04-1-b-node-i041b-0-0 err: zfs: context deadline reached
I0916 15:02:00.235113       1 grpc.go:72] GRPC call: /csi.v1.Controller/CreateVolume requests {"accessibility_requirements":{"preferred":[{"segments":{"beta.kubernetes.io/arch":"amd64","beta.kubernetes.io/os":"linux","kubernetes.io/arch":"amd64","kubernetes.io/hostname":"i04-1-b-node-i041b-0-0","kubernetes.io/os":"linux","m3.services/cluster":"i04-1-b","m3.services/worker-group":"i041b-0","node.systems.mittwald.cloud/placement-group":"i041b-0","openebs.io/nodeid":"i04-1-b-node-i041b-0-0","openebs.io/nodename":"i04-1-b-node-i041b-0-0"}}],"requisite":[{"segments":{"beta.kubernetes.io/arch":"amd64","beta.kubernetes.io/os":"linux","kubernetes.io/arch":"amd64","kubernetes.io/hostname":"i04-1-b-node-i041b-0-0","kubernetes.io/os":"linux","m3.services/cluster":"i04-1-b","m3.services/worker-group":"i041b-0","node.systems.mittwald.cloud/placement-group":"i041b-0","openebs.io/nodeid":"i04-1-b-node-i041b-0-0","openebs.io/nodename":"i04-1-b-node-i041b-0-0"}}]},"capacity_range":{"required_bytes":5368709120},"name":"pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457","parameters":{"compression":"off","csi.storage.k8s.io/pv/name":"pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457","csi.storage.k8s.io/pvc/name":"test-pvc0","csi.storage.k8s.io/pvc/namespace":"default","dedup":"off","fstype":"zfs","poolname":"kluster-pool/i04-1-b-128k","recordsize":"128k","shared":"yes","thinprovision":"yes"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"zfs"}},"access_mode":{"mode":1}}]}
I0916 15:02:00.449153       1 volume.go:221] zfs: deleted the volume pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457
I0916 15:02:00.449299       1 controller.go:466] created the volume kluster-pool/i04-1-b-128k/pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457 on node i04-1-b-node-i041b-0-0
I0916 15:02:00.553778       1 grpc.go:81] GRPC response: {"volume":{"accessible_topology":[{"segments":{"openebs.io/nodeid":"i04-1-b-node-i041b-0-0"}}],"capacity_bytes":5368709120,"volume_context":{"openebs.io/cas-type":"localpv-zfs","openebs.io/poolname":"kluster-pool/i04-1-b-128k"},"volume_id":"pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457"}}

What this PR does?: Adds a per volume mutex to csi calls to prevent simultaneous requests

Does this PR require any upgrade changes?: No

If the changes in this PR are manually verified, list down the scenarios covered::

Any additional information for your reviewer? :
Mention if this PR is part of any design or a continuation of previous PRs

Checklist:

Fixes #
PR Title follows the convention of <type>(<scope>): <subject>
Has the change log section been updated?
Commit has unit tests
Commit has integration tests
(Optional) Are upgrade changes included in this PR? If not, mention the issue/PR to track:
(Optional) If documentation changes are required, which issue on https://github.com/openebs/website is used to track them:

When a CreateVolume requests takes longer then 10 seconds the request runs into a client-side timeout and gets retied by kubelet. While processing the new request, the old request is still being canceled on the server-side and the created ZFSVolume CR gets deleted. 1|2 CreateVolume| ZFSVolume CR created| waiting for volume creation| client timeout + context cancel| |CreateVolume |ZFSVolume CR already exists ZFSVolume CR deleted| Return ERR|Return OK without creating a ZFSVolume ``` I0916 15:01:49.227721 1 grpc.go:72] GRPC call: /csi.v1.Controller/CreateVolume requests {"accessibility_requirements":{"preferred":[{"segments":{"beta.kubernetes.io/arch":"amd64","beta.kubernetes.io/os":"linux","kubernetes.io/arch":"amd64","kubernetes.io/hostname":"i04-1-b-node-i041b-0-0","kubernetes.io/os":"linux","m3.services/cluster":"i04-1-b","m3.services/worker-group":"i041b-0","node.systems.mittwald.cloud/placement-group":"i041b-0","openebs.io/nodeid":"i04-1-b-node-i041b-0-0","openebs.io/nodename":"i04-1-b-node-i041b-0-0"}}],"requisite":[{"segments":{"beta.kubernetes.io/arch":"amd64","beta.kubernetes.io/os":"linux","kubernetes.io/arch":"amd64","kubernetes.io/hostname":"i04-1-b-node-i041b-0-0","kubernetes.io/os":"linux","m3.services/cluster":"i04-1-b","m3.services/worker-group":"i041b-0","node.systems.mittwald.cloud/placement-group":"i041b-0","openebs.io/nodeid":"i04-1-b-node-i041b-0-0","openebs.io/nodename":"i04-1-b-node-i041b-0-0"}}]},"capacity_range":{"required_bytes":5368709120},"name":"pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457","parameters":{"compression":"off","csi.storage.k8s.io/pv/name":"pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457","csi.storage.k8s.io/pvc/name":"test-pvc0","csi.storage.k8s.io/pvc/namespace":"default","dedup":"off","fstype":"zfs","poolname":"kluster-pool/i04-1-b-128k","recordsize":"128k","shared":"yes","thinprovision":"yes"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"zfs"}},"access_mode":{"mode":1}}]} I0916 15:01:58.853180 1 controller.go:289] zfs: trying volume creation kluster-pool/i04-1-b-128k/pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457 on node [i04-1-b-node-i041b-0-0] I0916 15:01:59.104207 1 volume.go:139] zfs: waiting for volume kluster-pool/i04-1-b-128k/pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457 to be created on nodeid i04-1-b-node-i041b-0-0 I0916 15:02:00.105273 1 volume.go:170] zfs: volume kluster-pool/i04-1-b-128k/pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457 provisioning failed on nodeid i04-1-b-node-i041b-0-0 err: zfs: context deadline reached I0916 15:02:00.235113 1 grpc.go:72] GRPC call: /csi.v1.Controller/CreateVolume requests {"accessibility_requirements":{"preferred":[{"segments":{"beta.kubernetes.io/arch":"amd64","beta.kubernetes.io/os":"linux","kubernetes.io/arch":"amd64","kubernetes.io/hostname":"i04-1-b-node-i041b-0-0","kubernetes.io/os":"linux","m3.services/cluster":"i04-1-b","m3.services/worker-group":"i041b-0","node.systems.mittwald.cloud/placement-group":"i041b-0","openebs.io/nodeid":"i04-1-b-node-i041b-0-0","openebs.io/nodename":"i04-1-b-node-i041b-0-0"}}],"requisite":[{"segments":{"beta.kubernetes.io/arch":"amd64","beta.kubernetes.io/os":"linux","kubernetes.io/arch":"amd64","kubernetes.io/hostname":"i04-1-b-node-i041b-0-0","kubernetes.io/os":"linux","m3.services/cluster":"i04-1-b","m3.services/worker-group":"i041b-0","node.systems.mittwald.cloud/placement-group":"i041b-0","openebs.io/nodeid":"i04-1-b-node-i041b-0-0","openebs.io/nodename":"i04-1-b-node-i041b-0-0"}}]},"capacity_range":{"required_bytes":5368709120},"name":"pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457","parameters":{"compression":"off","csi.storage.k8s.io/pv/name":"pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457","csi.storage.k8s.io/pvc/name":"test-pvc0","csi.storage.k8s.io/pvc/namespace":"default","dedup":"off","fstype":"zfs","poolname":"kluster-pool/i04-1-b-128k","recordsize":"128k","shared":"yes","thinprovision":"yes"},"volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"zfs"}},"access_mode":{"mode":1}}]} I0916 15:02:00.449153 1 volume.go:221] zfs: deleted the volume pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457 I0916 15:02:00.449299 1 controller.go:466] created the volume kluster-pool/i04-1-b-128k/pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457 on node i04-1-b-node-i041b-0-0 I0916 15:02:00.553778 1 grpc.go:81] GRPC response: {"volume":{"accessible_topology":[{"segments":{"openebs.io/nodeid":"i04-1-b-node-i041b-0-0"}}],"capacity_bytes":5368709120,"volume_context":{"openebs.io/cas-type":"localpv-zfs","openebs.io/poolname":"kluster-pool/i04-1-b-128k"},"volume_id":"pvc-eb11c446-f26c-4333-b3da-4ecb9c5b2457"}} ``` Signed-off-by: Luca Berneking <[email protected]>

codecov-commenter · 2024-09-21T18:01:29Z

⚠️ Please install the to ensure uploads and comments are reliably processed by Codecov.

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 96.37%. Comparing base (e3d55d7) to head (0521ba4).
Report is 2 commits behind head on develop.

❗ Your organization needs to install the Codecov GitHub app to enable full functionality.

Additional details and impacted files

@@           Coverage Diff            @@
##           develop     #588   +/-   ##
========================================
  Coverage    96.37%   96.37%           
========================================
  Files            1        1           
  Lines          496      496           
========================================
  Hits           478      478           
  Misses          14       14           
  Partials         4        4

Flag	Coverage Δ
bddtests	`96.37% <ø> (ø)`

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

niladrih · 2024-09-25T10:40:37Z

Hmm... this is upsetting. I suppose all of the tests on our Go repos need to use the -race flag on CI pipeline.
I've created this ticket: openebs/openebs#3784

tiagolobocastro

Thanks!
I wonder if we're missing this in other places...

tiagolobocastro · 2024-09-25T11:10:09Z

pkg/driver/controller.go

@@ -705,6 +722,10 @@ func (cs *controller) CreateSnapshot(
 	if err != nil {
 		return nil, err
 	}
+	unlockVol := cs.LockVolume(volumeID)


ok for now but if we have more uses of the volume&snapshot, might be worth having a function to lock, ensuring the locks are always taken in the same order to avoid deadlock

Good point, added a new function LockVolumeWithSnapshot

tiagolobocastro · 2024-09-25T11:43:24Z

pkg/driver/controller.go

+}
+
+func (cs *controller) LockVolume(volume string) func() {
+	value, _ := cs.volMutexes.LoadOrStore(volume, &sync.Mutex{})


Just wondering, are entries automatically GC'd?
Otherwise this may grow "forever" ?

No, they are not getting GC'd. The Mutex can only be removed from the Map if there are no other references to the Mutex. Im not sure if this relatively small leak (the volume string key is probably larger than the mutex) is worth the additional complexity.

Well, it might grow to large extents? Also what about deleleted volume, the entries for them will also stay in the map right?

Seems most drivers on kubernetes-csi actually use the same exact implementation: https://github.com/kubernetes-sigs/gcp-compute-persistent-disk-csi-driver/blob/master/pkg/common/volume_lock.go
Which handles it by not using N locks but rather keep a list of volumes and deleting the volume entry.

They are handling it a bit different, instead of waiting for the lock, the csi call errors instantly with An operation with the given Volume ID %s already exists https://github.com/kubernetes-sigs/gcp-compute-persistent-disk-csi-driver/blob/master/pkg/gce-pd-csi-driver/node.go#L140

Yeah guess we'd need to do the same here as well. Perhaps that's also a better approach, letting the caller retry.
Should we use this new way instead? @Lucaber @Abhinandan-Purkait

I have looked at a few different Implementations. TopoLVM also uses a single map to add and remove keys but using a sync.Cond that locks the second concurrent call like my implementation: https://github.com/topolvm/topolvm/blob/main/internal/driver/lock.go This seems to be the best way to handle this.

Alternatively we could also use the keymutex implementation by kubernetes that used a few mutexes which are being shared between volumes. But this would require special handling to ensure that the snapshot and parent volume are using different mutexes (to prevent deadlocking). https://github.com/kubernetes/utils/blob/master/keymutex/hashed.go

The topolvm one looks reasonable, wdyt?

Lucaber · 2024-09-25T11:46:51Z

Hmm... this is upsetting. I suppose all of the tests on our Go repos need to use the -race flag on CI pipeline. I've created this ticket: openebs/openebs#3784

This isn't a go data race, -race can't detect this issue.
To reproduce this issue I created 50 PVCs with WaitForFirstConsumer and then started a single pod with all 50 volumes to create a high load on both kubelet and openebs.

Signed-off-by: Luca Berneking <[email protected]>

Abhinandan-Purkait requested review from tiagolobocastro, avishnu, sinhaashish, Abhinandan-Purkait and niladrih September 21, 2024 16:51

Abhinandan-Purkait approved these changes Sep 25, 2024

View reviewed changes

tiagolobocastro approved these changes Sep 25, 2024

View reviewed changes

tiagolobocastro reviewed Sep 25, 2024

View reviewed changes

Lucaber force-pushed the fix/controller-csi-race branch from 3b0f7ee to d2e4509 Compare September 25, 2024 12:14

Add LockVolumeWithSnapshot function to prevent future deadlocks

32b9de3

Signed-off-by: Luca Berneking <[email protected]>

Lucaber force-pushed the fix/controller-csi-race branch from d2e4509 to 32b9de3 Compare September 25, 2024 12:42

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix(controller): Fix race of csi controller calls on the same volume #588

fix(controller): Fix race of csi controller calls on the same volume #588

Lucaber commented Sep 17, 2024 •

edited

Loading

codecov-commenter commented Sep 21, 2024

niladrih commented Sep 25, 2024 •

edited

Loading

tiagolobocastro left a comment

tiagolobocastro Sep 25, 2024

Lucaber Sep 25, 2024

tiagolobocastro Sep 25, 2024

Lucaber Sep 25, 2024

Abhinandan-Purkait Sep 25, 2024

tiagolobocastro Sep 25, 2024

Lucaber Sep 25, 2024

tiagolobocastro Sep 25, 2024

Lucaber Sep 25, 2024

Abhinandan-Purkait Sep 30, 2024

Lucaber commented Sep 25, 2024

fix(controller): Fix race of csi controller calls on the same volume #588

Are you sure you want to change the base?

fix(controller): Fix race of csi controller calls on the same volume #588

Conversation

Lucaber commented Sep 17, 2024 • edited Loading

codecov-commenter commented Sep 21, 2024

Codecov Report

niladrih commented Sep 25, 2024 • edited Loading

tiagolobocastro left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Lucaber commented Sep 25, 2024

Lucaber commented Sep 17, 2024 •

edited

Loading

niladrih commented Sep 25, 2024 •

edited

Loading