Re: bizare bug in "btrfs subvolume show"

[Goffredo Baroncelli <kreijack@libero.it>]

On 11/16/20 3:09 AM, Lawrence D'Anna wrote:
> 
> 
>> On Nov 15, 2020, at 1:53 AM, Roman Mamedov <rm@romanrm.net> wrote:
>>
>> This still sounds very puzzling, as to how output redirection could affect
>> things. Perhaps you could run "btrfs sub show" with "strace"? Both with and
>> without the redirect to see exactly what was the call sequence, parameters and
>> return values, to compare and find where the difference starts.
>>
>>
> 
> The first meaningful difference occurs at this ioctl:
> 
> --- /dev/fd/63	2020-11-15 18:06:23.000000000 -0800
> +++ /dev/fd/62	2020-11-15 18:06:23.000000000 -0800
> @@ -1,84 +1,84 @@
>   ioctl(3, BTRFS_IOC_TREE_SEARCH, {key={tree_id=BTRFS_ROOT_TREE_OBJECTID,
>   min_objectid=BTRFS_FS_TREE_OBJECTID, max_objectid=BTRFS_FS_TREE_OBJECTID,
>   min_offset=7274, max_offset=UINT64_MAX, min_transid=0, max_transid=UINT64_MAX,
>   min_type=BTRFS_ROOT_REF_KEY, max_type=BTRFS_ROOT_REF_KEY, nr_items=4096}} =>
>   {key={nr_items=53}, buf=[{transid=56320, objectid=BTRFS_FS_TREE_OBJECTID,
>   offset=7274, type=BTRFS_ROOT_REF_KEY, len=43}, {transid=56570,
>   objectid=BTRFS_FS_TREE_OBJECTID, offset=7275, type=BTRFS_ROOT_REF_KEY, len=43},
>   {transid=56570, objectid=BTRFS_FS_TREE_OBJECTID, offset=7276,
>   type=BTRFS_ROOT_REF_KEY, len=43}, {transid=56570,
>   objectid=BTRFS_FS_TREE_OBJECTID, offset=7277, type=BTRFS_ROOT_REF_KEY, len=43},
[...]
> -{transid=56570, objectid=BTRFS_FS_TREE_OBJECTID, offset=7290,
> +{transid=56570, objectid=BTRFS_FS_TREE_OBJECTID, offset=7168,
>   type=BTRFS_ROOT_REF_KEY, len=43}, {transid=56570,
>   objectid=BTRFS_FS_TREE_OBJECTID, offset=7291, type=BTRFS_ROOT_REF_KEY, len=43},
[...]
> 
> A little while later they diverge again when the good side does a BTRFS_IOC_TREE_SEARCH for
> 7290, and the bad side does it for 7168, which fails.
> 
> Full traces are at https://odin.elder-gods.org/btrfs-bug/a  and https://odin.elder-gods.org/btrfs-bug/b
> If you’d like to see them
> 

Definitely it is a strange behavior. The value 7168 should be the wrong one because it is out of order.
Are you sure that this behavior depends *only* by the redirect ?
If you ran "btrfs subvol show /data/" several time, you always get the same (good) value ?
And if you do it with a redirect, you always got the wrong one ?

You have a raid10 profile, so an explanation is that sometime you read from the good drive (where there is the value 7290) and sometime from the bad one (where there is the value 7168).
However this should be impossible because
1) the metadata is protected by a corruption by the checksum (may be the checksum is different in each mirror ?)
2) and it should be not strictly related to the redirection. The mirror from which the kernel reads is decided on the value 'pid % 2'.

BR

> 
> 
> 
> 
> 


-- 
gpg @keyserver.linux.it: Goffredo Baroncelli <kreijackATinwind.it>
Key fingerprint BBF5 1610 0B64 DAC6 5F7D  17B2 0EDA 9B37 8B82 E0B5