The logs are available here : 

http://rhsqe-repo.lab.eng.blr.redhat.com/OCS/ocs-qe-bugs/bz-1896831/

1. What did you see in the logs?
2. Can you describe your environment, specifically is it powerful enough for performance tests? Is it dedicated?

@Yaniv Kaul ,

Per your questions: 

1) I saw retries to create a clone , for 600 seconds the following command was run with 5 secs interval: 

Going to run oc --kubeconfig /home/ypersky/cluster-dirs/vmware/ypersky--perf-04/auth/kubeconfig -n namespace-test-ca2064087b7d47d5b8966e1867793ae4 get pvc pvc-clone-452-0a38cadaf54e4084ad8f17fd83c7d4b6 -o yaml

After timeout of 600 seconds passed and clone#452 was not created, the test was failed .

@Yaniv, per your second question : 

2) The test was running on ypersky-perf-04 cluster on DC4. 
I was the only one working there, only one cluster per DC

3 worker nodes, 3 master nodes. 

There are 32 GB RAM and 12 CPUs for worker nodes. 
I realize that this is not a production level, therefore I'm going to run the same test on AWS and Azure and will post here the results. 
Also we will see whether the problem reproduces.

Replicated the scenario on AWS with 512 clones of a PVC of size 1 GB with 600MB data, but the issue did not get reproduced for me on the first attempt. Some of the PVCs took longer than the others but finally reached the BOUND state after some time. Will wait for Yuli's analysis on the same.

The ceph-csi plugin seems to be tight looping on flatten, and not returning an abort as flatten is in progress. This part needs investigation.

Log file: http://rhsqe-repo.lab.eng.blr.redhat.com/OCS/ocs-qe-bugs/bz-1896831/logs-20201112-003007/ocs-must-gather-us/quay-io-ocs-dev-ocs-must-gather-sha256-fbcaa53e653a3bb4c281dbb3e98706cfe9ee5f8effb1d177cbf6a694555c4fe5/namespaces/openshift-storage/pods/csi-rbdplugin-provisioner-697448756f-w49p7/csi-rbdplugin/csi-rbdplugin/logs/previous.log

Comments inline as <=== ... ===>

Logs of interest:
2020-11-10T23:06:01.482310415Z I1110 23:06:01.482252       1 utils.go:159] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 GRPC call: /csi.v1.Controller/CreateVolume
2020-11-10T23:06:01.485604806Z I1110 23:06:01.485551       1 utils.go:160] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 GRPC request: {"capacity_range":{"required_bytes":1073741824},"name":"pvc-62b64ef5-a213-4738-97cd-71e3433745b5","parameters":{"clusterID":"openshift-storage","imageFeatures":"layering","imageFormat":"2","pool":"ocs-storagecluster-cephblockpool"},"secrets":"***stripped***","volume_capabilities":[{"AccessType":{"Mount":{"fs_type":"ext4"}},"access_mode":{"mode":1}}],"volume_content_source":{"Type":{"Volume":{"volume_id":"0001-0011-openshift-storage-0000000000000001-a47d748a-23a1-11eb-a410-0a580a80020d"}}}}
2020-11-10T23:06:01.485827030Z I1110 23:06:01.485796       1 rbd_util.go:771] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 setting disableInUseChecks on rbd volume to: false
2020-11-10T23:06:01.487881565Z I1110 23:06:01.487842       1 omap.go:84] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 got omap values: (pool="ocs-storagecluster-cephblockpool", namespace="", name="csi.volume.a47d748a-23a1-11eb-a410-0a580a80020d"): map[csi.imageid:5f3376ea8f1b csi.imagename:csi-vol-a47d748a-23a1-11eb-a410-0a580a80020d csi.volname:pvc-8f95e554-28b2-4672-9fe2-ff7ca899f77f]
2020-11-10T23:06:01.544394356Z I1110 23:06:01.544327       1 omap.go:84] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 got omap values: (pool="ocs-storagecluster-cephblockpool", namespace="", name="csi.volumes.default"): map[]
2020-11-10T23:06:01.599402091Z I1110 23:06:01.599340       1 rbd_util.go:452] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 clone depth is (0), configured softlimit (4) and hardlimit (8) for ocs-storagecluster-cephblockpool/csi-vol-a47d748a-23a1-11eb-a410-0a580a80020d
2020-11-10T23:06:01.775872201Z I1110 23:06:01.775799       1 cephcmds.go:59] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 command succeeded: rbd [-m 172.30.185.235:6789,172.30.198.237:6789,172.30.218.89:6789 --id csi-rbd-provisioner --keyfile=***stripped*** -c /etc/ceph/ceph.conf --format=json snap ls --all ocs-storagecluster-cephblockpool/csi-vol-a47d748a-23a1-11eb-a410-0a580a80020d]
2020-11-10T23:06:01.778196038Z I1110 23:06:01.778154       1 rbd_util.go:312] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 executing [rbd task add flatten ocs-storagecluster-cephblockpool/csi-vol-c531f1f3-23a1-11eb-a410-0a580a80020d-temp --id csi-rbd-provisioner --keyfile=/tmp/csi/keys/keyfile-052364570 -m 172.30.185.235:6789,172.30.198.237:6789,172.30.218.89:6789] for image (csi-vol-c531f1f3-23a1-11eb-a410-0a580a80020d-temp) using mon 172.30.185.235:6789,172.30.198.237:6789,172.30.218.89:6789, pool ocs-storagecluster-cephblockpool

