fstests: btrfs/09[58]: Use hash to replace unreliable od output
diff mbox series

Message ID 20191212053034.21995-1-wqu@suse.com
State New
Headers show
Series
  • fstests: btrfs/09[58]: Use hash to replace unreliable od output
Related show

Commit Message

Qu Wenruo Dec. 12, 2019, 5:30 a.m. UTC
[BUG]
With latest master, btrfs/09[58] fails like:

  btrfs/095 2s ... - output mismatch (see xfstests-dev/results//btrfs/095.out.bad)
      --- tests/btrfs/095.out     2019-12-12 13:23:24.266697540 +0800
      +++ xfstests-dev/results//btrfs/095.out.bad      2019-12-12 13:23:29.340030879 +0800
      @@ -4,32 +4,32 @@
       File contents before power failure:
       0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
       *
      -207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
      +771 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
       *
      -226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
      ...
      (Run 'diff -u xfstests-dev/tests/btrfs/095.out xfstests-dev/results//btrfs/095.out.bad'  to see the entire diff)
  btrfs/098 2s ... - output mismatch (see xfstests-dev/results//btrfs/098.out.bad)
      --- tests/btrfs/098.out     2019-12-12 13:23:24.266697540 +0800
      +++ xfstests-dev/results//btrfs/098.out.bad      2019-12-12 13:23:31.306697545 +0800
      @@ -3,20 +3,20 @@
       File contents before power failure:
       0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
       *
      -144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
      +537 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
       *
      -151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
      ...
      (Run 'diff -u xfstests-dev/tests/btrfs/098.out xfstests-dev/results//btrfs/098.out.bad'  to see the entire diff)
  Ran: btrfs/095 btrfs/098
  Failures: btrfs/095 btrfs/098
  Failed 2 of 2 tests

[CAUSE]
It looks like commit 37520a314bd4 ("fstests: Don't use gawk's strtonum")
is making _filter_od doing stupid filtering.

[FIX]
Personally speaking, I don't really care about whatever _filter_od is
doing at all.
And since these two test cases only care about the content, let's use
hash to replace unreliable _filter_od output.
While move the filtered (and meaningless) od output to $seqres.full.

Reported-by: Nikolay Borisov <nborisov@suse.com>
Signed-off-by: Qu Wenruo <wqu@suse.com>
---
 tests/btrfs/095     | 13 +++++++++----
 tests/btrfs/095.out | 36 ++++--------------------------------
 tests/btrfs/098     | 14 ++++++++++----
 tests/btrfs/098.out | 24 ++++--------------------
 4 files changed, 27 insertions(+), 60 deletions(-)

Comments

Naohiro Aota Dec. 12, 2019, 5:37 a.m. UTC | #1
On Thu, Dec 12, 2019 at 01:30:34PM +0800, Qu Wenruo wrote:
>[BUG]
>With latest master, btrfs/09[58] fails like:
>
>  btrfs/095 2s ... - output mismatch (see xfstests-dev/results//btrfs/095.out.bad)
>      --- tests/btrfs/095.out     2019-12-12 13:23:24.266697540 +0800
>      +++ xfstests-dev/results//btrfs/095.out.bad      2019-12-12 13:23:29.340030879 +0800
>      @@ -4,32 +4,32 @@
>       File contents before power failure:
>       0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>       *
>      -207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>      +771 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>       *
>      -226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
>      ...
>      (Run 'diff -u xfstests-dev/tests/btrfs/095.out xfstests-dev/results//btrfs/095.out.bad'  to see the entire diff)
>  btrfs/098 2s ... - output mismatch (see xfstests-dev/results//btrfs/098.out.bad)
>      --- tests/btrfs/098.out     2019-12-12 13:23:24.266697540 +0800
>      +++ xfstests-dev/results//btrfs/098.out.bad      2019-12-12 13:23:31.306697545 +0800
>      @@ -3,20 +3,20 @@
>       File contents before power failure:
>       0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>       *
>      -144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>      +537 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>       *
>      -151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>      ...
>      (Run 'diff -u xfstests-dev/tests/btrfs/098.out xfstests-dev/results//btrfs/098.out.bad'  to see the entire diff)
>  Ran: btrfs/095 btrfs/098
>  Failures: btrfs/095 btrfs/098
>  Failed 2 of 2 tests
>
>[CAUSE]
>It looks like commit 37520a314bd4 ("fstests: Don't use gawk's strtonum")
>is making _filter_od doing stupid filtering.

I sent a fix to the list. That commit is parsing od's offsets as decimal
which actually is octal.

https://lore.kernel.org/fstests/20191212031152.1906287-1-naohiro.aota@wdc.com/T/#u

>[FIX]
>Personally speaking, I don't really care about whatever _filter_od is
>doing at all.
>And since these two test cases only care about the content, let's use
>hash to replace unreliable _filter_od output.
>While move the filtered (and meaningless) od output to $seqres.full.

I think using hash break the tests on non-4k blocks.

Actually, they both once used hash, but changed to use od with commit
55144172825f ("btrfs/095: work on non-4k block sized filesystems") and
commit 2099e00681dd ("btrfs/098: work on non-4k block sized filesystems").

>
>Reported-by: Nikolay Borisov <nborisov@suse.com>
>Signed-off-by: Qu Wenruo <wqu@suse.com>
>---
> tests/btrfs/095     | 13 +++++++++----
> tests/btrfs/095.out | 36 ++++--------------------------------
> tests/btrfs/098     | 14 ++++++++++----
> tests/btrfs/098.out | 24 ++++--------------------
> 4 files changed, 27 insertions(+), 60 deletions(-)
>
>diff --git a/tests/btrfs/095 b/tests/btrfs/095
>index 4c810a5d..4b381a9e 100755
>--- a/tests/btrfs/095
>+++ b/tests/btrfs/095
>@@ -122,8 +122,10 @@ $CLONER_PROG -s $((768 * $BLOCK_SIZE)) -d $((150 * $BLOCK_SIZE)) -l $((25 * $BLO
> # fsync and before the next transaction commit.
> $XFS_IO_PROG -c "fsync" $SCRATCH_MNT/foo
>
>-echo "File contents before power failure:"
>-od -t x1 $SCRATCH_MNT/foo | _filter_od
>+echo "File hash before power failure:"
>+_md5_checksum $SCRATCH_MNT/foo
>+echo "File contens before power failure:" >> $seqres.full
>+od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
>
> # During log replay, the btrfs delayed references implementation used to run the
> # deletion of back references before the addition of new back references, which
>@@ -135,8 +137,11 @@ od -t x1 $SCRATCH_MNT/foo | _filter_od
> # failure of the insertion that ended up turning the fs into read-only mode.
> _flakey_drop_and_remount
>
>-echo "File contents after log replay:"
>-od -t x1 $SCRATCH_MNT/foo | _filter_od
>+echo "File hash after log replay:"
>+_md5_checksum $SCRATCH_MNT/foo
>+
>+echo "File contents after log replay:" >> $seqres.full
>+od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
>
> _unmount_flakey
>
>diff --git a/tests/btrfs/095.out b/tests/btrfs/095.out
>index e73b24d5..5c3ec951 100644
>--- a/tests/btrfs/095.out
>+++ b/tests/btrfs/095.out
>@@ -1,35 +1,7 @@
> QA output created by 095
> Blocks modified: [135 - 164]
> Blocks modified: [768 - 792]
>-File contents before power failure:
>-0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>-*
>-207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>-*
>-226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
>-*
>-257 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>-*
>-1137 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>-*
>-1175 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>-*
>-1400 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
>-*
>-1431
>-File contents after log replay:
>-0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>-*
>-207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>-*
>-226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
>-*
>-257 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>-*
>-1137 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>-*
>-1175 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>-*
>-1400 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
>-*
>-1431
>+File hash before power failure:
>+beaf47c36659ac29bb9363fb8ffa10a1
>+File hash after log replay:
>+beaf47c36659ac29bb9363fb8ffa10a1
>diff --git a/tests/btrfs/098 b/tests/btrfs/098
>index 0e0b5123..e42e3146 100755
>--- a/tests/btrfs/098
>+++ b/tests/btrfs/098
>@@ -69,8 +69,11 @@ $CLONER_PROG -s $(((200 * $BLOCK_SIZE) + (5 * $BLOCK_SIZE))) \
> # first fsync we did before.
> $XFS_IO_PROG -c "fsync" $SCRATCH_MNT/foo
>
>-echo "File contents before power failure:"
>-od -t x1 $SCRATCH_MNT/foo | _filter_od
>+
>+echo "File hash before power failure:"
>+_md5_checksum $SCRATCH_MNT/foo
>+echo "File contents before power failure:" >> $seqres.full
>+od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
>
> # The fsync log replay first processes the file extent item corresponding to the
> # file offset mapped by 100th block (the one which refers to the [5, 10[ block
>@@ -95,10 +98,13 @@ od -t x1 $SCRATCH_MNT/foo | _filter_od
> #
> _flakey_drop_and_remount
>
>-echo "File contents after log replay:"
> # Must match the file contents we had after cloning the extent and before
> # the power failure happened.
>-od -t x1 $SCRATCH_MNT/foo | _filter_od
>+echo "File hash after log replay:"
>+_md5_checksum $SCRATCH_MNT/foo
>+
>+echo "File contents after log replay:" >> $seqres.full
>+od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
>
> _unmount_flakey
>
>diff --git a/tests/btrfs/098.out b/tests/btrfs/098.out
>index 98a96dec..e3db64a0 100644
>--- a/tests/btrfs/098.out
>+++ b/tests/btrfs/098.out
>@@ -1,22 +1,6 @@
> QA output created by 098
> Blocks modified: [200 - 224]
>-File contents before power failure:
>-0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>-*
>-144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>-*
>-151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>-*
>-310 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>-*
>-341
>-File contents after log replay:
>-0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>-*
>-144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>-*
>-151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>-*
>-310 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>-*
>-341
>+File hash before power failure:
>+39b386375971248740ed8651d5a2ed9f
>+File hash after log replay:
>+39b386375971248740ed8651d5a2ed9f
>-- 
>2.23.0
>
Qu Wenruo Dec. 12, 2019, 5:54 a.m. UTC | #2
On 2019/12/12 下午1:37, Naohiro Aota wrote:
> On Thu, Dec 12, 2019 at 01:30:34PM +0800, Qu Wenruo wrote:
>> [BUG]
>> With latest master, btrfs/09[58] fails like:
>>
>>  btrfs/095 2s ... - output mismatch (see
>> xfstests-dev/results//btrfs/095.out.bad)
>>      --- tests/btrfs/095.out     2019-12-12 13:23:24.266697540 +0800
>>      +++ xfstests-dev/results//btrfs/095.out.bad      2019-12-12
>> 13:23:29.340030879 +0800
>>      @@ -4,32 +4,32 @@
>>       File contents before power failure:
>>       0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>>       *
>>      -207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>>      +771 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>>       *
>>      -226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
>>      ...
>>      (Run 'diff -u xfstests-dev/tests/btrfs/095.out
>> xfstests-dev/results//btrfs/095.out.bad'  to see the entire diff)
>>  btrfs/098 2s ... - output mismatch (see
>> xfstests-dev/results//btrfs/098.out.bad)
>>      --- tests/btrfs/098.out     2019-12-12 13:23:24.266697540 +0800
>>      +++ xfstests-dev/results//btrfs/098.out.bad      2019-12-12
>> 13:23:31.306697545 +0800
>>      @@ -3,20 +3,20 @@
>>       File contents before power failure:
>>       0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>>       *
>>      -144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>>      +537 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>>       *
>>      -151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>>      ...
>>      (Run 'diff -u xfstests-dev/tests/btrfs/098.out
>> xfstests-dev/results//btrfs/098.out.bad'  to see the entire diff)
>>  Ran: btrfs/095 btrfs/098
>>  Failures: btrfs/095 btrfs/098
>>  Failed 2 of 2 tests
>>
>> [CAUSE]
>> It looks like commit 37520a314bd4 ("fstests: Don't use gawk's strtonum")
>> is making _filter_od doing stupid filtering.
>
> I sent a fix to the list. That commit is parsing od's offsets as decimal
> which actually is octal.
>
> https://lore.kernel.org/fstests/20191212031152.1906287-1-naohiro.aota@wdc.com/T/#u

Oh, that's much better.

Although that _filter_od still seems can't handle hex.

But anyway, that's a better root solution.
>
>
>> [FIX]
>> Personally speaking, I don't really care about whatever _filter_od is
>> doing at all.
>> And since these two test cases only care about the content, let's use
>> hash to replace unreliable _filter_od output.
>> While move the filtered (and meaningless) od output to $seqres.full.
>
> I think using hash break the tests on non-4k blocks.
>
> Actually, they both once used hash, but changed to use od with commit
> 55144172825f ("btrfs/095: work on non-4k block sized filesystems") and
> commit 2099e00681dd ("btrfs/098: work on non-4k block sized filesystems").

Forgot that.

Thanks for the info,
Qu
>
>>
>> Reported-by: Nikolay Borisov <nborisov@suse.com>
>> Signed-off-by: Qu Wenruo <wqu@suse.com>
>> ---
>> tests/btrfs/095     | 13 +++++++++----
>> tests/btrfs/095.out | 36 ++++--------------------------------
>> tests/btrfs/098     | 14 ++++++++++----
>> tests/btrfs/098.out | 24 ++++--------------------
>> 4 files changed, 27 insertions(+), 60 deletions(-)
>>
>> diff --git a/tests/btrfs/095 b/tests/btrfs/095
>> index 4c810a5d..4b381a9e 100755
>> --- a/tests/btrfs/095
>> +++ b/tests/btrfs/095
>> @@ -122,8 +122,10 @@ $CLONER_PROG -s $((768 * $BLOCK_SIZE)) -d $((150
>> * $BLOCK_SIZE)) -l $((25 * $BLO
>> # fsync and before the next transaction commit.
>> $XFS_IO_PROG -c "fsync" $SCRATCH_MNT/foo
>>
>> -echo "File contents before power failure:"
>> -od -t x1 $SCRATCH_MNT/foo | _filter_od
>> +echo "File hash before power failure:"
>> +_md5_checksum $SCRATCH_MNT/foo
>> +echo "File contens before power failure:" >> $seqres.full
>> +od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
>>
>> # During log replay, the btrfs delayed references implementation used
>> to run the
>> # deletion of back references before the addition of new back
>> references, which
>> @@ -135,8 +137,11 @@ od -t x1 $SCRATCH_MNT/foo | _filter_od
>> # failure of the insertion that ended up turning the fs into read-only
>> mode.
>> _flakey_drop_and_remount
>>
>> -echo "File contents after log replay:"
>> -od -t x1 $SCRATCH_MNT/foo | _filter_od
>> +echo "File hash after log replay:"
>> +_md5_checksum $SCRATCH_MNT/foo
>> +
>> +echo "File contents after log replay:" >> $seqres.full
>> +od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
>>
>> _unmount_flakey
>>
>> diff --git a/tests/btrfs/095.out b/tests/btrfs/095.out
>> index e73b24d5..5c3ec951 100644
>> --- a/tests/btrfs/095.out
>> +++ b/tests/btrfs/095.out
>> @@ -1,35 +1,7 @@
>> QA output created by 095
>> Blocks modified: [135 - 164]
>> Blocks modified: [768 - 792]
>> -File contents before power failure:
>> -0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>> -*
>> -207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>> -*
>> -226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
>> -*
>> -257 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>> -*
>> -1137 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>> -*
>> -1175 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>> -*
>> -1400 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
>> -*
>> -1431
>> -File contents after log replay:
>> -0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>> -*
>> -207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>> -*
>> -226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
>> -*
>> -257 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>> -*
>> -1137 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>> -*
>> -1175 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>> -*
>> -1400 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
>> -*
>> -1431
>> +File hash before power failure:
>> +beaf47c36659ac29bb9363fb8ffa10a1
>> +File hash after log replay:
>> +beaf47c36659ac29bb9363fb8ffa10a1
>> diff --git a/tests/btrfs/098 b/tests/btrfs/098
>> index 0e0b5123..e42e3146 100755
>> --- a/tests/btrfs/098
>> +++ b/tests/btrfs/098
>> @@ -69,8 +69,11 @@ $CLONER_PROG -s $(((200 * $BLOCK_SIZE) + (5 *
>> $BLOCK_SIZE))) \
>> # first fsync we did before.
>> $XFS_IO_PROG -c "fsync" $SCRATCH_MNT/foo
>>
>> -echo "File contents before power failure:"
>> -od -t x1 $SCRATCH_MNT/foo | _filter_od
>> +
>> +echo "File hash before power failure:"
>> +_md5_checksum $SCRATCH_MNT/foo
>> +echo "File contents before power failure:" >> $seqres.full
>> +od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
>>
>> # The fsync log replay first processes the file extent item
>> corresponding to the
>> # file offset mapped by 100th block (the one which refers to the [5,
>> 10[ block
>> @@ -95,10 +98,13 @@ od -t x1 $SCRATCH_MNT/foo | _filter_od
>> #
>> _flakey_drop_and_remount
>>
>> -echo "File contents after log replay:"
>> # Must match the file contents we had after cloning the extent and before
>> # the power failure happened.
>> -od -t x1 $SCRATCH_MNT/foo | _filter_od
>> +echo "File hash after log replay:"
>> +_md5_checksum $SCRATCH_MNT/foo
>> +
>> +echo "File contents after log replay:" >> $seqres.full
>> +od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
>>
>> _unmount_flakey
>>
>> diff --git a/tests/btrfs/098.out b/tests/btrfs/098.out
>> index 98a96dec..e3db64a0 100644
>> --- a/tests/btrfs/098.out
>> +++ b/tests/btrfs/098.out
>> @@ -1,22 +1,6 @@
>> QA output created by 098
>> Blocks modified: [200 - 224]
>> -File contents before power failure:
>> -0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>> -*
>> -144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>> -*
>> -151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>> -*
>> -310 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>> -*
>> -341
>> -File contents after log replay:
>> -0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>> -*
>> -144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>> -*
>> -151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>> -*
>> -310 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>> -*
>> -341
>> +File hash before power failure:
>> +39b386375971248740ed8651d5a2ed9f
>> +File hash after log replay:
>> +39b386375971248740ed8651d5a2ed9f
>> -- 
>> 2.23.0
>>
Naohiro Aota Dec. 12, 2019, 7:12 a.m. UTC | #3
On Thu, Dec 12, 2019 at 01:54:43PM +0800, Qu Wenruo wrote:
>
>
>On 2019/12/12 下午1:37, Naohiro Aota wrote:
>> On Thu, Dec 12, 2019 at 01:30:34PM +0800, Qu Wenruo wrote:
>>> [BUG]
>>> With latest master, btrfs/09[58] fails like:
>>>
>>>  btrfs/095 2s ... - output mismatch (see
>>> xfstests-dev/results//btrfs/095.out.bad)
>>>      --- tests/btrfs/095.out     2019-12-12 13:23:24.266697540 +0800
>>>      +++ xfstests-dev/results//btrfs/095.out.bad      2019-12-12
>>> 13:23:29.340030879 +0800
>>>      @@ -4,32 +4,32 @@
>>>       File contents before power failure:
>>>       0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>>>       *
>>>      -207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>>>      +771 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>>>       *
>>>      -226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
>>>      ...
>>>      (Run 'diff -u xfstests-dev/tests/btrfs/095.out
>>> xfstests-dev/results//btrfs/095.out.bad'  to see the entire diff)
>>>  btrfs/098 2s ... - output mismatch (see
>>> xfstests-dev/results//btrfs/098.out.bad)
>>>      --- tests/btrfs/098.out     2019-12-12 13:23:24.266697540 +0800
>>>      +++ xfstests-dev/results//btrfs/098.out.bad      2019-12-12
>>> 13:23:31.306697545 +0800
>>>      @@ -3,20 +3,20 @@
>>>       File contents before power failure:
>>>       0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>>>       *
>>>      -144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>>>      +537 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>>>       *
>>>      -151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>>>      ...
>>>      (Run 'diff -u xfstests-dev/tests/btrfs/098.out
>>> xfstests-dev/results//btrfs/098.out.bad'  to see the entire diff)
>>>  Ran: btrfs/095 btrfs/098
>>>  Failures: btrfs/095 btrfs/098
>>>  Failed 2 of 2 tests
>>>
>>> [CAUSE]
>>> It looks like commit 37520a314bd4 ("fstests: Don't use gawk's strtonum")
>>> is making _filter_od doing stupid filtering.
>>
>> I sent a fix to the list. That commit is parsing od's offsets as decimal
>> which actually is octal.
>>
>> https://lore.kernel.org/fstests/20191212031152.1906287-1-naohiro.aota@wdc.com/T/#u
>
>Oh, that's much better.
>
>Although that _filter_od still seems can't handle hex.

I agree with you that ocatal makes no sense these days. I'm considering to
extend _filter_od to take an argument to specify "oct|dec|hex" so that
callers can use "od -A x" and see outputs in hex (or decimal).

Thanks,
Filipe Manana Dec. 12, 2019, 3:04 p.m. UTC | #4
On Thu, Dec 12, 2019 at 5:30 AM Qu Wenruo <wqu@suse.com> wrote:
>
> [BUG]
> With latest master, btrfs/09[58] fails like:
>
>   btrfs/095 2s ... - output mismatch (see xfstests-dev/results//btrfs/095.out.bad)
>       --- tests/btrfs/095.out     2019-12-12 13:23:24.266697540 +0800
>       +++ xfstests-dev/results//btrfs/095.out.bad      2019-12-12 13:23:29.340030879 +0800
>       @@ -4,32 +4,32 @@
>        File contents before power failure:
>        0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>        *
>       -207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>       +771 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>        *
>       -226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
>       ...
>       (Run 'diff -u xfstests-dev/tests/btrfs/095.out xfstests-dev/results//btrfs/095.out.bad'  to see the entire diff)
>   btrfs/098 2s ... - output mismatch (see xfstests-dev/results//btrfs/098.out.bad)
>       --- tests/btrfs/098.out     2019-12-12 13:23:24.266697540 +0800
>       +++ xfstests-dev/results//btrfs/098.out.bad      2019-12-12 13:23:31.306697545 +0800
>       @@ -3,20 +3,20 @@
>        File contents before power failure:
>        0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>        *
>       -144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>       +537 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
>        *
>       -151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>       ...
>       (Run 'diff -u xfstests-dev/tests/btrfs/098.out xfstests-dev/results//btrfs/098.out.bad'  to see the entire diff)
>   Ran: btrfs/095 btrfs/098
>   Failures: btrfs/095 btrfs/098
>   Failed 2 of 2 tests
>
> [CAUSE]
> It looks like commit 37520a314bd4 ("fstests: Don't use gawk's strtonum")
> is making _filter_od doing stupid filtering.
>
> [FIX]
> Personally speaking, I don't really care about whatever _filter_od is
> doing at all.
> And since these two test cases only care about the content, let's use
> hash to replace unreliable _filter_od output.

Nop, this won't work.
Have you read carefully the tests and the changelogs?

The file contents are different depending on the page size of the
system where it runs. If you look at the tests, they do things like:

$CLONER_PROG -s $(((200 * $BLOCK_SIZE) + (5 * $BLOCK_SIZE))) ....

So hardcoding a checksum in the golden output is not an option, it
won't be the same on x86 as on powerpc (with a page size of 64Kb).

> While move the filtered (and meaningless) od output to $seqres.full.

Well, it does't make sense to use the filter for the output to $seqres.full.

Given that the author of the commit that introduced the regression is
asking Eryu to revert it, as it's causing problems on xfs tests as
well, this won't be necessary.

Thanks.

>
> Reported-by: Nikolay Borisov <nborisov@suse.com>
> Signed-off-by: Qu Wenruo <wqu@suse.com>
> ---
>  tests/btrfs/095     | 13 +++++++++----
>  tests/btrfs/095.out | 36 ++++--------------------------------
>  tests/btrfs/098     | 14 ++++++++++----
>  tests/btrfs/098.out | 24 ++++--------------------
>  4 files changed, 27 insertions(+), 60 deletions(-)
>
> diff --git a/tests/btrfs/095 b/tests/btrfs/095
> index 4c810a5d..4b381a9e 100755
> --- a/tests/btrfs/095
> +++ b/tests/btrfs/095
> @@ -122,8 +122,10 @@ $CLONER_PROG -s $((768 * $BLOCK_SIZE)) -d $((150 * $BLOCK_SIZE)) -l $((25 * $BLO
>  # fsync and before the next transaction commit.
>  $XFS_IO_PROG -c "fsync" $SCRATCH_MNT/foo
>
> -echo "File contents before power failure:"
> -od -t x1 $SCRATCH_MNT/foo | _filter_od
> +echo "File hash before power failure:"
> +_md5_checksum $SCRATCH_MNT/foo
> +echo "File contens before power failure:" >> $seqres.full
> +od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
>
>  # During log replay, the btrfs delayed references implementation used to run the
>  # deletion of back references before the addition of new back references, which
> @@ -135,8 +137,11 @@ od -t x1 $SCRATCH_MNT/foo | _filter_od
>  # failure of the insertion that ended up turning the fs into read-only mode.
>  _flakey_drop_and_remount
>
> -echo "File contents after log replay:"
> -od -t x1 $SCRATCH_MNT/foo | _filter_od
> +echo "File hash after log replay:"
> +_md5_checksum $SCRATCH_MNT/foo
> +
> +echo "File contents after log replay:" >> $seqres.full
> +od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
>
>  _unmount_flakey
>
> diff --git a/tests/btrfs/095.out b/tests/btrfs/095.out
> index e73b24d5..5c3ec951 100644
> --- a/tests/btrfs/095.out
> +++ b/tests/btrfs/095.out
> @@ -1,35 +1,7 @@
>  QA output created by 095
>  Blocks modified: [135 - 164]
>  Blocks modified: [768 - 792]
> -File contents before power failure:
> -0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> -*
> -207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
> -*
> -226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
> -*
> -257 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> -*
> -1137 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
> -*
> -1175 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> -*
> -1400 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
> -*
> -1431
> -File contents after log replay:
> -0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> -*
> -207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
> -*
> -226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
> -*
> -257 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> -*
> -1137 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
> -*
> -1175 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> -*
> -1400 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
> -*
> -1431
> +File hash before power failure:
> +beaf47c36659ac29bb9363fb8ffa10a1
> +File hash after log replay:
> +beaf47c36659ac29bb9363fb8ffa10a1
> diff --git a/tests/btrfs/098 b/tests/btrfs/098
> index 0e0b5123..e42e3146 100755
> --- a/tests/btrfs/098
> +++ b/tests/btrfs/098
> @@ -69,8 +69,11 @@ $CLONER_PROG -s $(((200 * $BLOCK_SIZE) + (5 * $BLOCK_SIZE))) \
>  # first fsync we did before.
>  $XFS_IO_PROG -c "fsync" $SCRATCH_MNT/foo
>
> -echo "File contents before power failure:"
> -od -t x1 $SCRATCH_MNT/foo | _filter_od
> +
> +echo "File hash before power failure:"
> +_md5_checksum $SCRATCH_MNT/foo
> +echo "File contents before power failure:" >> $seqres.full
> +od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
>
>  # The fsync log replay first processes the file extent item corresponding to the
>  # file offset mapped by 100th block (the one which refers to the [5, 10[ block
> @@ -95,10 +98,13 @@ od -t x1 $SCRATCH_MNT/foo | _filter_od
>  #
>  _flakey_drop_and_remount
>
> -echo "File contents after log replay:"
>  # Must match the file contents we had after cloning the extent and before
>  # the power failure happened.
> -od -t x1 $SCRATCH_MNT/foo | _filter_od
> +echo "File hash after log replay:"
> +_md5_checksum $SCRATCH_MNT/foo
> +
> +echo "File contents after log replay:" >> $seqres.full
> +od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
>
>  _unmount_flakey
>
> diff --git a/tests/btrfs/098.out b/tests/btrfs/098.out
> index 98a96dec..e3db64a0 100644
> --- a/tests/btrfs/098.out
> +++ b/tests/btrfs/098.out
> @@ -1,22 +1,6 @@
>  QA output created by 098
>  Blocks modified: [200 - 224]
> -File contents before power failure:
> -0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> -*
> -144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
> -*
> -151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> -*
> -310 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
> -*
> -341
> -File contents after log replay:
> -0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> -*
> -144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
> -*
> -151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> -*
> -310 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
> -*
> -341
> +File hash before power failure:
> +39b386375971248740ed8651d5a2ed9f
> +File hash after log replay:
> +39b386375971248740ed8651d5a2ed9f
> --
> 2.23.0
>

Patch
diff mbox series

diff --git a/tests/btrfs/095 b/tests/btrfs/095
index 4c810a5d..4b381a9e 100755
--- a/tests/btrfs/095
+++ b/tests/btrfs/095
@@ -122,8 +122,10 @@  $CLONER_PROG -s $((768 * $BLOCK_SIZE)) -d $((150 * $BLOCK_SIZE)) -l $((25 * $BLO
 # fsync and before the next transaction commit.
 $XFS_IO_PROG -c "fsync" $SCRATCH_MNT/foo
 
-echo "File contents before power failure:"
-od -t x1 $SCRATCH_MNT/foo | _filter_od
+echo "File hash before power failure:"
+_md5_checksum $SCRATCH_MNT/foo
+echo "File contens before power failure:" >> $seqres.full
+od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
 
 # During log replay, the btrfs delayed references implementation used to run the
 # deletion of back references before the addition of new back references, which
@@ -135,8 +137,11 @@  od -t x1 $SCRATCH_MNT/foo | _filter_od
 # failure of the insertion that ended up turning the fs into read-only mode.
 _flakey_drop_and_remount
 
-echo "File contents after log replay:"
-od -t x1 $SCRATCH_MNT/foo | _filter_od
+echo "File hash after log replay:"
+_md5_checksum $SCRATCH_MNT/foo
+
+echo "File contents after log replay:" >> $seqres.full
+od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
 
 _unmount_flakey
 
diff --git a/tests/btrfs/095.out b/tests/btrfs/095.out
index e73b24d5..5c3ec951 100644
--- a/tests/btrfs/095.out
+++ b/tests/btrfs/095.out
@@ -1,35 +1,7 @@ 
 QA output created by 095
 Blocks modified: [135 - 164]
 Blocks modified: [768 - 792]
-File contents before power failure:
-0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-*
-207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
-*
-226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
-*
-257 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-*
-1137 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
-*
-1175 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-*
-1400 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
-*
-1431
-File contents after log replay:
-0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-*
-207 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
-*
-226 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
-*
-257 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-*
-1137 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
-*
-1175 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-*
-1400 bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb bb
-*
-1431
+File hash before power failure:
+beaf47c36659ac29bb9363fb8ffa10a1
+File hash after log replay:
+beaf47c36659ac29bb9363fb8ffa10a1
diff --git a/tests/btrfs/098 b/tests/btrfs/098
index 0e0b5123..e42e3146 100755
--- a/tests/btrfs/098
+++ b/tests/btrfs/098
@@ -69,8 +69,11 @@  $CLONER_PROG -s $(((200 * $BLOCK_SIZE) + (5 * $BLOCK_SIZE))) \
 # first fsync we did before.
 $XFS_IO_PROG -c "fsync" $SCRATCH_MNT/foo
 
-echo "File contents before power failure:"
-od -t x1 $SCRATCH_MNT/foo | _filter_od
+
+echo "File hash before power failure:"
+_md5_checksum $SCRATCH_MNT/foo
+echo "File contents before power failure:" >> $seqres.full
+od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
 
 # The fsync log replay first processes the file extent item corresponding to the
 # file offset mapped by 100th block (the one which refers to the [5, 10[ block
@@ -95,10 +98,13 @@  od -t x1 $SCRATCH_MNT/foo | _filter_od
 #
 _flakey_drop_and_remount
 
-echo "File contents after log replay:"
 # Must match the file contents we had after cloning the extent and before
 # the power failure happened.
-od -t x1 $SCRATCH_MNT/foo | _filter_od
+echo "File hash after log replay:"
+_md5_checksum $SCRATCH_MNT/foo
+
+echo "File contents after log replay:" >> $seqres.full
+od -t x1 $SCRATCH_MNT/foo | _filter_od >> $seqres.full
 
 _unmount_flakey
 
diff --git a/tests/btrfs/098.out b/tests/btrfs/098.out
index 98a96dec..e3db64a0 100644
--- a/tests/btrfs/098.out
+++ b/tests/btrfs/098.out
@@ -1,22 +1,6 @@ 
 QA output created by 098
 Blocks modified: [200 - 224]
-File contents before power failure:
-0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-*
-144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
-*
-151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-*
-310 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
-*
-341
-File contents after log replay:
-0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-*
-144 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
-*
-151 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
-*
-310 aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa aa
-*
-341
+File hash before power failure:
+39b386375971248740ed8651d5a2ed9f
+File hash after log replay:
+39b386375971248740ed8651d5a2ed9f