Bug 1886551

Summary: Clone creation failed after timeout of 5 hours of Azure platrom for 3 CephFS PVCs ( PVC sizes: 1, 25 and 100 GB)
Product: [Red Hat Storage] Red Hat OpenShift Container Storage Reporter: Yuli Persky <ypersky>
Component: csi-driverAssignee: Humble Chirammal <hchiramm>
Status: CLOSED ERRATA QA Contact: Yuli Persky <ypersky>
Severity: high Docs Contact:
Priority: unspecified    
Version: 4.6CC: alayani, kramdoss, madam, mrajanna, muagarwa, ocs-bugs, srangana, ygupta
Target Milestone: ---Keywords: Automation, Performance
Target Release: OCS 4.6.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: 4.6.0-156.ci Doc Type: No Doc Update
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-12-17 06:24:44 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Yuli Persky 2020-10-08 18:12:49 UTC 
Description of problem (please be detailed as possible and provide log
snippests):

I've run test_singe_pvc_clone.py test as part of Performance suite on Azure.

The link to Jenkins job is : 
https://ocs4-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/Performance/job/qe-trigger-azure-ipi-1az-rhcos-3m-3w-performance/3/


When analyzsing the logs, it appeared that clone creation failed after 5 hours ( 18000 sec) of retrying for the three following CephFS PVC sizes and data : 

1 GB PVC with 600 MB data

25GB PVC with 15 GB data

100GB PVC with 60 GB data 

PLease note that clone creation was successful for all sizes of RBD PVCs. 


Version of all relevant components (if applicable): 4.6 ( both OCP and OCS) 


Does this issue impact your ability to continue to work with the product
(please explain in detail what is the user impact)?


Is there any workaround available to the best of your knowledge?

No


Rate from 1 - 5 the complexity of the scenario you performed that caused this
bug (1 - very simple, 5 - very complex)?

3


Can this issue reproducible?

did not try another run on Azure

Can this issue reproduce from the UI?


If this is a regression, please provide more details to justify this:


Steps to Reproduce:
1. run on Azure platform test_single_pvc_clone_performance.py test 
2.
3.


Actual results:

Clones were not created after 5 hours of retries. 

The first command to create a clone was on 05:59

5 hours later: 

Executing command: oc -n namespace-test-1f642981a55c4697973a57c88cf59bb3 --kubeconfig
 /home/jenkins/current-cluster-dir/openshift-cluster-dir/auth/kubeconfig get PersistentVolumeClaim pvc-cloned-864a120c2f5945c096f93d89be125513 -n namespace-test-1f642981a55c469
7973a57c88cf59bb3

10:59:18 - MainThread - ocs_ci.ocs.ocp - <span style="color: #00CD00;">INFO</span> - status of pvc-cloned-864a120c2f5945c096f93d89be125513 at column STATUS was Pending, but we 
were waiting for Bound
10:59:18 - MainThread - ocs_ci.ocs.ocp - <span style="color: #CD0000;"><b>ERROR</b></span> - timeout expired: Timed Out: (18000,)





Expected results:

Clones should be created within much chorter time than 5 hours.  

Additional info:

Please note that all the logs are available in Jenkins job : 

https://ocs4-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/Performance/job/qe-trigger-azure-ipi-1az-rhcos-3m-3w-performance/3/
Comment 2 Humble Chirammal 2020-10-09 06:51:57 UTC 
Shyam, would you be able to help on this bugzilla?
Comment 3 Mudit Agarwal 2020-10-09 11:01:40 UTC 
Proposing it as a blocker till we get RCA
Comment 4 Shyamsundar 2020-10-09 18:09:12 UTC 
The issue seems to be as follows,

- A CreateVolume request with a volume_content as another volume is processed
- The code creates the required CSI journal initially and starts the cloning process
- As the clone state is "in progress", an ABRT error is returned for the request
- A subsequent CreateVolume request with the same request name is sent
- This does not find the journal entry, and goes and creates a new clone from source

The above loop repeats endlessly causing the operation to never suceed, and also leaking volumes as part of the prior clones that were initiated. IOW, the CreateVolume from a Volume is not behaving in an idempotent fashion.

Log file: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-zi1c33-p/jnk-zi1c33-p_20201006T105942/logs/failed_testcase_ocs_logs_1601986096/test_clone_create_delete_performance%5bCephFileSystem-1-600M%5d_ocs_logs/ocs_must_gather/quay-io-rhceph-dev-ocs-must-gather-sha256-5fe3b72ce75ba0f0bc15dcd51ee1a166b86b0557df8275f3f5bdf62c92630865/namespaces/openshift-storage/pods/csi-cephfsplugin-provisioner-db5584d78-pqbtt/csi-cephfsplugin/csi-cephfsplugin/logs/current.log

