Openebs: cstor rebuild continues on checksum error

[mynktl]

Description

Cstor replica rebuilds from its clone in AFS mode. To rebuild from the clone, the degraded replica will start a scanner on the clone to read the data. If there is an error while reading the data then the rebuild scanner will report the error and marked the rebuild as failed. Since the replica is in a degraded state, it will again start rebuilding and this cycle will continue.

logs:

2021-05-10/13:19:32.767 Checkpointed IO_seq: 184332695, Rebuild Req offset: 773094113280, Rebuild Req length: 10737418240 for zvol(cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934)
2021-05-10/13:20:39.502 Checkpointed IO_seq: 184332695, Rebuild Req offset: 783831531520, Rebuild Req length: 10737418240 for zvol(cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934)
2021-05-10/13:20:52.305 Checkpointed IO_seq: 184332695, Rebuild Req offset: 794568949760, Rebuild Req length: 10737418240 for zvol(cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934)
2021-05-10/13:21:15.527 Checkpointed IO_seq: 184332695, Rebuild Req offset: 805306368000, Rebuild Req length: 10737418240 for zvol(cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934)
XXX ZFS_ZEVENT_BROADCAST on CV 0x7f8e0d2b18, LOCK 0x7f8e0d2aa8
XXX ZFS_ZEVENT_BROADCAST on CV 0x7f8e0d2b18, LOCK 0x7f8e0d2aa8
XXX ZFS_ZEVENT_BROADCAST on CV 0x7f8e0d2b18, LOCK 0x7f8e0d2aa8
2021-05-10/13:21:53.552 ERROR ZFS event:

ereport.fs.zfs.data ena=0x13aabb331fbffc01 detector=[ version=0x0 scheme="zfs"
 pool=0xaf41b07f46a84091 ] pool="cstor-67623196-d6e5-4956-9eb4-db81259c9089"2021-05-10/13:21:53.552 ERROR OP code 2 failed: 52
2021-05-10/13:21:53.553 ERROR received err in rebuild.. for cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934..

 pool_guid=2021-05-10/13:21:53.553 zvol cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 rebuild status change: ACTIVE DATASET REBUILD INPROGRESS -> ERRORED
0xaf41b07f46a84091 pool_state=0x0 pool_context=0x0 pool_failmode=
 "wait" zio_err=0x34 zio_flags=0x808881 zio_stage=0x800000 zio_pipeline=
 0x840000 zio_delay=0x0 zio_timestamp=0x0 zio_delta=0x0 zio_objset=0x672
 zio_object=0x1 zio_level=0x0 zio_blkid=0xbb8b709 time=[ 0x60993371 0x0 ] eid=
 0x106

2021-05-10/13:21:53.557 ERROR uzfs_zvol_rebuild_dw_replica thread exiting, rebuilding failed zvol: cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 on fd(35)
2021-05-10/13:21:53.558 ERROR ZFS event:

ereport.fs.zfs.checksum ena=0x13aabb331fbffc01 detector=[ version=0x0 scheme=
 "zfs" pool=0xaf41b07f46a84091 vdev=0xc42712fdd43485d1 ] pool=
 "cstor-67623196-d6e5-4956-9eb4-db81259c9089" pool_guid=0xaf41b07f46a84091
 pool_state=0x0 pool_context=0x0 pool_failmode="wait" vdev_guid=
 0xc42712fdd43485d1 vdev_type="disk" vdev_path=
 "/dev/disk/by-id/usb-WDC_WD30_EZRZ-00Z5HB0_74D7334E6AEA955-0:0-part1"
 vdev_devid="usb-WDC_WD30_EZRZ-00Z5HB0_74D7334E6AEA955-0:0-part1" vdev_ashift=
 0x9 vdev_complete_ts=0x7a13aabcb8d3e vdev_delta_ts=0x1064cc vdev_read_errors=
 0x0 vdev_write_errors=0x0 vdev_cksum_errors=0x61 parent_guid=
 0xaf41b07f46a84091 parent_type="root" vdev_spare_paths=[...] vdev_spare_guids=
 [ ] zio_err=0x34 zio_flags=0x188881 zio_stage=0x400000 zio_pipeline=0xf80000
 zio_delay=0x102774 zio_timestamp=0x7a13aabbb2872 zio_delta=0x106426
 zio_offset=0x22ccabc8000 zio_size=0x600 zio_objset=0x672 zio_object=0x1
 zio_level=0x0 zio_blkid=0xbb8b709 cksum_expected=[ 0x62e9e4cba8 
 0x4d2f6a55e58f 0x268a30b55726b3 0xe87068494f0857b ] cksum_actual=[ 
 0x521eebd2e1 0x3663b8bc8a3c 0x16fa217ee50828 0x767214e45f7084f ]
 cksum_algorithm="fletcher4" time=[ 0x60993371 0x0 ] eid=0x107

