Bug 2028757

Hi Jijlu,

I have a question before we can get to the root cause for the mismatch of the md5sum values.
How are the read and write operations done here?
Because sometimes just running md5sum maynot be enough. In block mode, it's important to use Direct-io for the I/O to avoid caching.
On checking the test case I don't see Direct-IO being used for write operation( I maybe wrong). 
Something like this, `dd oflag=directio -f=/dev/rbdblock | md5sum` may help.

Here, we need to make sure that the writes are completely flushed to the cluster before the clone is done. Because if all caches are not flushed, the md5sum of the clone will result in checking incomplete sets of writes (excluding unflushed writes from cache)
And thereby resulting in a mismatched md5sum value.

Also, on checking the logs we see that the unmap(NodeUnstageVolume) was done 10mins after the creation of the clone, which means the writes were most likely not flushed.

Logs with timestamp of cloning:
```
2021-11-25T08:55:20.916652229Z I1125 08:55:20.916609       1 connection.go:183] GRPC call: /csi.v1.Controller/CreateVolume
2021-11-25T08:55:20.916887317Z I1125 08:55:20.916702       1 connection.go:184] GRPC request: {"capacity_range":{"required_bytes":1073741824},"name":"pvc-bf1945ac-794b-466c-a983-ce98f12f5e2e","parameters":{"clusterID":"openshift-storage","csi.storage.k8s.io/pv/name":"pvc-bf1945ac-794b-466c-a983-ce98f12f5e2e","csi.storage.k8s.io/pvc/name":"clone-pvc-test-7074f875a85e4b-400a9faf87","csi.storage.k8s.io/pvc/namespace":"namespace-test-51aeaa179720451e97fca455a","encrypted":"true","encryptionKMSID":"vault-test-af2553dd7e594e659b543976457a1","imageFeatures":"layering","imageFormat":"2","pool":"ocs-storagecluster-cephblockpool"},"secrets":"***stripped***","volume_capabilities":[{"AccessType":{"Block":{}},"access_mode":{"mode":1}}],"volume_content_source":{"Type":{"Volume":{"volume_id":"0001-0011-openshift-storage-0000000000000001-108d3b2a-4dcd-11ec-aa1e-0a580a810221"}}}}
```

Logs of NodeUnstageVolume:
```
2021-11-25T09:06:50.410287166Z I1125 09:06:50.410260   19603 utils.go:177] ID: 5180 Req-ID: 0001-0011-openshift-storage-0000000000000001-108d3b2a-4dcd-11ec-aa1e-0a580a810221 GRPC call: /csi.v1.Node/NodeUnstageVolume
2021-11-25T09:06:50.410375913Z I1125 09:06:50.410363   19603 utils.go:181] ID: 5180 Req-ID: 0001-0011-openshift-storage-0000000000000001-108d3b2a-4dcd-11ec-aa1e-0a580a810221 GRPC request: {"staging_target_path":"/var/lib/kubelet/plugins/kubernetes.io/csi/volumeDevices/staging/pvc-02f315dd-19c2-4e99-a825-bc0cb1b9b199","volume_id":"0001-0011-openshift-storage-0000000000000001-108d3b2a-4dcd-11ec-aa1e-0a580a810221"}
```

The writes can be flushed either by using Direct-IO or rbd unmap. Is any of these done to flush the writes before the clone is done?

Is the PV attached (mounted) to a Pod for this test or is it just "created" without attaching it? Mounting the PV can change things in the file system header, which would change the checksum

I can see that the test used to pass in the past. For instance, in this run:
OCS4-9-Downstream-OCP4-9-IBM-Cloud-managed-1AZ-RHEL-3W-tier1 (BUILD ID: 4.9.0-249.ci RUN ID: 1638210117)

The run is from Tue, Nov 30, 9:55 AM (6 days ago)

