rbd creating multiple images in the backend for single PVC #426

Madhu-1 · 2019-06-12T12:17:44Z

Describe the bug

rbd creating multiple images in the backend for single PVC

Environment details

Image/version of Ceph CSI driver (canary)
helm chart version
Kubernetes cluster version (1.14.1)
Logs

Steps to reproduce

deploy rbdplugin
create/delete multiple PVC
check rbd ls output

Actual results

rbd is creating multiple images in the backend for single PVC
Describe what happened

create and deleted an rbd PVC (dint see any issue) once I recreated an rbd PVC am seeing 3 rbd images in the backend

Expected behavior

rbd ls should show a single image for PVC
A clear and concise description of what you expected to happen.

Logs
PVC output

[🎩]mrajanna@localhost rbd $]kubectl create -f pvc.yaml 
persistentvolumeclaim/rbd-pvc created
[🎩]mrajanna@localhost rbd $]kubectl get pvc
NAME      STATUS    VOLUME   CAPACITY   ACCESS MODES   STORAGECLASS   AGE
rbd-pvc   Pending                                      csi-rbd-sc     3s
[🎩]mrajanna@localhost rbd $]kubectl get pvc
NAME      STATUS   VOLUME                                     CAPACITY   ACCESS MODES   STORAGECLASS   AGE
rbd-pvc   Bound    pvc-d4cdddf5-8d0a-11e9-b1d0-525400709fd9   1Gi        RWO            csi-rbd-sc     4s
[🎩]mrajanna@localhost rbd $]
[🎩]mrajanna@localhost rbd $]kubectl delete -f pvc.yaml 
persistentvolumeclaim "rbd-pvc" deleted
[🎩]mrajanna@localhost rbd $]kubectl create -f snapshotclass.yaml 
volumesnapshotclass.snapshot.storage.k8s.io/csi-rbdplugin-snapclass created
[🎩]mrajanna@localhost rbd $]kubectl create -f pvc.yaml 
persistentvolumeclaim/rbd-pvc created
[🎩]mrajanna@localhost rbd $]kubectl get pvc
NAME      STATUS   VOLUME                                     CAPACITY   ACCESS MODES   STORAGECLASS   AGE
rbd-pvc   Bound    pvc-0741bb29-8d0b-11e9-b1d0-525400709fd9   1Gi        RWO            csi-rbd-sc     66s
[🎩]mrajanna@localhost rbd $]kubectl get pv
NAME                                       CAPACITY   ACCESS MODES   RECLAIM POLICY   STATUS   CLAIM             STORAGECLASS   REASON   AGE
pvc-0741bb29-8d0b-11e9-b1d0-525400709fd9   1Gi        RWO            Delete           Bound    default/rbd-pvc   csi-rbd-sc              63s

rbd ls output

[root@worker0 /]# rbd ls
csi-vol-d4f8d412-8d0a-11e9-90fe-a298890739d8
[root@worker0 /]# rbd ls
csi-vol-d4f8d412-8d0a-11e9-90fe-a298890739d8
[root@worker0 /]# rbd ls
csi-vol-d4f8d412-8d0a-11e9-90fe-a298890739d8
[root@worker0 /]# rbd ls
csi-vol-d4f8d412-8d0a-11e9-90fe-a298890739d8
[root@worker0 /]# rbd ls
csi-vol-d4f8d412-8d0a-11e9-90fe-a298890739d8
[root@worker0 /]# rbd ls
csi-vol-d4f8d412-8d0a-11e9-90fe-a298890739d8
[root@worker0 /]# rbd ls
csi-vol-d4f8d412-8d0a-11e9-90fe-a298890739d8
[root@worker0 /]# rbd info csi-vol-d4f8d412-8d0a-11e9-90fe-a298890739d8
rbd image 'csi-vol-d4f8d412-8d0a-11e9-90fe-a298890739d8':
	size 1 GiB in 256 objects
	order 22 (4 MiB objects)
	snapshot_count: 0
	id: 11b289bbb304
	block_name_prefix: rbd_data.11b289bbb304
	format: 2
	features: layering
	op_features: 
	flags: 
	create_timestamp: Wed Jun 12 12:08:50 2019
	access_timestamp: Wed Jun 12 12:08:50 2019
	modify_timestamp: Wed Jun 12 12:08:50 2019
