parent transid verify failed: Fixed but re-appearing

parent transid verify failed: Fixed but re-appearing

[Hendrik Friedel]

Hello,

I have a re-occuring issue with my btrfs volume.
I am using dduper (https://github.com/Lakshmipathi/dduper/issues/39).
When running it, I get:
parent transid verify failed on 9332119748608 wanted 204976 found 204978
(reproducable when running the same dduper command)
I cured that by unmounting and
   mount -t btrfs -o nospace_cache,clear_cache /dev/sda1 /mnt/test

After that, I was able to run that dduper command without a failure.
But some days later, the same command resulted in:
   parent transid verify failed on 16465691033600 wanted 352083 found 
352085

again.

A scrub showed no error
  btrfs scrub status /dev/sda1
scrub status for c4a6a2c9-5cf0-49b8-812a-0784953f9ba3
         scrub started at Mon Oct 19 21:07:13 2020 and finished after 
15:11:10
         total bytes scrubbed: 6.56TiB with 0 errors

Filesystem info:
  btrfs fi show /dev/sda1
Label: 'DataPool1'  uuid: c4a6a2c9-5cf0-49b8-812a-0784953f9ba3
         Total devices 2 FS bytes used 6.56TiB
         devid    1 size 7.28TiB used 6.75TiB path /dev/sda1
         devid    2 size 7.28TiB used 6.75TiB path /dev/sdj1

The system has a USV. Consequently, it should not experience any power 
interruptions during writes.

I did not find any indications of it in /var/log/*
(grep  -i btrfs /var/log/* | grep -v snapper |grep sda)

What could be the reason for this re-appearing issue?

Regards,
Hendrik

Re: parent transid verify failed: Fixed but re-appearing

[Zygo Blaxell]

On Wed, Oct 21, 2020 at 09:04:36AM +0000, Hendrik Friedel wrote:
> Hello,
> 
> I have a re-occuring issue with my btrfs volume.
> I am using dduper (https://github.com/Lakshmipathi/dduper/issues/39).
> When running it, I get:
> parent transid verify failed on 9332119748608 wanted 204976 found 204978
> (reproducable when running the same dduper command)

Were there any other symptoms?  IO errors?  Inaccessible files?  Filesystem
remounted read-only?

> I cured that by unmounting and
>   mount -t btrfs -o nospace_cache,clear_cache /dev/sda1 /mnt/test

That command normally won't cure a parent transid verify failure if it
has been persisted on disk.  The only command that can fix ptvf is 'btrfs
check --repair --init-extent-tree', i.e. a full rebuild of btrfs metadata.

> After that, I was able to run that dduper command without a failure.
> But some days later, the same command resulted in:
>   parent transid verify failed on 16465691033600 wanted 352083 found 352085
> 
> again.
> 
> A scrub showed no error
>  btrfs scrub status /dev/sda1
> scrub status for c4a6a2c9-5cf0-49b8-812a-0784953f9ba3
>         scrub started at Mon Oct 19 21:07:13 2020 and finished after
> 15:11:10
>         total bytes scrubbed: 6.56TiB with 0 errors

Scrub iterates over all metadata pages and should hit ptvf if it's
on disk.

> Filesystem info:
>  btrfs fi show /dev/sda1
> Label: 'DataPool1'  uuid: c4a6a2c9-5cf0-49b8-812a-0784953f9ba3
>         Total devices 2 FS bytes used 6.56TiB
>         devid    1 size 7.28TiB used 6.75TiB path /dev/sda1
>         devid    2 size 7.28TiB used 6.75TiB path /dev/sdj1

If you have raid1 metadata (see 'btrfs fi usage') then it's possible
only one of your disks is silently dropping writes.  In that case
btrfs will recover from ptvf by replacing the missing block from the
other drive.  But there are no scrub errors or kernel messages related
to this, so there aren't any symptoms of that happening, so it seems
these ptvf are not coming from the disk.

> The system has a USV. Consequently, it should not experience any power
> interruptions during writes.
> 
> I did not find any indications of it in /var/log/*
> (grep  -i btrfs /var/log/* | grep -v snapper |grep sda)
> 
> What could be the reason for this re-appearing issue?

What kernel are you running?  Until early 2020 there was a UAF bug in tree
mod log code that could occasionally spit out harmless ptvf messages and
a few other verification messages like "bad tree block start" because
it was essentially verifying garbage from kernel RAM.  This happens a
lot while running LOGICAL_INO ioctl calls, but can also happen during
any long-running metadata write operations, including dedupe.

My original bug report was:

	https://www.spinics.net/lists/linux-btrfs/msg87425.html

This was ultimately fixed by several commits.  These are the four "tree
mod log" issues listed at:

	https://github.com/Zygo/bees/blob/master/docs/btrfs-kernel.md

Kernels after 5.4.19, 5.5.3, 5.6 and later should be OK.  4.19.103 has
3 of the 4 fixes so it should happen much less often there.

> Regards,
> Hendrik
> 

Re[2]: parent transid verify failed: Fixed but re-appearing

[Hendrik Friedel]

Hello Zygo,

thanks for your reply.

>Were there any other symptoms?  IO errors?  Inaccessible files?  Filesystem
>remounted read-only?
>
No, not at all.


>
>>  I cured that by unmounting and
>>    mount -t btrfs -o nospace_cache,clear_cache /dev/sda1 /mnt/test
>
>That command normally won't cure a parent transid verify failure if it
>has been persisted on disk.  The only command that can fix ptvf is 'btrfs
>check --repair --init-extent-tree', i.e. a full rebuild of btrfs metadata.

Hm, it would be good to document that somewhere.
I found
https://askubuntu.com/questions/157917/how-do-i-recover-a-btrfs-partition-that-will-not-mount
(there I found that recommendation)
https://stackoverflow.com/questions/46472439/fix-btrfs-btrfs-parent-transid-verify-failed-on/46472522#46472522
Here the selected answer says:

"Surfing the web I found a lot of answers recommending to clear btrfs' 
internal log by using btrfs-zero-log. I thought btrfsck could help but 
eventually I discovered the official recommendation which is to first 
just start a btrfs scrub before taking other actions!"


>
>>  After that, I was able to run that dduper command without a failure.
>>  But some days later, the same command resulted in:
>>    parent transid verify failed on 16465691033600 wanted 352083 found 352085
>>
>>  again.
>>
>>  A scrub showed no error
>>   btrfs scrub status /dev/sda1
>>  scrub status for c4a6a2c9-5cf0-49b8-812a-0784953f9ba3
>>          scrub started at Mon Oct 19 21:07:13 2020 and finished after
>>  15:11:10
>>          total bytes scrubbed: 6.56TiB with 0 errors
>
>Scrub iterates over all metadata pages and should hit ptvf if it's
>on disk.

But apparently it did not?!

>>  Filesystem info:
>>   btrfs fi show /dev/sda1
>>  Label: 'DataPool1'  uuid: c4a6a2c9-5cf0-49b8-812a-0784953f9ba3
>>          Total devices 2 FS bytes used 6.56TiB
>>          devid    1 size 7.28TiB used 6.75TiB path /dev/sda1
>>          devid    2 size 7.28TiB used 6.75TiB path /dev/sdj1
>
>If you have raid1 metadata (see 'btrfs fi usage') then it's possible

  btrfs fi usage /srv/dev-disk-by-label-DataPool1
Overall:
     Device size:                  14.55TiB
     Device allocated:             13.51TiB
     Device unallocated:            1.04TiB
     Device missing:                  0.00B
     Used:                         13.12TiB
     Free (estimated):            731.48GiB      (min: 731.48GiB)
     Data ratio:                       2.00
     Metadata ratio:                   2.00
     Global reserve:              512.00MiB      (used: 0.00B)

Data,RAID1: Size:6.74TiB, Used:6.55TiB
    /dev/sda1       6.74TiB
    /dev/sdj1       6.74TiB

Metadata,RAID1: Size:15.00GiB, Used:9.91GiB
    /dev/sda1      15.00GiB
    /dev/sdj1      15.00GiB

System,RAID1: Size:32.00MiB, Used:992.00KiB
    /dev/sda1      32.00MiB
    /dev/sdj1      32.00MiB

Unallocated:
    /dev/sda1     535.00GiB
    /dev/sdj1     535.00GiB

So it looks like it is raid1 metadata

>only one of your disks is silently dropping writes.  In that case
>btrfs will recover from ptvf by replacing the missing block from the
>other drive.  But there are no scrub errors or kernel messages related
>to this, so there aren't any symptoms of that happening, so it seems
>these ptvf are not coming from the disk.
And can this be confirmed somehow? Would be good to replace that disk 
then...

>
>>  The system has a USV. Consequently, it should not experience any power
>>  interruptions during writes.
>>
>>  I did not find any indications of it in /var/log/*
>>  (grep  -i btrfs /var/log/* | grep -v snapper |grep sda)
>>
>>  What could be the reason for this re-appearing issue?
>
>What kernel are you running?
5.6.12 since May 11th. Before that, (since Jan 5th) I ran 5.4.8.


>  Until early 2020 there was a UAF bug in tree
>mod log code that could occasionally spit out harmless ptvf messages and
>a few other verification messages like "bad tree block start" because
>it was essentially verifying garbage from kernel RAM.
Of course I did use older kernels in the past. But as I understand this 
bug, it would only give spurious error messages but not have caused any 
errors on the disk that would be now hit?

Regards,
Hendrik

Re: parent transid verify failed: Fixed but re-appearing

[Zygo Blaxell]

On Wed, Oct 21, 2020 at 06:19:02PM +0000, Hendrik Friedel wrote:
> Hello Zygo,
> 
> thanks for your reply.
> 
> > Were there any other symptoms?  IO errors?  Inaccessible files?  Filesystem
> > remounted read-only?
> > 
> No, not at all.
> 
> 
> > 
> > >  I cured that by unmounting and
> > >    mount -t btrfs -o nospace_cache,clear_cache /dev/sda1 /mnt/test
> > 
> > That command normally won't cure a parent transid verify failure if it
> > has been persisted on disk.  The only command that can fix ptvf is 'btrfs
> > check --repair --init-extent-tree', i.e. a full rebuild of btrfs metadata.
> 
> Hm, it would be good to document that somewhere.
> I found
> https://askubuntu.com/questions/157917/how-do-i-recover-a-btrfs-partition-that-will-not-mount
> (there I found that recommendation)
> https://stackoverflow.com/questions/46472439/fix-btrfs-btrfs-parent-transid-verify-failed-on/46472522#46472522
> Here the selected answer says:
> 
> "Surfing the web I found a lot of answers recommending to clear btrfs'
> internal log by using btrfs-zero-log. I thought btrfsck could help but
> eventually I discovered the official recommendation which is to first just
> start a btrfs scrub before taking other actions!"

To be clear, scrub is the first thing to try, it will try to walk all
the trees on the filesystem and read all the blocks.

'--init-extent-tree' is the very last resort, after "copy all data
to another filesystem" and before "give up, mkfs and start over."
--init-extent-tree either works perfectly, or damages the filesystem
beyond all possible recovery (and can silently corrupt data in either
case).  There's a non-zero chance of the second thing, so you don't want
to do --init-extent-tree unless you're ready to mkfs and start over when
it fails.

zero-log is useful for correcting log tree replay errors (and nothing
else).  It deletes the last 30 seconds of fsync() data updates.
zero-log clears the log tree, but the log tree is only for data updates
via fsync(), it is not used for metadata and will have no effect on
parent transid verification failures.

> > >  After that, I was able to run that dduper command without a failure.
> > >  But some days later, the same command resulted in:
> > >    parent transid verify failed on 16465691033600 wanted 352083 found 352085
> > > 
> > >  again.
> > > 
> > >  A scrub showed no error
> > >   btrfs scrub status /dev/sda1
> > >  scrub status for c4a6a2c9-5cf0-49b8-812a-0784953f9ba3
> > >          scrub started at Mon Oct 19 21:07:13 2020 and finished after
> > >  15:11:10
> > >          total bytes scrubbed: 6.56TiB with 0 errors
> > 
> > Scrub iterates over all metadata pages and should hit ptvf if it's
> > on disk.
> 
> But apparently it did not?!

...which indicates the problem is probably in memory, not on disk.

> > >  Filesystem info:
> > >   btrfs fi show /dev/sda1
> > >  Label: 'DataPool1'  uuid: c4a6a2c9-5cf0-49b8-812a-0784953f9ba3
> > >          Total devices 2 FS bytes used 6.56TiB
> > >          devid    1 size 7.28TiB used 6.75TiB path /dev/sda1
> > >          devid    2 size 7.28TiB used 6.75TiB path /dev/sdj1
> > 
> > If you have raid1 metadata (see 'btrfs fi usage') then it's possible
> 
>  btrfs fi usage /srv/dev-disk-by-label-DataPool1
> Overall:
>     Device size:                  14.55TiB
>     Device allocated:             13.51TiB
>     Device unallocated:            1.04TiB
>     Device missing:                  0.00B
>     Used:                         13.12TiB
>     Free (estimated):            731.48GiB      (min: 731.48GiB)
>     Data ratio:                       2.00
>     Metadata ratio:                   2.00
>     Global reserve:              512.00MiB      (used: 0.00B)
> 
> Data,RAID1: Size:6.74TiB, Used:6.55TiB
>    /dev/sda1       6.74TiB
>    /dev/sdj1       6.74TiB
> 
> Metadata,RAID1: Size:15.00GiB, Used:9.91GiB
>    /dev/sda1      15.00GiB
>    /dev/sdj1      15.00GiB
> 
> System,RAID1: Size:32.00MiB, Used:992.00KiB
>    /dev/sda1      32.00MiB
>    /dev/sdj1      32.00MiB
> 
> Unallocated:
>    /dev/sda1     535.00GiB
>    /dev/sdj1     535.00GiB
> 
> So it looks like it is raid1 metadata

That would mean either that recovery already happened (if the corruption
was on disk and has been removed), or the problem never reached a disk
(if it is only in memory).

> > only one of your disks is silently dropping writes.  In that case
> > btrfs will recover from ptvf by replacing the missing block from the
> > other drive.  But there are no scrub errors or kernel messages related
> > to this, so there aren't any symptoms of that happening, so it seems
> > these ptvf are not coming from the disk.
> And can this be confirmed somehow? Would be good to replace that disk
> then...

These normally appear in 'btrfs dev stats', although there are various
coverage gaps with raid5/6 and (until recently) compressed data blocks.

'btrfs scrub status -d' will give a per-drive error breakdown.

> > >  The system has a USV. Consequently, it should not experience any power
> > >  interruptions during writes.
> > > 
> > >  I did not find any indications of it in /var/log/*
> > >  (grep  -i btrfs /var/log/* | grep -v snapper |grep sda)
> > > 
> > >  What could be the reason for this re-appearing issue?
> > 
> > What kernel are you running?
> 5.6.12 since May 11th. Before that, (since Jan 5th) I ran 5.4.8.

5.4.8 could corrupt the filesystem, but not in a recoverable way.
So that's probably not the cause here.

5.6.12 should have all the relevant tree mod log fixes, but might be
missing some other UAF fixes from 5.7 (there were almost 20 of these
fixes in 2019 and 2020, it's not always possible to pin them all down
to a specific behavior).

I haven't seen spurious ptvf errors on my test machines since the 5.4.30s,
but 5.4 has a lot of fixes that between-LTS kernels like 5.6 do not
always get.

> >  Until early 2020 there was a UAF bug in tree
> > mod log code that could occasionally spit out harmless ptvf messages and
> > a few other verification messages like "bad tree block start" because
> > it was essentially verifying garbage from kernel RAM.
> Of course I did use older kernels in the past. But as I understand this bug,
> it would only give spurious error messages but not have caused any errors on
> the disk that would be now hit?

Correct, the spurious failure occurs only in memory (that's why it's
spurious--the data on disk is correct).

> Regards,
> Hendrik
> 
> 

Re[2]: parent transid verify failed: Fixed but re-appearing

[Hendrik Friedel]

Hello Zygo,

thanks for your reply.
>To be clear, scrub is the first thing to try, it will try to walk all
>the trees on the filesystem and read all the blocks.
>
Understood. Also thanks for explaining the other two options.
I think, it would be really advisable to add some recipies in the btrfs 
wiki - especially because btrfs check --repair is often not the right 
option opposed to the equivalent on other file systems.

>>  > Scrub iterates over all metadata pages and should hit ptvf if it's
>>  > on disk.
>>
>>  But apparently it did not?!
>
>...which indicates the problem is probably in memory, not on disk.

Which is good. On the other hand, that leaves the question why I have 
re-occuring failures of this kind (apparently) in memory.
What are possible reasons?

>>  So it looks like it is raid1 metadata
>
>That would mean either that recovery already happened (if the corruption
>was on disk and has been removed), or the problem never reached a disk
>(if it is only in memory).
Ok.
Good news.

But it's still there:
dduper --device /dev/sda1 --dir 
/srv/dev-disk-by-label-DataPool1/dduper_test/testfiles -r --dry-run
parent transid verify failed on 8333716668416 wanted 357026 found 357028
parent transid verify failed on 8333716668416 wanted 357026 found 357028
parent transid verify failed on 8333716668416 wanted 357026 found 357028


>
>>  > only one of your disks is silently dropping writes.  In that case
>>  > btrfs will recover from ptvf by replacing the missing block from the
>>  > other drive.  But there are no scrub errors or kernel messages related
>>  > to this, so there aren't any symptoms of that happening, so it seems
>>  > these ptvf are not coming from the disk.
>>  And can this be confirmed somehow? Would be good to replace that disk
>>  then...
>
>These normally appear in 'btrfs dev stats', although there are various
>coverage gaps with raid5/6 and (until recently) compressed data blocks.
I do not use raid5/6 and I think I do not use compressed data.

btrfs dev stats /dev/sda1
[/dev/sda1].write_io_errs    0
[/dev/sda1].read_io_errs     0
[/dev/sda1].flush_io_errs    0
[/dev/sda1].corruption_errs  0
[/dev/sda1].generation_errs  1

So, what does the generation_errs tell us?

>'btrfs scrub status -d' will give a per-drive error breakdown.

btrfs scrub status -d /dev/sda1
scrub status for c4a6a2c9-5cf0-49b8-812a-0784953f9ba3
scrub device /dev/sda1 (id 1) history
         scrub started at Mon Oct 19 21:07:13 2020 and finished after 
15:11:10
         total bytes scrubbed: 6.56TiB with 0 errors

btrfs scrub status -d /dev/sdj1
scrub status for c4a6a2c9-5cf0-49b8-812a-0784953f9ba3
scrub device /dev/sdj1 (id 2) history
         scrub started at Mon Oct 19 21:07:13 2020 and finished after 
17:06:15
         total bytes scrubbed: 6.56TiB with 0 errors


>I haven't seen spurious ptvf errors on my test machines since the 5.4.30s,
>but 5.4 has a lot of fixes that between-LTS kernels like 5.6 do not
>always get.

Ok, I am compiling 5.9.1 now.

Apart from switching to the latest Kernel - what next step do you 
recommend?
I tend to run a scrub again. Is it possible/useful to make it more 
verbose?
What else?

Greetings,
Hendrik

Re: parent transid verify failed: Fixed but re-appearing

[Zygo Blaxell]

On Wed, Oct 21, 2020 at 09:15:06PM +0000, Hendrik Friedel wrote:
> > That would mean either that recovery already happened (if the corruption
> > was on disk and has been removed), or the problem never reached a disk
> > (if it is only in memory).
> Ok.
> Good news.
> 
> But it's still there:
> dduper --device /dev/sda1 --dir
> /srv/dev-disk-by-label-DataPool1/dduper_test/testfiles -r --dry-run
> parent transid verify failed on 8333716668416 wanted 357026 found 357028
> parent transid verify failed on 8333716668416 wanted 357026 found 357028
> parent transid verify failed on 8333716668416 wanted 357026 found 357028

> > >  > only one of your disks is silently dropping writes.  In that case
> > >  > btrfs will recover from ptvf by replacing the missing block from the
> > >  > other drive.  But there are no scrub errors or kernel messages related
> > >  > to this, so there aren't any symptoms of that happening, so it seems
> > >  > these ptvf are not coming from the disk.
> > >  And can this be confirmed somehow? Would be good to replace that disk
> > >  then...
> > 
> > These normally appear in 'btrfs dev stats', although there are various
> > coverage gaps with raid5/6 and (until recently) compressed data blocks.
> I do not use raid5/6 and I think I do not use compressed data.
> 
> btrfs dev stats /dev/sda1
> [/dev/sda1].write_io_errs    0
> [/dev/sda1].read_io_errs     0
> [/dev/sda1].flush_io_errs    0
> [/dev/sda1].corruption_errs  0
> [/dev/sda1].generation_errs  1
> 
> So, what does the generation_errs tell us?

Try btrfs dev stats on the filesystem mount point instead of the device.
We want to see if there are generation errors on both disks or just one.

This indicates there was a parent transid verify failure observed on
that disk in the past.

If there is one on the other drive too then the filesystem may be broken,
though I'm not sure how you're getting scrub to work in that case.

It's also possible you're hitting some other kernel bug, possibly a new
one.

> > 'btrfs scrub status -d' will give a per-drive error breakdown.
> 
> btrfs scrub status -d /dev/sda1
> scrub status for c4a6a2c9-5cf0-49b8-812a-0784953f9ba3
> scrub device /dev/sda1 (id 1) history
>         scrub started at Mon Oct 19 21:07:13 2020 and finished after
> 15:11:10
>         total bytes scrubbed: 6.56TiB with 0 errors
> 
> btrfs scrub status -d /dev/sdj1
> scrub status for c4a6a2c9-5cf0-49b8-812a-0784953f9ba3
> scrub device /dev/sdj1 (id 2) history
>         scrub started at Mon Oct 19 21:07:13 2020 and finished after
> 17:06:15
>         total bytes scrubbed: 6.56TiB with 0 errors
> 
> 
> > I haven't seen spurious ptvf errors on my test machines since the 5.4.30s,
> > but 5.4 has a lot of fixes that between-LTS kernels like 5.6 do not
> > always get.
> 
> Ok, I am compiling 5.9.1 now.
> 
> Apart from switching to the latest Kernel - what next step do you recommend?
> I tend to run a scrub again. Is it possible/useful to make it more verbose?
> What else?

scrub already reports pretty much everything it finds.  'btrfs scrub
start -Bd' will present a per-disk error count at the end.

> Greetings,
> Hendrik
> 
> 

Re[2]: parent transid verify failed: Fixed but re-appearing

[Hendrik Friedel]

Hello,

thanks for your reply.

>>  So, what does the generation_errs tell us?
>
>Try btrfs dev stats on the filesystem mount point instead of the device.
>We want to see if there are generation errors on both disks or just one.
>
>This indicates there was a parent transid verify failure observed on
>that disk in the past.
>
btrfs dev stats /srv/DataPool
[/dev/sda1].write_io_errs    0
[/dev/sda1].read_io_errs     0
[/dev/sda1].flush_io_errs    0
[/dev/sda1].corruption_errs  0
[/dev/sda1].generation_errs  1
[/dev/sdj1].write_io_errs    0
[/dev/sdj1].read_io_errs     0
[/dev/sdj1].flush_io_errs    0
[/dev/sdj1].corruption_errs  0
[/dev/sdj1].generation_errs  0
>
So, on one of the drives only.
>
>If there is one on the other drive too then the filesystem may be broken,
>though I'm not sure how you're getting scrub to work in that case.
>
So, we are lucky, it seems?
>
>scrub already reports pretty much everything it finds.  'btrfs scrub
>start -Bd' will present a per-disk error count at the end.
>

So, should I do that now/next?
Anything else, I can do?

Regards,
Hendrik

>
>>  Greetings,
>>  Hendrik
>>
>>

Re: parent transid verify failed: Fixed but re-appearing

[Zygo Blaxell]

On Wed, Oct 21, 2020 at 09:26:24PM +0000, Hendrik Friedel wrote:
> Hello,
> 
> thanks for your reply.
> 
> > >  So, what does the generation_errs tell us?
> > 
> > Try btrfs dev stats on the filesystem mount point instead of the device.
> > We want to see if there are generation errors on both disks or just one.
> > 
> > This indicates there was a parent transid verify failure observed on
> > that disk in the past.
> > 
> btrfs dev stats /srv/DataPool
> [/dev/sda1].write_io_errs    0
> [/dev/sda1].read_io_errs     0
> [/dev/sda1].flush_io_errs    0
> [/dev/sda1].corruption_errs  0
> [/dev/sda1].generation_errs  1
> [/dev/sdj1].write_io_errs    0
> [/dev/sdj1].read_io_errs     0
> [/dev/sdj1].flush_io_errs    0
> [/dev/sdj1].corruption_errs  0
> [/dev/sdj1].generation_errs  0
> > 
> So, on one of the drives only.

If one drive is silently dropping writes then it would explain the
behavior so far; however, it's relatively rare to have a drive fail
that specifically and quietly (and only when you use one particular
application).  Not impossible, but only one in 10,000.

> > If there is one on the other drive too then the filesystem may be broken,
> > though I'm not sure how you're getting scrub to work in that case.
> > 
> So, we are lucky, it seems?

Filesystems are supposed to be deterministic.  Luck has no place here.  ;)

> > scrub already reports pretty much everything it finds.  'btrfs scrub
> > start -Bd' will present a per-disk error count at the end.
> > 
> 
> So, should I do that now/next?

Sure, more scrubs are better.  They are supposed to be run regularly
to detect drives going bad.

> Anything else, I can do?

It looks like sda1 might be bad and it is working by replacing lost
data from the mirror on sdj.  But this replacement should be happening
automatically on read (and definitely on scrub), so you shouldn't ever
see the same error twice, but it seems that you do.

That makes it sound more like you've found a kernel bug.

> Regards,
> Hendrik
> 
> > 
> > >  Greetings,
> > >  Hendrik
> > > 
> > > 
> 
> 

Re[2]: parent transid verify failed: Fixed but re-appearing

[Hendrik Friedel]

Hello Zygo,

thanks for your reply.

>>  [/dev/sda1].generation_errs  1
>>  [/dev/sdj1].generation_errs  0
>>  >
>>  So, on one of the drives only.
>
>If one drive is silently dropping writes then it would explain the
>behavior so far; however, it's relatively rare to have a drive fail
>that specifically and quietly (and only when you use one particular
>application).
Well, we do not know that it occurs when I use one particular 
application. It could also occur a before and just become visible when 
using dduper.

>>  > scrub already reports pretty much everything it finds.  'btrfs scrub
>>  > start -Bd' will present a per-disk error count at the end.
>>  >
>>
>>  So, should I do that now/next?
>
>Sure, more scrubs are better.  They are supposed to be run regularly
>to detect drives going bad.
btrfs scrub start -Bd /dev/sda1


scrub device /dev/sda1 (id 1) done
         scrub started at Wed Oct 21 23:38:36 2020 and finished after 
13:45:29
         total bytes scrubbed: 6.56TiB with 0 errors

But then again:
dduper --device /dev/sda1 --dir 
/srv/dev-disk-by-label-DataPool1/dduper_test/testfiles -r --dry-run
parent transid verify failed on 16500741947392 wanted 358407 found 
358409
Ignoring transid failure


>>  Anything else, I can do?
>
>It looks like sda1 might be bad and it is working by replacing lost
>data from the mirror on sdj.  But this replacement should be happening
>automatically on read (and definitely on scrub), so you shouldn't ever
>see the same error twice, but it seems that you do.

Well, it is not the same error twice.
Both the first ("on") value as well as the following two values change 
each time.
What's consistent is, that the wanted vs found always differ by two.
Here some samples:
parent transid verify failed on 9332119748608 wanted 204976 found 204978
parent transid verify failed on 9332147879936 wanted 204979 found 204981
parent transid verify failed on 16465691033600 wanted 352083 found 
352085
parent transid verify failed on 16500741947392 wanted 358407 found 
358409

>That makes it sound more like you've found a kernel bug.

And what do we do in order to narrow it down?

Regards,
Hendrik

>

Re[3]: parent transid verify failed: Fixed but re-appearing

[Hendrik Friedel]

Hello Zygo,

can you further me help on this?

Regards,
Hendrik

------ Originalnachricht ------
Von: "Hendrik Friedel" <hendrik@friedels.name>
An: "Zygo Blaxell" <ce3g8jdj@umail.furryterror.org>
Cc: "Btrfs BTRFS" <linux-btrfs@vger.kernel.org>
Gesendet: 22.10.2020 21:30:14
Betreff: Re[2]: parent transid verify failed: Fixed but re-appearing

>Hello Zygo,
>
>thanks for your reply.
>
>>>  [/dev/sda1].generation_errs  1
>>>  [/dev/sdj1].generation_errs  0
>>>  >
>>>  So, on one of the drives only.
>>
>>If one drive is silently dropping writes then it would explain the
>>behavior so far; however, it's relatively rare to have a drive fail
>>that specifically and quietly (and only when you use one particular
>>application).
>Well, we do not know that it occurs when I use one particular application. It could also occur a before and just become visible when using dduper.
>
>>>  > scrub already reports pretty much everything it finds.  'btrfs scrub
>>>  > start -Bd' will present a per-disk error count at the end.
>>>  >
>>>
>>>  So, should I do that now/next?
>>
>>Sure, more scrubs are better.  They are supposed to be run regularly
>>to detect drives going bad.
>btrfs scrub start -Bd /dev/sda1
>
>
>scrub device /dev/sda1 (id 1) done
>         scrub started at Wed Oct 21 23:38:36 2020 and finished after 13:45:29
>         total bytes scrubbed: 6.56TiB with 0 errors
>
>But then again:
>dduper --device /dev/sda1 --dir /srv/dev-disk-by-label-DataPool1/dduper_test/testfiles -r --dry-run
>parent transid verify failed on 16500741947392 wanted 358407 found 358409
>Ignoring transid failure
>
>
>>>  Anything else, I can do?
>>
>>It looks like sda1 might be bad and it is working by replacing lost
>>data from the mirror on sdj.  But this replacement should be happening
>>automatically on read (and definitely on scrub), so you shouldn't ever
>>see the same error twice, but it seems that you do.
>
>Well, it is not the same error twice.
>Both the first ("on") value as well as the following two values change each time.
>What's consistent is, that the wanted vs found always differ by two.
>Here some samples:
>parent transid verify failed on 9332119748608 wanted 204976 found 204978
>parent transid verify failed on 9332147879936 wanted 204979 found 204981
>parent transid verify failed on 16465691033600 wanted 352083 found 352085
>parent transid verify failed on 16500741947392 wanted 358407 found 358409
>
>>That makes it sound more like you've found a kernel bug.
>
>And what do we do in order to narrow it down?
>
>Regards,
>Hendrik
>
>>

Re: parent transid verify failed: Fixed but re-appearing

[Zygo Blaxell]

On Tue, Nov 03, 2020 at 06:19:41PM +0000, Hendrik Friedel wrote:
> Hello Zygo,
> 
> can you further me help on this?
> 
> Regards,
> Hendrik
> 
> ------ Originalnachricht ------
> Von: "Hendrik Friedel" <hendrik@friedels.name>
> An: "Zygo Blaxell" <ce3g8jdj@umail.furryterror.org>
> Cc: "Btrfs BTRFS" <linux-btrfs@vger.kernel.org>
> Gesendet: 22.10.2020 21:30:14
> Betreff: Re[2]: parent transid verify failed: Fixed but re-appearing
> 
> > Hello Zygo,
> > 
> > thanks for your reply.
> > 
> > > >  [/dev/sda1].generation_errs  1
> > > >  [/dev/sdj1].generation_errs  0
> > > >  >
> > > >  So, on one of the drives only.
> > > 
> > > If one drive is silently dropping writes then it would explain the
> > > behavior so far; however, it's relatively rare to have a drive fail
> > > that specifically and quietly (and only when you use one particular
> > > application).
> > Well, we do not know that it occurs when I use one particular application. It could also occur a before and just become visible when using dduper.
> > 
> > > >  > scrub already reports pretty much everything it finds.  'btrfs scrub
> > > >  > start -Bd' will present a per-disk error count at the end.
> > > >  >
> > > > 
> > > >  So, should I do that now/next?
> > > 
> > > Sure, more scrubs are better.  They are supposed to be run regularly
> > > to detect drives going bad.
> > btrfs scrub start -Bd /dev/sda1
> > 
> > 
> > scrub device /dev/sda1 (id 1) done
> >         scrub started at Wed Oct 21 23:38:36 2020 and finished after 13:45:29
> >         total bytes scrubbed: 6.56TiB with 0 errors
> > 
> > But then again:
> > dduper --device /dev/sda1 --dir /srv/dev-disk-by-label-DataPool1/dduper_test/testfiles -r --dry-run
> > parent transid verify failed on 16500741947392 wanted 358407 found 358409
> > Ignoring transid failure

Wait...is that the kernel log, or the output of the dduper command?

commit 3e5f67f45b553045a34113cafb3c22180210a19f (tag: v0.04, origin/dockerbuild)
Author: Lakshmipathi <lakshmipathi.ganapathi@collabora.com>
Date:   Fri Sep 18 11:51:42 2020 +0530

file deduper:

    194 def btrfs_dump_csum(filename):
    195     global device_name
    196 
    197     btrfs_bin = "/usr/sbin/btrfs.static"
    198     if os.path.exists(btrfs_bin) is False:
    199         btrfs_bin = "btrfs"
    200 
    201     out = subprocess.Popen(
    202         [btrfs_bin, 'inspect-internal', 'dump-csum', filename, device_name],
    203         stdout=subprocess.PIPE,
    204         close_fds=True).stdout.readlines()
    205     return out

OK there's the problem:  it's dumping csums from a mounted filesystem by
reading the block device instead of using the TREE_SEARCH_V2 ioctl.
Don't do that, because it won't work.  ;)

The "parent transid verify failed" errors are harmless.  They are due
to the fact that a process reading the raw block device can never build
an accurate model of a live filesystem that is changing underneathi it.

If you manage to get some dedupe to happen, then that's a bonus.


> > 
> > > >  Anything else, I can do?
> > > 
> > > It looks like sda1 might be bad and it is working by replacing lost
> > > data from the mirror on sdj.  But this replacement should be happening
> > > automatically on read (and definitely on scrub), so you shouldn't ever
> > > see the same error twice, but it seems that you do.
> > 
> > Well, it is not the same error twice.

Earlier you quoted some duplicate lines.  Normally those get fixed after the
first line, so you never see the second.

> > Both the first ("on") value as well as the following two values change each time.
> > What's consistent is, that the wanted vs found always differ by two.
> > Here some samples:
> > parent transid verify failed on 9332119748608 wanted 204976 found 204978
> > parent transid verify failed on 9332147879936 wanted 204979 found 204981
> > parent transid verify failed on 16465691033600 wanted 352083 found 352085
> > parent transid verify failed on 16500741947392 wanted 358407 found 358409
> > 
> > > That makes it sound more like you've found a kernel bug.
> > 
> > And what do we do in order to narrow it down?
> > 
> > Regards,
> > Hendrik
> > 
> > > 
> 
> 

Re[2]: parent transid verify failed: Fixed but re-appearing

[Hendrik Friedel]

Hello Zygo, hello Lakshmipathi,

@Lakshmipathi: as you suggested I consulted the BTRFS-Mailing list on 
this issue:
https://github.com/Lakshmipathi/dduper/issues/39

Zygo was so kind to help me and he suspects the error to lie within 
dduper.
>>  > > Sure, more scrubs are better.  They are supposed to be run regularly
>>  > > to detect drives going bad.
>>  > btrfs scrub start -Bd /dev/sda1
>>  >
>>  >
>>  > scrub device /dev/sda1 (id 1) done
>>  >         scrub started at Wed Oct 21 23:38:36 2020 and finished after 13:45:29
>>  >         total bytes scrubbed: 6.56TiB with 0 errors
>>  >
>>  > But then again:
>>  > dduper --device /dev/sda1 --dir /srv/dev-disk-by-label-DataPool1/dduper_test/testfiles -r --dry-run
>>  > parent transid verify failed on 16500741947392 wanted 358407 found 358409
>>  > Ignoring transid failure
>
>Wait...is that the kernel log, or the output of the dduper command?
>
It is on the commandline once I run the command; thus I suspect it is 
the dduper output. But of course sometimes the Kernel-Messages appear 
directly on the commandline. I do not know how to tell.

>
>commit 3e5f67f45b553045a34113cafb3c22180210a19f (tag: v0.04, origin/dockerbuild)
>Author: Lakshmipathi <lakshmipathi.ganapathi@collabora.com>
>Date:   Fri Sep 18 11:51:42 2020 +0530
>
>file deduper:
>
>     194 def btrfs_dump_csum(filename):
>     195     global device_name
>     196
>     197     btrfs_bin = "/usr/sbin/btrfs.static"
>     198     if os.path.exists(btrfs_bin) is False:
>     199         btrfs_bin = "btrfs"
>     200
>     201     out = subprocess.Popen(
>     202         [btrfs_bin, 'inspect-internal', 'dump-csum', filename, device_name],
>     203         stdout=subprocess.PIPE,
>     204         close_fds=True).stdout.readlines()
>     205     return out
>
>OK there's the problem:  it's dumping csums from a mounted filesystem by
>reading the block device instead of using the TREE_SEARCH_V2 ioctl.
>Don't do that, because it won't work.  ;)
I trust you on this ;-) But I am surprised I am the only one reporting 
this issue. Will it *always* not work, or does it not work in some cases 
and my situation is making it extremely unlikely to work?
>
>The "parent transid verify failed" errors are harmless.  They are due
>to the fact that a process reading the raw block device can never build
>an accurate model of a live filesystem that is changing underneathi it.
>
>If you manage to get some dedupe to happen, then that's a bonus.
>
>
>>  >
>>  > > >  Anything else, I can do?
>>  > >
>>  > > It looks like sda1 might be bad and it is working by replacing lost
>>  > > data from the mirror on sdj.  But this replacement should be happening
>>  > > automatically on read (and definitely on scrub), so you shouldn't ever
>>  > > see the same error twice, but it seems that you do.
>>  >
>>  > Well, it is not the same error twice.
>
>Earlier you quoted some duplicate lines.  Normally those get fixed after the
>first line, so you never see the second.
>
I see.

Regards,
Hendrik

Re: Re[2]: parent transid verify failed: Fixed but re-appearing

[Amy Parker]

On Tue, Nov 3, 2020 at 2:09 PM Hendrik Friedel <hendrik@friedels.name> wrote:
>
> Hello Zygo, hello Lakshmipathi,
>
> @Lakshmipathi: as you suggested I consulted the BTRFS-Mailing list on
> this issue:
> https://github.com/Lakshmipathi/dduper/issues/39
>
> Zygo was so kind to help me and he suspects the error to lie within
> dduper.
> >>  > > Sure, more scrubs are better.  They are supposed to be run regularly
> >>  > > to detect drives going bad.
> >>  > btrfs scrub start -Bd /dev/sda1
> >>  >
> >>  >
> >>  > scrub device /dev/sda1 (id 1) done
> >>  >         scrub started at Wed Oct 21 23:38:36 2020 and finished after 13:45:29
> >>  >         total bytes scrubbed: 6.56TiB with 0 errors
> >>  >
> >>  > But then again:
> >>  > dduper --device /dev/sda1 --dir /srv/dev-disk-by-label-DataPool1/dduper_test/testfiles -r --dry-run
> >>  > parent transid verify failed on 16500741947392 wanted 358407 found 358409
> >>  > Ignoring transid failure
> >
> >Wait...is that the kernel log, or the output of the dduper command?
> >
> It is on the commandline once I run the command; thus I suspect it is
> the dduper output. But of course sometimes the Kernel-Messages appear
> directly on the commandline. I do not know how to tell.

Kernel logs would be on dmesg. Check the entries against your current dmesg.

>
> >
> >commit 3e5f67f45b553045a34113cafb3c22180210a19f (tag: v0.04, origin/dockerbuild)
> >Author: Lakshmipathi <lakshmipathi.ganapathi@collabora.com>
> >Date:   Fri Sep 18 11:51:42 2020 +0530
> >
> >file deduper:
> >
> >     194 def btrfs_dump_csum(filename):
> >     195     global device_name
> >     196
> >     197     btrfs_bin = "/usr/sbin/btrfs.static"
> >     198     if os.path.exists(btrfs_bin) is False:
> >     199         btrfs_bin = "btrfs"
> >     200
> >     201     out = subprocess.Popen(
> >     202         [btrfs_bin, 'inspect-internal', 'dump-csum', filename, device_name],
> >     203         stdout=subprocess.PIPE,
> >     204         close_fds=True).stdout.readlines()
> >     205     return out
> >
> >OK there's the problem:  it's dumping csums from a mounted filesystem by
> >reading the block device instead of using the TREE_SEARCH_V2 ioctl.
> >Don't do that, because it won't work.  ;)
> I trust you on this ;-) But I am surprised I am the only one reporting
> this issue. Will it *always* not work, or does it not work in some cases
> and my situation is making it extremely unlikely to work?

It always won't work.

> >
> >The "parent transid verify failed" errors are harmless.  They are due
> >to the fact that a process reading the raw block device can never build
> >an accurate model of a live filesystem that is changing underneathi it.
> >
> >If you manage to get some dedupe to happen, then that's a bonus.
> >
> >
> >>  >
> >>  > > >  Anything else, I can do?
> >>  > >
> >>  > > It looks like sda1 might be bad and it is working by replacing lost
> >>  > > data from the mirror on sdj.  But this replacement should be happening
> >>  > > automatically on read (and definitely on scrub), so you shouldn't ever
> >>  > > see the same error twice, but it seems that you do.
> >>  >
> >>  > Well, it is not the same error twice.
> >
> >Earlier you quoted some duplicate lines.  Normally those get fixed after the
> >first line, so you never see the second.
> >
> I see.
>
> Regards,
> Hendrik
>

Best regards,
Amy Parker
(they/them)

Re: parent transid verify failed: Fixed but re-appearing

[Zygo Blaxell]

On Tue, Nov 03, 2020 at 08:40:40PM +0000, Hendrik Friedel wrote:
> Hello Zygo, hello Lakshmipathi,
> 
> @Lakshmipathi: as you suggested I consulted the BTRFS-Mailing list on this
> issue:
> https://github.com/Lakshmipathi/dduper/issues/39
> 
> Zygo was so kind to help me and he suspects the error to lie within dduper.
> > >  > > Sure, more scrubs are better.  They are supposed to be run regularly
> > >  > > to detect drives going bad.
> > >  > btrfs scrub start -Bd /dev/sda1
> > >  >
> > >  >
> > >  > scrub device /dev/sda1 (id 1) done
> > >  >         scrub started at Wed Oct 21 23:38:36 2020 and finished after 13:45:29
> > >  >         total bytes scrubbed: 6.56TiB with 0 errors
> > >  >
> > >  > But then again:
> > >  > dduper --device /dev/sda1 --dir /srv/dev-disk-by-label-DataPool1/dduper_test/testfiles -r --dry-run
> > >  > parent transid verify failed on 16500741947392 wanted 358407 found 358409
> > >  > Ignoring transid failure
> > 
> > Wait...is that the kernel log, or the output of the dduper command?
> > 
> It is on the commandline once I run the command; thus I suspect it is the
> dduper output. But of course sometimes the Kernel-Messages appear directly
> on the commandline. I do not know how to tell.

Kernel logs usually have timestamps, and will also be logged in files
like /var/log/kern.log and /var/log/dmesg (depending on the distro).
You can also review past kernel logs with the 'dmesg' utility.

The output of the command will just appear in the terminal window, or a
log file if you redirect stdout and stderr to a file.

> > commit 3e5f67f45b553045a34113cafb3c22180210a19f (tag: v0.04, origin/dockerbuild)
> > Author: Lakshmipathi <lakshmipathi.ganapathi@collabora.com>
> > Date:   Fri Sep 18 11:51:42 2020 +0530
> > 
> > file deduper:
> > 
> >     194 def btrfs_dump_csum(filename):
> >     195     global device_name
> >     196
> >     197     btrfs_bin = "/usr/sbin/btrfs.static"
> >     198     if os.path.exists(btrfs_bin) is False:
> >     199         btrfs_bin = "btrfs"
> >     200
> >     201     out = subprocess.Popen(
> >     202         [btrfs_bin, 'inspect-internal', 'dump-csum', filename, device_name],
> >     203         stdout=subprocess.PIPE,
> >     204         close_fds=True).stdout.readlines()
> >     205     return out
> > 
> > OK there's the problem:  it's dumping csums from a mounted filesystem by
> > reading the block device instead of using the TREE_SEARCH_V2 ioctl.
> > Don't do that, because it won't work.  ;)
> I trust you on this ;-) But I am surprised I am the only one reporting this
> issue. 

It means the code isn't being adequately tested by anyone who is currently
using it.  A common problem for new software projects.

The text "never run this" and "don't run this" appears in several places
in dduper's README.md, along with "Please be aware that dduper is largely
un-tesed tool." After reading advice like that, if I had stumbled across
this behavior myself, I wouldn't have bothered to report it--I'd say to
myself "hey, the README was right!" and then I'd move on to the next
candidate project on my list.  If other people do the same, that may
account for the low defect report rate.

I was able to quickly reproduce the parent transid verify failure by
running dduper on a test VM:

	# dduper -p /dev/vgtest/tvdb -r -s -d /media/testfs
	parent transid verify failed on 35179391188992 wanted 3743662 found 3743762
	parent transid verify failed on 35179391188992 wanted 3743662 found 3743762
	parent transid verify failed on 35179391188992 wanted 3743662 found 3743762
	Ignoring transid failure
	ERROR: child eb corrupted: parent bytenr=4414666997760 item=278 parent level=2 child level=0
	ERROR: failed to read block groups: Input/output error
	unable to open /dev/vgtest/tvdb
	Traceback (most recent call last):
	  File "./dduper", line 594, in <module>
	    main(results)
	  File "./dduper", line 465, in main
	    dedupe_dir(results.dir_path, results.dry_run, results.recurse)
	  File "./dduper", line 456, in dedupe_dir
	    dedupe_files(file_list, dry_run)
	  File "./dduper", line 410, in dedupe_files
	    ret = do_dedupe(src_file, dst_file, dry_run)
	  File "./dduper", line 224, in do_dedupe
	    assert len(out1) != 0
	AssertionError

The test VM runs 100 rsync processes, balance, snapshot create and
delete, scrub and bees continuously.  dduper survived almost 10 minutes.

Nothing else in the VM was disturbed by the test, which confirms that
the "parent transid verify failure" messages are not indicative of a
filesystem failure, and only dduper is affected by them.

> Will it *always* not work, or does it not work in some cases and my
> situation is making it extremely unlikely to work?

A short run (e.g. a small file on a small filesystem) could extract all
the needed data from the csum tree before a transaction commit removes
old parts of the csum tree from the filesystem.  dduper seems to invoke
dump-csum on every individual input file, so it is probably avoiding the
issue most of the time.  By starting over for every new file, the amount
of time that stale pages are held in dump-csum's memory is minimized.

dump-csum will always fail if it runs too long and there are concurrent
filesystem updates (including the changes dduper makes to the filesystem
itself).  It will fail more often on larger files than on smaller ones
(they take longer to read), and also more often on files that straddle
metadata page boundaries (they require more tree searches and validate
more tree node parents) or have data blocks scattered across the
disk (these will require reading more metadata tree interior nodes).
You might see some semi-repeatable behavior that seems data-dependent
(and is in fact dependent on the structure of the data on disk), but
it'll break eventually no matter what you do.

The kernel provides TREE_SEARCH_V2, an ioctl which can provide a map
from file to extent address, and also retrieve the csum tree items by
extent address from a mounted filesystem.  Accessing the csums through the
filesystem's ioctl interface instead of the block device will eliminate
the race condition leading to parent transid verify failure.  Switching to
this ioctl in dduper would also remove the dependency on non-upstream
btrfs-progs and probably make it run considerably faster, especially on
filesystems with many small files.  I'd recommend using python-btrfs for
that--no need to invent the wheel twice in the same programming language.

> > The "parent transid verify failed" errors are harmless.  They are due
> > to the fact that a process reading the raw block device can never build
> > an accurate model of a live filesystem that is changing underneathi it.

Well, almost harmless.  It seems dduper will abort as soon as it sees
a dump-csum error, without doing any further dedupe.

> > If you manage to get some dedupe to happen, then that's a bonus.
> > 
> > 
> > >  >
> > >  > > >  Anything else, I can do?
> > >  > >
> > >  > > It looks like sda1 might be bad and it is working by replacing lost
> > >  > > data from the mirror on sdj.  But this replacement should be happening
> > >  > > automatically on read (and definitely on scrub), so you shouldn't ever
> > >  > > see the same error twice, but it seems that you do.
> > >  >
> > >  > Well, it is not the same error twice.
> > 
> > Earlier you quoted some duplicate lines.  Normally those get fixed after the
> > first line, so you never see the second.
> > 
> I see.
> 
> Regards,
> Hendrik
> 
>