<=== initial flatten, seems to have been succesful ===> 2020-11-10T23:06:02.258382841Z I1110 23:06:02.258315       1 cephcmds.go:59] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 command succeeded: ceph [rbd task add flatten ocs-storagecluster-cephblockpool/csi-vol-c531f1f3-23a1-11eb-a410-0a580a80020d-temp --id csi-rbd-provisioner --keyfile=***stripped*** -m 172.30.185.235:6789,172.30.198.237:6789,172.30.218.89:6789]
<=== processed as an error ===> 2020-11-10T23:06:02.258382841Z E1110 23:06:02.258361       1 rbd_util.go:434] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 failed to flatten ocs-storagecluster-cephblockpool/csi-vol-c531f1f3-23a1-11eb-a410-0a580a80020d-temp; err flatten in progress: flatten is in progress for image csi-vol-c531f1f3-23a1-11eb-a410-0a580a80020d-temp

<=== the loop continues ===>
2020-11-10T23:06:02.258434627Z I1110 23:06:02.258379       1 rbd_util.go:312] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 executing [rbd task add flatten ocs-storagecluster-cephblockpool/csi-vol-c960e155-23a1-11eb-a410-0a580a80020d-temp --id csi-rbd-provisioner --keyfile=/tmp/csi/keys/keyfile-052364570 -m 172.30.185.235:6789,172.30.198.237:6789,172.30.218.89:6789] for image (csi-vol-c960e155-23a1-11eb-a410-0a580a80020d-temp) using mon 172.30.185.235:6789,172.30.198.237:6789,172.30.218.89:6789, pool ocs-storagecluster-cephblockpool
2020-11-10T23:06:03.412682529Z I1110 23:06:03.412620       1 cephcmds.go:59] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 command succeeded: ceph [rbd task add flatten ocs-storagecluster-cephblockpool/csi-vol-c960e155-23a1-11eb-a410-0a580a80020d-temp --id csi-rbd-provisioner --keyfile=***stripped*** -m 172.30.185.235:6789,172.30.198.237:6789,172.30.218.89:6789]
2020-11-10T23:06:03.412682529Z E1110 23:06:03.412658       1 rbd_util.go:434] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 failed to flatten ocs-storagecluster-cephblockpool/csi-vol-c960e155-23a1-11eb-a410-0a580a80020d-temp; err flatten in progress: flatten is in progress for image csi-vol-c960e155-23a1-11eb-a410-0a580a80020d-temp