[root@worker0 /]# rbd ls
[root@worker0 /]# rbd ls
[root@worker0 /]# rbd ls
csi-vol-082b9436-8d0b-11e9-bb4e-1eb22aff46bb
csi-vol-08374cf5-8d0b-11e9-90fe-a298890739d8
csi-vol-08399ffd-8d0b-11e9-a5a4-c6fbd27664af
[root@worker0 /]# 
[root@worker0 /]# rbd ls
csi-vol-082b9436-8d0b-11e9-bb4e-1eb22aff46bb
csi-vol-08374cf5-8d0b-11e9-90fe-a298890739d8
csi-vol-08399ffd-8d0b-11e9-a5a4-c6fbd27664af
[root@worker0 /]# rbd info csi-vol-082b9436-8d0b-11e9-bb4e-1eb22aff46bb
rbd image 'csi-vol-082b9436-8d0b-11e9-bb4e-1eb22aff46bb':
	size 1 GiB in 256 objects
	order 22 (4 MiB objects)
	snapshot_count: 0
	id: 3a9cfcec3884
	block_name_prefix: rbd_data.3a9cfcec3884
	format: 2
	features: layering
	op_features: 
	flags: 
	create_timestamp: Wed Jun 12 12:10:15 2019
	access_timestamp: Wed Jun 12 12:10:15 2019
	modify_timestamp: Wed Jun 12 12:10:15 2019
[root@worker0 /]# rbd info csi-vol-08374cf5-8d0b-11e9-90fe-a298890739d8
rbd image 'csi-vol-08374cf5-8d0b-11e9-90fe-a298890739d8':
	size 1 GiB in 256 objects
	order 22 (4 MiB objects)
	snapshot_count: 0
	id: 600835a1e1a4
	block_name_prefix: rbd_data.600835a1e1a4
	format: 2
	features: layering
	op_features: 
	flags: 
	create_timestamp: Wed Jun 12 12:10:15 2019
	access_timestamp: Wed Jun 12 12:10:15 2019
	modify_timestamp: Wed Jun 12 12:10:15 2019
[root@worker0 /]# rbd info csi-vol-08399ffd-8d0b-11e9-a5a4-c6fbd27664af
rbd image 'csi-vol-08399ffd-8d0b-11e9-a5a4-c6fbd27664af':
	size 1 GiB in 256 objects
	order 22 (4 MiB objects)
	snapshot_count: 0
	id: 3a9f873ae438
	block_name_prefix: rbd_data.3a9f873ae438
	format: 2
	features: layering
	op_features: 
	flags: 
	create_timestamp: Wed Jun 12 12:10:15 2019
	access_timestamp: Wed Jun 12 12:10:15 2019
	modify_timestamp: Wed Jun 12 12:10:15 2019
[root@worker0 /]# 
[root@worker0 /]# rbd ls
csi-vol-082b9436-8d0b-11e9-bb4e-1eb22aff46bb
csi-vol-08374cf5-8d0b-11e9-90fe-a298890739d8
csi-vol-08399ffd-8d0b-11e9-a5a4-c6fbd27664af
[root@worker0 /]#

after deleting the PVC am seeing 2 extra images in backend

[root@worker0 /]# rbd ls
csi-vol-082b9436-8d0b-11e9-bb4e-1eb22aff46bb
csi-vol-08399ffd-8d0b-11e9-a5a4-c6fbd27664af

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

Madhu-1 · 2019-06-12T12:17:59Z

@humblec @ShyamsundarR PTAL

Madhu-1 · 2019-06-12T12:35:56Z

samething is happening with snapshot also