(In reply to Elad from comment #4)
> I can see that the test used to pass in the past. For instance, in this run:
> OCS4-9-Downstream-OCP4-9-IBM-Cloud-managed-1AZ-RHEL-3W-tier1 (BUILD ID:
> 4.9.0-249.ci RUN ID: 1638210117)
> 
> The run is from Tue, Nov 30, 9:55 AM (6 days ago)

Jilju mentioned in comment #0:

> How reproducible:
> Not easily reproducible. Less than 1/12.

That means, 11 out of 12 times the test does not return an error.

There is a strong suggestion that the testing is racy. There is a possibility of unflushed cached data when the clone is created, flushing the caches before creating the clone would likely result in more stable test results. Yati explained this quite well in comment #2.

(In reply to yati padia from comment #2)
> Hi Jijlu,
> 
> I have a question before we can get to the root cause for the mismatch of
> the md5sum values.
> How are the read and write operations done here?
fio is used in the test case for I/O.

fio --name=fio-rand-write --filename=/dev/rbdblock --rw=randwrite --bs=4K --direct=0 --numjobs=1 --time_based=1 --runtime=60 --size=500M --ioengine=libaio --iodepth=4 --rate=1m --rate_process=poisson --output-format=json


> Here, we need to make sure that the writes are completely flushed to the
> cluster before the clone is done.
Should we add some additional steps after I/O to perform this before creating the clone ?

(In reply to Chris Blum from comment #3)
> Is the PV attached (mounted) to a Pod for this test or is it just "created"
> without attaching it? Mounting the PV can change things in the file system
> header, which would change the checksum
Yes, it is attached to a pod. This issue is not seen usually. There are other tests which verifies data integrity using md5sum after taking clone and restoring snapshots. Those tests are passing, that means the change in checksum after attaching to a pod might be race condition. If there is a better alternative to verify the data integrity we can change the test accordingly.

(In reply to Jilju Joy from comment #6)
> fio --name=fio-rand-write --filename=/dev/rbdblock --rw=randwrite --bs=4K
> --direct=0 --numjobs=1 --time_based=1 --runtime=60 --size=500M
> --ioengine=libaio --iodepth=4 --rate=1m --rate_process=poisson
> --output-format=json

Does the direct=0 represent the direct-IO operation?
> 
> > Here, we need to make sure that the writes are completely flushed to the
> > cluster before the clone is done.
> Should we add some additional steps after I/O to perform this before
> creating the clone ?
You can try using the dd command as mentioned in comment 2.

(In reply to yati padia from comment #8)
> (In reply to Jilju Joy from comment #6)
> > fio --name=fio-rand-write --filename=/dev/rbdblock --rw=randwrite --bs=4K
> > --direct=0 --numjobs=1 --time_based=1 --runtime=60 --size=500M
> > --ioengine=libaio --iodepth=4 --rate=1m --rate_process=poisson
> > --output-format=json
> 
> Does the direct=0 represent the direct-IO operation?

Indeed, enable direct-io with this option. Or maybe fio offers an option to flush caches once it is finished?


(In reply to Jilju Joy from comment #7)
> (In reply to Chris Blum from comment #3)
> > Is the PV attached (mounted) to a Pod for this test or is it just "created"
> > without attaching it? Mounting the PV can change things in the file system
> > header, which would change the checksum
> Yes, it is attached to a pod. This issue is not seen usually. There are
> other tests which verifies data integrity using md5sum after taking clone
> and restoring snapshots. Those tests are passing, that means the change in
> checksum after attaching to a pod might be race condition. If there is a
> better alternative to verify the data integrity we can change the test
> accordingly.

Detaching from the Pod (and waiting for the NodeUnstageVolume CSI operation to finish) is an alternative to flushing cached writes.

Added direct=1 in fio command for the test as suggested by Yati in our discussion. We will check if the issue is reproducible in upcoming runs.

btw - ripsaw, our benchmark operator, supports running fio and has the option for dropping caches:
https://github.com/cloud-bulldozer/benchmark-operator/blob/master/docs/fio_distributed.md

drop_cache_kernel: (optional, default false) If set to True, kernel cache will be dropped on the labeled hosts before each sample. See here for how to set up kernel cache dropping
drop_cache_rook_ceph: (optional, default false) The IP address of the pod hosting the Rook-Ceph cache drop URL -- See here for how to set up Ceph OSD cache dropping
Technical Note: If you are running kube/openshift on VMs make sure the diskimage or volume is preallocated.

Executed the test case 20 times after updating the fio parameters. All 20 are success. We will closely watch the production runs of the test case.

Moving it out from 4.9 based on the above comment

Closing this bug as there is nothing to be done from our side.
Assuming https://bugzilla.redhat.com/show_bug.cgi?id=2028757#c10 to be proposed solution.