Relevant logs for the first 2 CreateVolume requests for the PVC request "pvc-cloned-864a120c2f5945c096f93d89be125513" (need to check the provisioner side car logs to map this to the request name of "pvc-b5f7016c-a856-479e-b05d-32abe575a42b")

--- CreateVolume initial request
2020-10-07T05:59:18.561865629Z I1007 05:59:18.561818       1 utils.go:160] ID: 2238 Req-ID: pvc-b5f7016c-a856-479e-b05d-32abe575a42b GRPC request: {"capacity_range":{"required_bytes":1073741824},"name":"pvc-b5f7016c-a856-479e-b05d-32abe575a42b","parameters":{"clusterID":"openshift-storage","fsName":"ocs-storagecluster-cephfilesystem"},"secrets":"***stripped***","volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":5}}],"volume_content_source":{"Type":{"Volume":{"volume_id":"0001-0011-openshift-storage-0000000000000001-b614daeb-0861-11eb-bcdf-0a580a81020b"}}}}

--- Initial OMap for the request is empty
2020-10-07T05:59:20.837881852Z I1007 05:59:20.837847       1 omap.go:72] ID: 2238 Req-ID: pvc-b5f7016c-a856-479e-b05d-32abe575a42b got omap values: (pool="ocs-storagecluster-cephfilesystem-metadata", namespace="csi", name="csi.volumes.default"): map[]
--- Entry created with the UUID value, "3e3489eb-0862-11eb-bcdf-0a580a81020b"
2020-10-07T05:59:20.854299053Z I1007 05:59:20.854223       1 omap.go:136] ID: 2238 Req-ID: pvc-b5f7016c-a856-479e-b05d-32abe575a42b set omap keys (pool="ocs-storagecluster-cephfilesystem-metadata", namespace="csi", name="csi.volumes.default"): map[csi.volume.pvc-b5f7016c-a856-479e-b05d-32abe575a42b:3e3489eb-0862-11eb-bcdf-0a580a81020b])

--- Subsequent CreateVolume request
2020-10-07T05:59:22.975024425Z I1007 05:59:22.974958       1 utils.go:160] ID: 2239 Req-ID: pvc-b5f7016c-a856-479e-b05d-32abe575a42b GRPC request: {"capacity_range":{"required_bytes":1073741824},"name":"pvc-b5f7016c-a856-479e-b05d-32abe575a42b","parameters":{"clusterID":"openshift-storage","fsName":"ocs-storagecluster-cephfilesystem"},"secrets":"***stripped***","volume_capabilities":[{"AccessType":{"Mount":{}},"access_mode":{"mode":5}}],"volume_content_source":{"Type":{"Volume":{"volume_id":"0001-0011-openshift-storage-0000000000000001-b614daeb-0861-11eb-bcdf-0a580a81020b"}}}}

--- OMap should have returned valid values, but comes back empty again
2020-10-07T05:59:25.829143157Z I1007 05:59:25.829081       1 omap.go:72] ID: 2239 Req-ID: pvc-b5f7016c-a856-479e-b05d-32abe575a42b got omap values: (pool="ocs-storagecluster-cephfilesystem-metadata", namespace="csi", name="csi.volumes.default"): map[]
--- A newer OMap is created and the cloning process is started all over again
2020-10-07T05:59:25.939839793Z I1007 05:59:25.939766       1 omap.go:136] ID: 2239 Req-ID: pvc-b5f7016c-a856-479e-b05d-32abe575a42b set omap keys (pool="ocs-storagecluster-cephfilesystem-metadata", namespace="csi", name="csi.volumes.default"): map[csi.volume.pvc-b5f7016c-a856-479e-b05d-32abe575a42b:412e23ef-0862-11eb-bcdf-0a580a81020b])

List of current subvolumes which relate to the multiple clones as above can be found here: http://magna002.ceph.redhat.com/ocsci-jenkins/openshift-clusters/jnk-zi1c33-p/jnk-zi1c33-p_20201006T105942/logs/failed_testcase_ocs_logs_1601986096/test_clone_create_delete_performance%5bCephFileSystem-1-600M%5d_ocs_logs/ocs_must_gather/quay-io-rhceph-dev-ocs-must-gather-sha256-5fe3b72ce75ba0f0bc15dcd51ee1a166b86b0557df8275f3f5bdf62c92630865/ceph/must_gather_commands/ceph_fs_subvolume_ls_ocs-storagecluster-cephfilesystem_csi

=== Dev notes ===

I tried to look at the code briefly to understand if the initial OMap lookup has a bug, it did not appear so.
Also checked if "in progress" is processed correctly and the journal is not deleted as part of the err defer in CreateVolume, this again checks out fine (I see no logs as evidence that the OMap was deleted).