log is from different volume

[root@worker0 /]# rbd snap ls csi-vol-1211d7f7-8d0e-11e9-955e-36b2595be5cf
SNAPID NAME                                          SIZE  PROTECTED TIMESTAMP                
     5 csi-snap-35aeac3e-8d0e-11e9-9e28-8e86690237d6 1 GiB yes       Wed Jun 12 12:33:01 2019 
     6 csi-snap-35c585b0-8d0e-11e9-955e-36b2595be5cf 1 GiB yes       Wed Jun 12 12:33:01 2019 
     7 csi-snap-35b9afc8-8d0e-11e9-849b-5647cc15ee54 1 GiB yes       Wed Jun 12 12:33:02 2019 
[root@worker0 /]# 
[root@worker0 /]# rbd snap ls csi-vol-1211d7f7-8d0e-11e9-955e-36b2595be5cf
SNAPID NAME                                          SIZE  PROTECTED TIMESTAMP                
     6 csi-snap-35c585b0-8d0e-11e9-955e-36b2595be5cf 1 GiB yes       Wed Jun 12 12:33:01 2019 
     7 csi-snap-35b9afc8-8d0e-11e9-849b-5647cc15ee54 1 GiB yes       Wed Jun 12 12:33:02 2019 
[root@worker0 /]# 
[root@worker0 /]# rbd snap ls csi-vol-1211d7f7-8d0e-11e9-955e-36b2595be5cf
SNAPID NAME                                          SIZE  PROTECTED TIMESTAMP                
     6 csi-snap-35c585b0-8d0e-11e9-955e-36b2595be5cf 1 GiB yes       Wed Jun 12 12:33:01 2019 
     7 csi-snap-35b9afc8-8d0e-11e9-849b-5647cc15ee54 1 GiB yes       Wed Jun 12 12:33:02 2019 
[root@worker0 /]# 
[root@worker0 /]# rbd snap ls csi-vol-1211d7f7-8d0e-11e9-955e-36b2595be5cf
SNAPID NAME                                          SIZE  PROTECTED TIMESTAMP                
     6 csi-snap-35c585b0-8d0e-11e9-955e-36b2595be5cf 1 GiB yes       Wed Jun 12 12:33:01 2019 
     7 csi-snap-35b9afc8-8d0e-11e9-849b-5647cc15ee54 1 GiB yes       Wed Jun 12 12:33:02 2019 
[root@worker0 /]# 
[root@worker0 /]# rbd snap ls csi-vol-1211d7f7-8d0e-11e9-955e-36b2595be5cf
SNAPID NAME                                          SIZE  PROTECTED TIMESTAMP                
     6 csi-snap-35c585b0-8d0e-11e9-955e-36b2595be5cf 1 GiB yes       Wed Jun 12 12:33:01 2019 
     7 csi-snap-35b9afc8-8d0e-11e9-849b-5647cc15ee54 1 GiB yes       Wed Jun 12 12:33:02 2019 
[root@worker0 /]# 
[root@worker0 /]# rbd snap ls csi-vol-1211d7f7-8d0e-11e9-955e-36b2595be5cf
SNAPID NAME                                          SIZE  PROTECTED TIMESTAMP                
     6 csi-snap-35c585b0-8d0e-11e9-955e-36b2595be5cf 1 GiB yes       Wed Jun 12 12:33:01 2019 
     7 csi-snap-35b9afc8-8d0e-11e9-849b-5647cc15ee54 1 GiB yes       Wed Jun 12 12:33:02 2019

humblec · 2019-06-12T13:43:35Z

@Madhu-1 first thing to check here is the number of attempts the CSI driver made to create the volume in the backend. The volume create call is idempotent, still we have to check that. If its something wrong in the backend ( by logging in the tool box pod), it should be easily reproducible by creating a volume in the backend manually. If its CSI code, we have to track down from which commit this behaves differently or wrongly.

humblec · 2019-06-12T13:44:31Z