2021-05-10/13:21:53.560 ERROR ZFS event:

ereport.fs.zfs.checksum ena=0x13aabb331fbffc01 detector=[ version=0x0 scheme=
 "zfs" pool=0xaf41b07f46a84091 vdev=0xc42712fdd43485d1 ] pool=
 "cstor-67623196-d6e5-4956-9eb4-db81259c9089" pool_guid=0xaf41b07f46a84091
 pool_state=0x0 pool_context=0x0 pool_failmode="wait" vdev_guid=
 0xc42712fdd43485d1 vdev_type="disk" vdev_path=
 "/dev/disk/by-id/usb-WDC_WD30_EZRZ-00Z5HB0_74D7334E6AEA955-0:0-part1"
 vdev_devid="usb-WDC_WD30_EZRZ-00Z5HB0_74D7334E6AEA955-0:0-part1" vdev_ashift=
 0x9 vdev_complete_ts=0x7a13aab9b875d vdev_delta_ts=0xc241f vdev_read_errors=
 0x0 vdev_write_errors=0x0 vdev_cksum_errors=0x60 parent_guid=
 0xaf41b07f46a84091 parent_type="root" vdev_spare_paths=[...] vdev_spare_guids=
 [ ] zio_err=0x34 zio_flags=0x180880 zio_stage=0x400000 zio_pipeline=0xf80000
 zio_delay=0xbf7a2 zio_timestamp=0x7a13aab8f633e zio_delta=0xc2378 zio_offset=
 0x22ccabc8000 zio_size=0x600 zio_objset=0x672 zio_object=0x1 zio_level=0x0
 zio_blkid=0xbb8b709 cksum_expected=[ 0x62e9e4cba8 0x4d2f6a55e58f 
 0x268a30b55726b3 0xe87068494f0857b ] cksum_actual=[ 0x521eebd2e1 
 0x3663b8bc8a3c 0x16fa217ee50828 0x767214e45f7084f ] cksum_algorithm=
 "fletcher4" time=[ 0x60993371 0x0 ] eid=0x108

XXX ZFS_ZEVENT_WAIT on CV 0x7f8e0d2b18, LOCK 0x7f8e0d2aa8
2021-05-10/13:21:53.577 ERROR Socket write error: Broken pipe
2021-05-10/13:21:53.577 ERROR [fd:39]socket write err: No such file or directory
2021-05-10/13:21:53.577 ERROR rebuilding already errored.. for cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934..
2021-05-10/13:21:53.578 zvol cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 rebuild status change: ERRORED -> ERRORED
2021-05-10/13:21:53.577 ERROR Socket write error: Broken pipe
2021-05-10/13:21:53.578 ERROR [fd:39]socket write err: No such file or directory
2021-05-10/13:21:53.577 ERROR [cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934:39] errored at ack_sender
2021-05-10/13:21:53.578 ERROR uzfs_zvol_rebuild_dw_replica thread exiting, rebuilding failed zvol: cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 on fd(28)
2021-05-10/13:21:53.578 ERROR [cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934:39]Rebuild scanning failed err:-1
2021-05-10/13:21:53.578 closing snap on conn break cstor-67623196-d6e5-4956-9eb4-db81259c9089/[email protected]_snap184332695.1620631816
2021-05-10/13:21:53.578 zvol cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 rebuild status change: ERRORED -> FAILED
2021-05-10/13:21:56.089 Closing rebuild connection for zvol cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 from sock(39)
2021-05-10/13:22:03.454 zvol cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 rebuild status change: FAILED -> INIT
2021-05-10/13:22:03.454 zvol cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 rebuild status change: INIT -> INIT
2021-05-10/13:22:03.495 zvol cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 rebuild status change: INIT -> SNAP REBUILD INPROGRESS
2021-05-10/13:22:03.496 [pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934:16] at 10.42.1.154:3233 helping in rebuild
2021-05-10/13:22:03.502 zvol cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 rebuild status change: SNAP REBUILD INPROGRESS -> ACTIVE DATASET REBUILD INPROGRESS
2021-05-10/13:22:03.504 Volume:cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 has zvol_guid:9145514214743931833
2021-05-10/13:22:03.504 IO sequence number:184332695 Degraded IO sequence number:203071195
2021-05-10/13:22:03.505 [cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934:35] at 10.42.0.136:3233 helping in rebuild
2021-05-10/13:22:03.506 Rebuild started from clone for vol cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 on fd(16)
2021-05-10/13:22:03.510 New rebuild connection on fd 39
2021-05-10/13:22:05.511 Rebuild scanner started on zvol cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934 from sock(39)
2021-05-10/13:22:07.511 Checkpointed IO_seq: 184332695, Rebuild Req offset: 0, Rebuild Req length: 10737418240 for zvol(cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934)
2021-05-10/13:22:08.102 zvol cstor-67623196-d6e5-4956-9eb4-db81259c9089/[email protected]_snap184332695.1620652927 status change: DEGRADED -> DEGRADED
2021-05-10/13:22:08.103 zvol cstor-67623196-d6e5-4956-9eb4-db81259c9089/[email protected]_snap184332695.1620652927 rebuild status change: INIT -> INIT
2021-05-10/14:01:59.308 Checkpointed IO_seq: 184332695, Rebuild Req offset: 10737418240, Rebuild Req length: 10737418240 for zvol(cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934)
2021-05-10/14:03:35.017 Checkpointed IO_seq: 184332695, Rebuild Req offset: 21474836480, Rebuild Req length: 10737418240 for zvol(cstor-67623196-d6e5-4956-9eb4-db81259c9089/pvc-d34d58e4-d2c0-48cc-8d8e-69df0d197934)
202