This would need a dry-run, with a possible forced error return, to test and confirm if there is something incorrect in the ceph-csi code, or that the OMap is really nor present at the ceph end (which again seems highly unusual).
Comment 5 Michael Adam 2020-10-14 16:37:31 UTC 
Can this be reproduced on other platforms?
Comment 6 Yuli Persky 2020-10-14 20:40:06 UTC 
@Michael Adam,

This test run successfully number of times on VMware and Vmware LSO platforms. Never saw this issue on other plaform.
Comment 7 Yuli Persky 2020-10-18 00:22:16 UTC 
@to whom it may concern, 

I tried to reproduce this issue while running twice on another Azure cluster, and the problem was NOT reproduced. 
The clones were created for 1/25/500/100 GB PVC ( each one 60% filled with data) , both RBD and CephFS PCVs. 

I'll add here the clone creation times.
Comment 8 Humble Chirammal 2020-10-19 02:19:00 UTC 
(In reply to Shyamsundar from comment #4)
> The issue seems to be as follows,
> 
> - A CreateVolume request with a volume_content as another volume is processed
> - The code creates the required CSI journal initially and starts the cloning
> process
> - As the clone state is "in progress", an ABRT error is returned for the
> request
> - A subsequent CreateVolume request with the same request name is sent
> - This does not find the journal entry, and goes and creates a new clone
> from source
> 


Shyam, Thanks for looking into this issue and describing the scenario of events!
Comment 9 Humble Chirammal 2020-10-19 02:20:56 UTC 
(In reply to Yuli Persky from comment #7)
> @to whom it may concern, 
> 
> I tried to reproduce this issue while running twice on another Azure
> cluster, and the problem was NOT reproduced. 
> The clones were created for 1/25/500/100 GB PVC ( each one 60% filled with
> data) , both RBD and CephFS PCVs. 
> 
> I'll add here the clone creation times.

Thats great! Considering this is working as expected and we have already analyzed the logs and we dont see
any possibilities of a bug in the code, can we close this case ? or move to verified?
Comment 10 Mudit Agarwal 2020-10-19 04:46:39 UTC 
Removing the blocker flag as it is not reproducible, lets keep the discussions on.

@Humble, Shyam has mentioned a posibility of hitting some corner case so lets keep the bug open.
Yug, is trying to repro it from dev point of view. If we wont't be able to repro it then we can close the BZ.
Comment 11 Yuli Persky 2020-10-19 12:11:19 UTC 

Regarding the creation - looks like there is no problem to create clones for various sizes of PVC ( with data). 
I'd like to post here the statistics gathered by the test_pvc_clone_performance.py. 
Please go over and let me know whether the performance ( creation time and creation speed) is satisfactory to your opinion.  


RBD PVC, pvc size = 1GB, data size: 600MB :


03:17:20 - MainThread - test_pvc_clone_performance - INFO - Printing clone creation time and speed for 1 clones on CephBlockPool PVC of size 1 GB:
03:17:20 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation time is 1.840727 secs.
03:17:20 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation speed is 325 MB/sec.
03:17:20 - MainThread - test_pvc_clone_performance - INFO - Clone deletion time and speed for CephBlockPool PVC of size 1 GB are:
03:17:20 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion time is 1.434871 secs.
03:17:20 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion speed is 418 MB/sec.
03:17:20 - MainThread - test_pvc_clone_performance - INFO - test_clones_creation_performance finished successfully.


RBD PVC, pvc size = 25GB, data size: 15GB :


03:28:07 - MainThread - test_pvc_clone_performance - INFO - Printing clone creation time and speed for 1 clones on CephBlockPool PVC of size 25 GB:
03:28:07 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation time is 2.628879 secs.
03:28:07 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation speed is 5705 MB/sec.
03:28:07 - MainThread - test_pvc_clone_performance - INFO - Clone deletion time and speed for CephBlockPool PVC of size 25 GB are:
03:28:07 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion time is 1.200171 secs.
03:28:07 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion speed is 12498 MB/sec.
03:28:07 - MainThread - test_pvc_clone_performance - INFO - test_clones_creation_performance finished successfully.


RBD PVC, pvc size = 50GB, data size: 30GB :


03:47:39 - MainThread - test_pvc_clone_performance - INFO - Printing clone creation time and speed for 1 clones on CephBlockPool PVC of size 50 GB:
03:47:39 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation time is 2.171814 secs.
03:47:39 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation speed is 13813 MB/sec.
03:47:39 - MainThread - test_pvc_clone_performance - INFO - Clone deletion time and speed for CephBlockPool PVC of size 50 GB are:
03:47:39 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion time is 1.274241 secs.
03:47:39 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion speed is 23543 MB/sec.
03:47:39 - MainThread - test_pvc_clone_performance - INFO - test_clones_creation_performance finished successfully.


RBD PVC, pvc size = 100GB, data size: 60GB :


04:26:14 - MainThread - test_pvc_clone_performance - INFO - Printing clone creation time and speed for 1 clones on CephBlockPool PVC of size 100 GB:
04:26:14 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation time is 2.481718 secs.
04:26:14 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation speed is 24176 MB/sec.
04:26:14 - MainThread - test_pvc_clone_performance - INFO - Clone deletion time and speed for CephBlockPool PVC of size 100 GB are:
04:26:14 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion time is 1.213381 secs.
04:26:14 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion speed is 49448 MB/sec.
04:26:14 - MainThread - test_pvc_clone_performance - INFO - test_clones_creation_performance finished successfully.


CephFS PVC, pvc size = 1GB, data size: 600MB :


04:28:59 - MainThread - test_pvc_clone_performance - INFO - Printing clone creation time and speed for 1 clones on CephFileSystem PVC of size 1 GB:
04:28:59 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation time is 11.460319 secs.
04:28:59 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation speed is 52 MB/sec.
04:28:59 - MainThread - test_pvc_clone_performance - INFO - Clone deletion time and speed for CephFileSystem PVC of size 1 GB are:
04:28:59 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion time is 1.842994 secs.
04:28:59 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion speed is 325 MB/sec.
04:28:59 - MainThread - test_pvc_clone_performance - INFO - test_clones_creation_performance finished successfully.


CephFS PVC, pvc size = 25GB, data size: 15GB :


04:42:53 - MainThread - test_pvc_clone_performance - INFO - Printing clone creation time and speed for 1 clones on CephFileSystem PVC of size 25 GB:
04:42:53 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation time is 142.704535 secs.
04:42:53 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation speed is 105 MB/sec.
04:42:53 - MainThread - test_pvc_clone_performance - INFO - Clone deletion time and speed for CephFileSystem PVC of size 25 GB are:
04:42:53 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion time is 1.862197 secs.
04:42:53 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion speed is 8055 MB/sec.
04:42:53 - MainThread - test_pvc_clone_performance - INFO - test_clones_creation_performance finished successfully.


CephFS PVC, pvc size = 50GB, data size: 30GB :


05:08:12 - MainThread - test_pvc_clone_performance - INFO - Printing clone creation time and speed for 1 clones on CephFileSystem PVC of size 50 GB:
05:08:12 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation time is 273.911991 secs.
05:08:12 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation speed is 109 MB/sec.
05:08:12 - MainThread - test_pvc_clone_performance - INFO - Clone deletion time and speed for CephFileSystem PVC of size 50 GB are:
05:08:12 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion time is 1.833906 secs.
05:08:12 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion speed is 16358 MB/sec.
05:08:12 - MainThread - test_pvc_clone_performance - INFO - test_clones_creation_performance finished successfully.


CephFS PVC, pvc size = 100GB, data size: 60GB :


05:55:29 - MainThread - test_pvc_clone_performance - INFO - Printing clone creation time and speed for 1 clones on CephFileSystem PVC of size 100 GB:
05:55:29 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation time is 533.057136 secs.
05:55:29 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 creation speed is 112 MB/sec.
05:55:29 - MainThread - test_pvc_clone_performance - INFO - Clone deletion time and speed for CephFileSystem PVC of size 100 GB are:
05:55:29 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion time is 1.88582 secs.
05:55:29 - MainThread - test_pvc_clone_performance - INFO - Clone number 1 deletion speed is 31816 MB/sec.
05:55:29 - MainThread - test_pvc_clone_performance - INFO - test_clones_creation_performance finished successfully.
Comment 12 Mudit Agarwal 2020-10-21 10:19:40 UTC 
This is not reproducible yet both from dev and qe side. Yug, will again give a try once he is done with other priority things.
Moving it to 4.7 as it seems to be a corner case, lets keep debugging it.
Comment 14 Mudit Agarwal 2020-11-06 16:39:07 UTC 
Bringing this back to 4.6 and providing dev_ack, will move to ON_QA once we have a new 4.6 build.
Comment 18 Yuli Persky 2020-11-19 22:45:35 UTC 
I've run the same scenario ( test_pvc_clone_performace.py test) on Azure  ( ocs 4.6ga) and it passed .
Comment 20 errata-xmlrpc 2020-12-17 06:24:44 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: Red Hat OpenShift Container Storage 4.6.0 security, bug fix, enhancement 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-2020:5605