@dillaman Any thoughts here while we continue our analysis from CSI side?

nehaberry · 2019-06-12T15:03:49Z

@Madhu-1

Is it that the rbd image is not getting deleted and staying behind ?

OR

Is it that for a single pvc request, more than one rbd volume is getting created ?

Thanks

Madhu-1 · 2019-06-12T15:06:39Z

@nehaberry yeah correct let's wait till we fix #426

ShyamsundarR · 2019-06-12T17:00:00Z

The issue is that once we moved to a Deployment from a StatefulSet, in PR #414 we are getting a create request being sent to all replicas in the Deployment. This causes each running instance to not lock out the other (as the locks are in memory locks, and will not conflict across processes/nodes) request, and so we end up losing atomicity.

The Deployment should have only 1 active/primary member, with the rest being passive/secondary. If this cannot be achieved using a deployment, then we possibly cannot use such constructs for the provisioner plugin.

Some logs from the 3 replicas processing the same request: (notice the Volume request name being common and sent to all 3 instances)

get pods
NAME                                         READY   STATUS    RESTARTS   AGE
csi-rbdplugin-hxjj8                          2/2     Running   1          4m43s
csi-rbdplugin-k74rk                          2/2     Running   1          4m43s
csi-rbdplugin-pj6s6                          2/2     Running   1          4m43s
csi-rbdplugin-provisioner-7c48d7c6c7-5k9cl   4/4     Running   2          4m47s
csi-rbdplugin-provisioner-7c48d7c6c7-c5dv2   4/4     Running   2          4m47s
csi-rbdplugin-provisioner-7c48d7c6c7-fp78v   4/4     Running   2          4m47s

logs csi-rbdplugin-provisioner-7c48d7c6c7-5k9cl -c csi-rbdplugin

I0612 15:58:48.263513       1 utils.go:105] GRPC call: /csi.v1.Controller/CreateVolume
I0612 15:58:48.263536       1 utils.go:106] GRPC request: {"capacity_range":{"required_bytes":1073741824},"name":"pvc-523d180a-8d2a-11e9-95e7-5cca182e0ce1","parameters":{"adminid":"admin","clusterID":"rookcluster","imageFeatures":"layering","imageFormat":"2","pool":"replicapool","userid":"admin"},"secrets":"***stripped***","volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}}]}
I0612 15:58:48.267616       1 rbd_util.go:460] setting disableInUseChecks on rbd volume to: false
I0612 15:58:50.075643       1 rbd_journal.go:277] generated Volume ID (0001-000b-rookcluster-0000000000000001-f721ca81-8d2a-11e9-8982-ee87bc610626) and image name (csi-vol-f721ca81-8d2a-11e9-8982-ee87bc610626) for request name (pvc-523d180a-8d2a-11e9-95e7-5cca182e0ce1)
I0612 15:58:50.075848       1 rbd_util.go:130] rbd: create csi-vol-f721ca81-8d2a-11e9-8982-ee87bc610626 size 1024M format 2 (features: layering) using mon 10.99.104.132:6790,10.100.133.246:6790,10.102.44.116:6790, pool replicapool 
I0612 15:58:51.828748       1 controllerserver.go:185] created image csi-vol-f721ca81-8d2a-11e9-8982-ee87bc610626
I0612 15:58:51.828778       1 utils.go:111] GRPC response: {"volume":{"capacity_bytes":1073741824,"volume_context":{"adminid":"admin","clusterID":"rookcluster","imageFeatures":"layering","imageFormat":"2","pool":"replicapool","userid":"admin"},"volume_id":"0001-000b-rookcluster-0000000000000001-f721ca81-8d2a-11e9-8982-ee87bc610626"}}

logs csi-rbdplugin-provisioner-7c48d7c6c7-c5dv2 -c csi-rbdplugin