<=== the whole create request with ID 764 ends with resource exhaustion here ===>

2020-11-10T23:13:15.800981325Z I1110 23:13:15.800925       1 rbd_util.go:312] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 executing [rbd task add flatten ocs-storagecluster-cephblockpool/csi-vol-48cd53d6-23a9-11eb-a410-0a580a80020d-temp --id csi-rbd-provisioner --keyfile=/tmp/csi/keys/keyfile-052364570 -m 172.30.185.235:6789,172.30.198.237:6789,172.30.218.89:6789] for image (csi-vol-48cd53d6-23a9-11eb-a410-0a580a80020d-temp) using mon 172.30.185.235:6789,172.30.198.237:6789,172.30.218.89:6789, pool ocs-storagecluster-cephblockpool
2020-11-10T23:13:17.084235670Z I1110 23:13:17.084164       1 cephcmds.go:59] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 command succeeded: ceph [rbd task add flatten ocs-storagecluster-cephblockpool/csi-vol-48cd53d6-23a9-11eb-a410-0a580a80020d-temp --id csi-rbd-provisioner --keyfile=***stripped*** -m 172.30.185.235:6789,172.30.198.237:6789,172.30.218.89:6789]
2020-11-10T23:13:17.084235670Z E1110 23:13:17.084208       1 rbd_util.go:434] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 failed to flatten ocs-storagecluster-cephblockpool/csi-vol-48cd53d6-23a9-11eb-a410-0a580a80020d-temp; err flatten in progress: flatten is in progress for image csi-vol-48cd53d6-23a9-11eb-a410-0a580a80020d-temp
2020-11-10T23:13:17.084334126Z E1110 23:13:17.084304       1 utils.go:163] ID: 764 Req-ID: pvc-62b64ef5-a213-4738-97cd-71e3433745b5 GRPC error: rpc error: code = ResourceExhausted desc = rbd image ocs-storagecluster-cephblockpool/csi-vol-a47d748a-23a1-11eb-a410-0a580a80020d has 451 snapshots

(In reply to Shyamsundar from comment #7)
> The ceph-csi plugin seems to be tight looping on flatten, and not returning
> an abort as flatten is in progress. This part needs investigation.
> 
> Log file:
> http://rhsqe-repo.lab.eng.blr.redhat.com/OCS/ocs-qe-bugs/bz-1896831/logs-
> 20201112-003007/ocs-must-gather-us/quay-io-ocs-dev-ocs-must-gather-sha256-
> fbcaa53e653a3bb4c281dbb3e98706cfe9ee5f8effb1d177cbf6a694555c4fe5/namespaces/
> openshift-storage/pods/csi-rbdplugin-provisioner-697448756f-w49p7/csi-
> rbdplugin/csi-rbdplugin/logs/previous.log
> 

Request ID 764 finds that the snapshot limit (max 450) on the rbd image has exceeded limits and hence flattens all intermediate images before returning the resource exhausted error for the request. This takes >10 minutes as seen in the logs, causing all other create requests, for the same volume, in the interim to fail with operation in progress.

As the test timeout is 600 seconds, the test case fails due to the above.

Finally, a volume create for the same volume, post the request with ID 764 releases its locks, succeeds. The request ID of this is 785. Which basically means clone succeeds in the end once intermediate images are flattened, due to reaching the limits.

Although functionality is not broken, the delay in flattening intermediate images for a clone from a clone use case, causes the said behavior. We may need to check if we can use soft/hard limits in here to not flatten in bulk once the max limit is reached.

Marking as a proposed blocker.
Mass clones might be considered as an edge case but this BZ is in POST so if possible to get a fix, QE can run the automated test to quickly verify

The problem was not reproduced on the latest 4.6 build. 
Closing the bug.

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