Re: misc-next and for-next: kernel BUG at fs/btrfs/extent_io.c:2350! during raid5 recovery

[Qu Wenruo <quwenruo.btrfs@gmx.com>]

On 2022/8/10 03:24, Zygo Blaxell wrote:
> On Tue, Aug 09, 2022 at 01:29:59AM -0700, Christoph Hellwig wrote:
>> On Mon, Aug 08, 2022 at 11:31:51PM -0400, Zygo Blaxell wrote:
>>> There is now a BUG_ON arising from this test case:
>>>
>>> 	[  241.051326][   T45] btrfs_print_data_csum_error: 156 callbacks suppressed
>>> 	[  241.100910][   T45] ------------[ cut here ]------------
>>> 	[  241.102531][   T45] kernel BUG at fs/btrfs/extent_io.c:2350!
>>
>> This
>>
>>          BUG_ON(!mirror_num);
>>
>> so repair_io_failure gets called with a mirror_num of 0..
>>
>>> 	[  241.128354][   T45]  clean_io_failure+0x21a/0x260
>>
>> .. from clean_io_failure.  Which starts from failrec->this_mirror and
>> tries to go back to failrec->failed_mirror using the prev_mirror
>> helper.  prev_mirror looks like:
>>
>> static int prev_mirror(const struct io_failure_record *failrec, int cur_mirror)
>> {
>>          if (cur_mirror == 1)
>> 		return failrec->num_copies;
>> 	return cur_mirror - 1;
>> }
>>
>> So the only way we could end up with a mirror = 0 is if
>> failrec->num_copies is 0.  -failrec->num_copies is initialized
>> in btrfs_get_io_failure_record by doing:
>>
>>          failrec->num_copies = btrfs_num_copies(fs_info, failrec->logical, sectorsize);
>>
>> just adter allocating the failrec.  I can't see any obvious way how
>> btrfs_num_copies would return 0, though, as for raid5 it just copies
>> from btrfs_raid_array.
>
> Judging from prior raid5 testing behavior, it looks like there's a race
> condition specific to btrfs raid5 IO.  Previous kernel versions have had
> assorted UAF bugs from time to time that KASAN tripped over, and btrfs
> replace almost never works on the first try on a real raid5 array.
> These issues were reported years ago, but nobody seems to have been
> working on them until recently.
>
> A similar test setup previously produced data corruption during raid5
> recovery, even on an otherwise idle filesystem, at a low rate (~1
> error per 100 GB).  I expect whatever bug was leading to that hasn't
> been entirely fixed yet.
>
>> Any chance you could share a script for your reproducer?
>
> The simplest reproducer is some variant of:
>
> 	mkfs.btrfs -draid5 -mraid1 /dev/vdb /dev/vdc /dev/vdd
> 	mount /dev/vdb /mnt -ocompress=zstd,noatime
> 	cd /mnt
> 	cp -a /40gb-test-data .
> 	sync
> 	while true; do
> 		find -type f -exec cat {} + > /dev/null
> 	done &
> 	while true; do
> 		cat /dev/zero > /dev/vdb
> 	done &
> 	while true; do
> 		btrfs scrub start -Bd /mnt
> 	done &
> 	wait
>
> but it can take a long time to hit a failure with something that gentle.
> I throw on some extra test workload (e.g. lots of rsyncs) to keep the
> page cache full and under memory pressure, which seems to speed up the
> failure rate to once every few hours.

I got it reproduced, although it's a different crash it has the minimal
workload so far, and it doesn't even need the race of corrupting the
disk on-the-fly:

         mkfs.btrfs -f -d raid5 -m raid5 $dev1 $dev2 $dev3 -b 1G > /dev/null
         mount $dev1 $mnt
         $fsstress -w -d $mnt -n 100 -s 1660337237
         sync
         $fssum -A -f -w /tmp/fssum.saved $mnt
         umount $mnt

         xfs_io -c "pwrite -S 0x0 1m 1023m" $dev1
         mount $dev1 $mnt
         $fssum -r /tmp/fssum.saved $mnt > /dev/null # <<< CRASH here
         umount $mnt

The point here is, before another BUG_ON() triggered, we can got the
following "unable to find logical" triggered:

[  173.089275] BTRFS critical (device dm-1): unable to find logical
18446744073709551613 length 4096
[  173.089825] BTRFS critical (device dm-1): unable to find logical 4093
length 4096
[  173.090224] BTRFS critical (device dm-1): unable to find logical
18446744073709551613 length 4096
[  173.090657] BTRFS critical (device dm-1): unable to find logical 4093
length 4096
[  173.091451] assertion failed: failrec->this_mirror ==
bbio->mirror_num, in fs/btrfs/extent_io.c:2566

I have even pinned down the offending commit: "btrfs: pass a btrfs_bio
to btrfs_repair_one_sector". (not RAID56 though)

The "unable to find logical" is caused by the fact that, we're repairing
HOLE extent, which should not happen at all.

Unfortunately I can not find out why that seemingly harmless refactor is
causing the problem.
My initial guess is the bbio->file_offset is incorrect, I need to do
more debugging using above minimal script to find out why.

Thanks,
Qu