I0612 15:58:48.872618       1 utils.go:105] GRPC call: /csi.v1.Controller/CreateVolume
I0612 15:58:48.872644       1 utils.go:106] GRPC request: {"capacity_range":{"required_bytes":1073741824},"name":"pvc-523d180a-8d2a-11e9-95e7-5cca182e0ce1","parameters":{"adminid":"admin","clusterID":"rookcluster","imageFeatures":"layering","imageFormat":"2","pool":"replicapool","userid":"admin"},"secrets":"***stripped***","volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}}]}
I0612 15:58:48.875264       1 rbd_util.go:460] setting disableInUseChecks on rbd volume to: false
I0612 15:59:10.176947       1 rbd_journal.go:277] generated Volume ID (0001-000b-rookcluster-0000000000000001-f7788132-8d2a-11e9-9098-d6b872beca9e) and image name (csi-vol-f7788132-8d2a-11e9-9098-d6b872beca9e) for request name (pvc-523d180a-8d2a-11e9-95e7-5cca182e0ce1)
I0612 15:59:10.176982       1 rbd_util.go:130] rbd: create csi-vol-f7788132-8d2a-11e9-9098-d6b872beca9e size 1024M format 2 (features: layering) using mon 10.99.104.132:6790,10.100.133.246:6790,10.102.44.116:6790, pool replicapool 
I0612 15:59:10.311413       1 controllerserver.go:185] created image csi-vol-f7788132-8d2a-11e9-9098-d6b872beca9e
I0612 15:59:10.311465       1 utils.go:111] GRPC response: {"volume":{"capacity_bytes":1073741824,"volume_context":{"adminid":"admin","clusterID":"rookcluster","imageFeatures":"layering","imageFormat":"2","pool":"replicapool","userid":"admin"},"volume_id":"0001-000b-rookcluster-0000000000000001-f7788132-8d2a-11e9-9098-d6b872beca9e"}}

logs csi-rbdplugin-provisioner-7c48d7c6c7-fp78v -c csi-rbdplugin

I0612 15:58:47.892960       1 utils.go:105] GRPC call: /csi.v1.Controller/CreateVolume
I0612 15:58:47.892979       1 utils.go:106] GRPC request: {"capacity_range":{"required_bytes":1073741824},"name":"pvc-523d180a-8d2a-11e9-95e7-5cca182e0ce1","parameters":{"adminid":"admin","clusterID":"rookcluster","imageFeatures":"layering","imageFormat":"2","pool":"replicapool","userid":"admin"},"secrets":"***stripped***","volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}}]}
I0612 15:58:47.895126       1 rbd_util.go:460] setting disableInUseChecks on rbd volume to: false
I0612 15:58:49.632222       1 rbd_journal.go:277] generated Volume ID (0001-000b-rookcluster-0000000000000001-f6eb0a96-8d2a-11e9-86a1-8a7fb00d4e3f) and image name (csi-vol-f6eb0a96-8d2a-11e9-86a1-8a7fb00d4e3f) for request name (pvc-523d180a-8d2a-11e9-95e7-5cca182e0ce1)
I0612 15:58:49.632274       1 rbd_util.go:130] rbd: create csi-vol-f6eb0a96-8d2a-11e9-86a1-8a7fb00d4e3f size 1024M format 2 (features: layering) using mon 10.99.104.132:6790,10.100.133.246:6790,10.102.44.116:6790, pool replicapool 
I0612 15:58:51.340840       1 controllerserver.go:185] created image csi-vol-f6eb0a96-8d2a-11e9-86a1-8a7fb00d4e3f
I0612 15:58:51.340864       1 utils.go:111] GRPC response: {"volume":{"capacity_bytes":1073741824,"volume_context":{"adminid":"admin","clusterID":"rookcluster","imageFeatures":"layering","imageFormat":"2","pool":"replicapool","userid":"admin"},"volume_id":"0001-000b-rookcluster-0000000000000001-f6eb0a96-8d2a-11e9-86a1-8a7fb00d4e3f"}}

tombarron · 2019-06-12T17:26:38Z