Expected Behavior

The above issue happens because of a checksum error from the rebuild scanner. CVR should report this information, i.e rebuild failure details/history with an error or rebuild mode.

Possible Solution

A possible solution for this issue is to run a scrub on the pool.
command:

zpool scrub <POOL_NAME>

For debugability, CVR should have this information about rebuild error and possible reasons. This will ease the debugging process. Since running scrub is a manual process, having this information in CVR will be helpful to the user. later this can be automated through the cstor control plane.

Steps to Reproduce

Since this issue happens because of a checksum error, it can be reproduced by injecting an error in the rebuild scanner in AFS mode. This will require a code modification.

Your Environment

openebs version: 2.1.0

[sgielen]

I had a call with @mynktl about this issue. This is what I took from the call, please correct me if necessary @mynktl :-)

The first topic we discussed was how to resolve the issue in the cluster. We went for a different solution than described above. The issue occurs when rebuilding from the local on-disk data, which has a checksum error. ZFS only uses the on-disk data for rebuilding, because it considers the on-disk data to be up-to-date wrt the healthy replicas. We work-around the checksum issue by forcing ZFS to rebuild from a healthy replica instead of the on-disk data, by creating a volume snapshot on the healthy replicas. Since I have Velero installed on my cluster, we will use it to create the snapshot as it is the quickest way. Normally, this volume excluded from Velero backups.

1. I disabled periodic Velero backups as I am about to include this volume in Velero, and don't want it backed up remotely.
2. I edit the PV that fails to rebuild, and remove velero.io/exclude-from-backup: "true" to include it.
3. I create a local VolumeSnapshotLocation in the cluster called local-backup.
4. I create a velero backup with this snapshot location: velero backup create localbackup --include-namespaces=samba --snapshot-volumes --volume-snapshot-locations=local-backup.
5. When the Velero process picks up this backup, it immediately creates local snapshots in all of the PVCs in the samba namespace. The rebuild immediately restarts (zvol ... is not healthy and rebuild is going on, can't take the localbackup snapshot, erroring out the rebuild & Rebuilding from zv:...@localbackup)

The rebuild is now running, I'll update this ticket when I know more.

The second topic we discussed was how to detect & report the issue in the software. However, as I understood it, the software currently used for extracting information and updating the CStorVolumeReplica object in the cluster, cstor-pool-mgmt / maya-exporter, is outdated and will be replaced by cstor-csi which will already implement better error reporting functionality. So, we decided not to update the current software.

[sgielen]

After the steps in the previous comment, the ±1.5 TB volume successfully finished its rebuild just now :-)

[kmova]

@sgielen - would it be possible for you to push in a comment to #2719 with information on how you are using cStor or raise a PR to this page (https://github.com/openebs/openebs/blob/master/ADOPTERS.md) with details.