I am reminded of slides 44-48 in the Storage 101 [1] talk at Kubecon Barcelona this year.

[1] https://static.sched.com/hosted_files/kccnceu19/cf/slides.pdf

ShyamsundarR · 2019-06-12T17:56:15Z

The Deployment should have only 1 active/primary member, with the rest being passive/secondary. If this cannot be achieved using a deployment, then we possibly cannot use such constructs for the provisioner plugin.

Looks like this is achieved using the leader election feature in the csi-provisioner side car, BUT in order for this to trigger we need the following additions/corrections to the file: deploy/rbd/kubernetes/csi-rbdplugin-provisioner.yaml

This line needs an opening quotation mark (IOW, has a typo):

ceph-csi/deploy/rbd/kubernetes/csi-rbdplugin-provisioner.yaml

Line 23 in 69662e6

- --leader-election-type=leases"

Following the above line in the same file we need to add - "--enable-leader-election" to actually enable leader election by the csi-provisioner containers, as even with the above change the request is broadcast than sent to a leader.

Finally, even with the above 2 changes, my pods are stuck in electing a leader with the following error from the csi-provisioner container:

E0612 17:52:40.605813       1 leaderelection.go:310] error initially creating leader election record: the server could not find the requested resource
I0612 17:52:40.605882       1 leaderelection.go:222] failed to acquire lease default/rbd-csi-ceph-com
E0612 17:52:50.500719       1 leaderelection.go:310] error initially creating leader election record: the server could not find the requested resource
I0612 17:52:50.500742       1 leaderelection.go:222] failed to acquire lease default/rbd-csi-ceph-com

This could be due to me running kubernetes v1.13.5 or a problem with the RBAC for leases or some more configuration needed before leases can work.

@Madhu-1 request you take a look?

humblec · 2019-06-19T06:55:32Z

@Madhu-1 after reverting the patch, things are working as expected , Isnt it ?

Madhu-1 · 2019-06-19T07:00:27Z

yes closing this one

[release-4.18]: cephfs: log clone progress

Madhu-1 added bug Something isn't working release-1.1.0 Track release 1.1 items labels Jun 12, 2019

Madhu-1 mentioned this issue Jun 13, 2019

Fix leader election in deployment #428

Closed

Madhu-1 closed this as completed Jun 19, 2019

openshift-cherrypick-robot pushed a commit to openshift-cherrypick-robot/ceph-csi that referenced this issue Dec 17, 2024

Merge pull request ceph#426 from Nikhil-Ladha/clone-progress

44b93cb

[release-4.18]: cephfs: log clone progress

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

rbd creating multiple images in the backend for single PVC #426

rbd creating multiple images in the backend for single PVC #426

Madhu-1 commented Jun 12, 2019

Madhu-1 commented Jun 12, 2019

Madhu-1 commented Jun 12, 2019

humblec commented Jun 12, 2019

humblec commented Jun 12, 2019

nehaberry commented Jun 12, 2019

Madhu-1 commented Jun 12, 2019

ShyamsundarR commented Jun 12, 2019

tombarron commented Jun 12, 2019

ShyamsundarR commented Jun 12, 2019

humblec commented Jun 19, 2019

Madhu-1 commented Jun 19, 2019

rbd creating multiple images in the backend for single PVC #426

rbd creating multiple images in the backend for single PVC #426

Comments

Madhu-1 commented Jun 12, 2019

Describe the bug

Environment details

Steps to reproduce

Actual results

Expected behavior

Madhu-1 commented Jun 12, 2019

Madhu-1 commented Jun 12, 2019

humblec commented Jun 12, 2019

humblec commented Jun 12, 2019

nehaberry commented Jun 12, 2019

Madhu-1 commented Jun 12, 2019

ShyamsundarR commented Jun 12, 2019

tombarron commented Jun 12, 2019

ShyamsundarR commented Jun 12, 2019

humblec commented Jun 19, 2019

Madhu-1 commented Jun 19, 2019