Monitoring not working as "dev stats" returns 0 after read error occurred

Monitoring not working as "dev stats" returns 0 after read error occurred

[philip]

A bad drive caused i/o errors, but no notifications were sent out 
because "btrfs dev stats" fails to increase the error counter.

When checking dmesg, looking for something completely different, there 
were some error messages indicating that this drive is causing i/o 
errors and may die soon:

BTRFS info (device sda3): read error corrected: ino 194473 off 2170880

But checking the stats (as generally recommended to get notified about 
such errors) claims that no errors have occurred (nothing to see here, 
keep moving):

# btrfs dev stats / | grep sda3 | grep read
[/dev/sda3].read_io_errs 0

Why?
Isn't that the most important feature of a RAID system - to get notified 
about errors, to be able to replace such a drive...?

The fs is mirrored, so those errors didn't cause any data loss.

# uname -sr
Linux 5.2.7-100.fc29.x86_64
# btrfs --version
btrfs-progs v5.1

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[Graham Cobb]

On 08/01/2020 17:41, philip@philip-seeger.de wrote:
> A bad drive caused i/o errors, but no notifications were sent out
> because "btrfs dev stats" fails to increase the error counter.
> 
> When checking dmesg, looking for something completely different, there
> were some error messages indicating that this drive is causing i/o
> errors and may die soon:
> 
> BTRFS info (device sda3): read error corrected: ino 194473 off 2170880

I am not convinced that that message is telling you that the error
happened on device sda3. Certainly in some other cases Btrfs error
messages  identify the **filesystem** using the name of the device the
kernel thinks is mounted, which might be sda3.

> But checking the stats (as generally recommended to get notified about
> such errors) claims that no errors have occurred (nothing to see here,
> keep moving):
> 
> # btrfs dev stats / | grep sda3 | grep read
> [/dev/sda3].read_io_errs 0

Have you checked the stats for the other devices as well?

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[Chris Murphy]

On Wed, Jan 8, 2020 at 10:47 AM <philip@philip-seeger.de> wrote:
>
> # uname -sr
> Linux 5.2.7-100.fc29.x86_64

Unrelated to your report, but you need to update your kernel. The one
you're using has a pernicious bug that can result in unrepairable
corruption of the file system. Use 5.2.15 or newer.

https://lore.kernel.org/linux-btrfs/20190725082729.14109-3-nborisov@suse.com/


--
Chris Murphy

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[Philip Seeger]

On 2020-01-08 20:35, Graham Cobb wrote:
>> BTRFS info (device sda3): read error corrected: ino 194473 off 2170880
> 
> I am not convinced that that message is telling you that the error
> happened on device sda3. Certainly in some other cases Btrfs error
> messages  identify the **filesystem** using the name of the device the
> kernel thinks is mounted, which might be sda3.

You're right, it looks like I copied the wrong piece, my bad. This btrfs 
filesystem is a mirror with two drives:

# btrfs fi show / | grep devid
	devid    1 size 100.00GiB used 81.03GiB path /dev/sda3
	devid    2 size 100.00GiB used 81.03GiB path /dev/nvme0n1p3

And this is from dmesg:

print_req_error: critical medium error, dev nvme0n1, sector 40910720 
flags 84700
BTRFS info (device sda3): read error corrected: ino 194473 off 2134016 
(dev /dev/nvme0n1p3 sector 36711808)

So it's nvme0n1 that's about to die. But it doesn't matter, dev stats 
prints 0 for all error counts as if nothing had ever happened.

# btrfs dev stats /
[/dev/sda3].write_io_errs    0
[/dev/sda3].read_io_errs     0
[/dev/sda3].flush_io_errs    0
[/dev/sda3].corruption_errs  0
[/dev/sda3].generation_errs  0
[/dev/nvme0n1p3].write_io_errs    0
[/dev/nvme0n1p3].read_io_errs     0
[/dev/nvme0n1p3].flush_io_errs    0
[/dev/nvme0n1p3].corruption_errs  0
[/dev/nvme0n1p3].generation_errs  0

>> # btrfs dev stats / | grep sda3 | grep read
>> [/dev/sda3].read_io_errs 0
> 
> Have you checked the stats for the other devices as well?

Yes, of course. Nevermind that grep. The monitoring cron job checks all 
error counts returned by the stats command and sends out an alert if an 
error is reported (just like with zfs status on zfs filesystems which 
also returns error counts for read/write/cksum errors). But as you can 
see, it didn't send out anything as dev stats says that all error counts 
are at zero.

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[Philip Seeger]

On 2020-01-08 22:47, Chris Murphy wrote:
> Unrelated to your report, but you need to update your kernel. The one
> you're using has a pernicious bug that can result in unrepairable
> corruption of the file system. Use 5.2.15 or newer.
> 
> https://lore.kernel.org/linux-btrfs/20190725082729.14109-3-nborisov@suse.com/

Chris, thank you very much! I appreciate it (not the pernicious bug but 
the heads-up).

I was going to do that anyway very soon.

I guess those who're not always up-to-date with their kernel are living 
dangerous lives...
(I just realized that I still wouldn't know about that bad drive, had I 
upgraded or rebooted earlier.)

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[Nikolay Borisov]

On 9.01.20 г. 12:33 ч., Philip Seeger wrote:
> On 2020-01-08 20:35, Graham Cobb wrote:
>>> BTRFS info (device sda3): read error corrected: ino 194473 off 2170880
>>
>> I am not convinced that that message is telling you that the error
>> happened on device sda3. Certainly in some other cases Btrfs error
>> messages  identify the **filesystem** using the name of the device the
>> kernel thinks is mounted, which might be sda3.
> 
> You're right, it looks like I copied the wrong piece, my bad. This btrfs
> filesystem is a mirror with two drives:
> 
> # btrfs fi show / | grep devid
>     devid    1 size 100.00GiB used 81.03GiB path /dev/sda3
>     devid    2 size 100.00GiB used 81.03GiB path /dev/nvme0n1p3
> 
> And this is from dmesg:
> 
> print_req_error: critical medium error, dev nvme0n1, sector 40910720
> flags 84700
> BTRFS info (device sda3): read error corrected: ino 194473 off 2134016
> (dev /dev/nvme0n1p3 sector 36711808)
> 
> So it's nvme0n1 that's about to die. But it doesn't matter, dev stats
> prints 0 for all error counts as if nothing had ever happened.
> 

According to the log provided the error returned from the NVME device is
BLK_STS_MEDIUM/-ENODATA hence the "critical medium" string there. Btrfs'
code OTOH only logs error in case we it gets STS_IOERR or STS_TARGET
from the block layer. It seems there are other error codes which are
also ignored but can signify errors e.g. STS_NEXUS/STS_TRANSPORT.

So as it stands this is expected but I'm not sure it's correct behavior,
perhaps we need to extend the range of conditions we record as errors.

Thanks for the report.


<snip>

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[Philip Seeger]

On 2020-01-09 13:04, Nikolay Borisov wrote:
> According to the log provided the error returned from the NVME device 
> is
> BLK_STS_MEDIUM/-ENODATA hence the "critical medium" string there. 
> Btrfs'
> code OTOH only logs error in case we it gets STS_IOERR or STS_TARGET
> from the block layer. It seems there are other error codes which are
> also ignored but can signify errors e.g. STS_NEXUS/STS_TRANSPORT.

Thanks for looking into this!

> So as it stands this is expected but I'm not sure it's correct 
> behavior,
> perhaps we need to extend the range of conditions we record as errors.

I don't understand how this could possibly be correct behavior.

The "device stats" command returns the error counters for a BTRFS 
filesystem, just like "zfs status" returns the error counters for a ZFS 
filesystem. So that's the one and only command that can be used by the 
monitoring job that checks the health of the system. If the error 
counters all stay at zero after device errors have occurred and that's 
deemed correct behavior, how would the monitoring system be able to 
notify the admin about a bad drive that should be replace before another 
one goes bad, causing data loss?

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[Philip Seeger]

> On 2020-01-09 13:04, Nikolay Borisov wrote:
>> It seems there are other error codes which are
>> also ignored but can signify errors e.g. STS_NEXUS/STS_TRANSPORT.

Speaking of other errors also being ignored.

I just saw this on a different system:

BTRFS warning (device sdd1): csum failed root 5 ino 263 off 5869793280 
csum 0xeee8ab75 expected csum 0x1fc62249 mirror 1

Is BTRFS trying to tell me that the file with inode number 263 is 
corrupt (checksum mismatch)?
I did indeed read (copy) that file earlier so it sounds like BTRFS 
calculated its checksum to verify it and it didn't match the stored 
checksum.

The error counters returned by "dev stats" all stayed at 0 (even after 
scrubbing). This is (was) a single filesystem, no RAID.

Suppose this was an important file, should I be worried now?

If this was a checksum error, why does the stats command keep saying 
that zero errors have been detected?

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[Andrei Borzenkov]

10.01.2020 02:50, Philip Seeger пишет:
>> On 2020-01-09 13:04, Nikolay Borisov wrote:
>>> It seems there are other error codes which are
>>> also ignored but can signify errors e.g. STS_NEXUS/STS_TRANSPORT.
> 
> Speaking of other errors also being ignored.
> 
> I just saw this on a different system:
> 
> BTRFS warning (device sdd1): csum failed root 5 ino 263 off 5869793280
> csum 0xeee8ab75 expected csum 0x1fc62249 mirror 1
> 
> Is BTRFS trying to tell me that the file with inode number 263 is
> corrupt (checksum mismatch)?
> I did indeed read (copy) that file earlier so it sounds like BTRFS
> calculated its checksum to verify it and it didn't match the stored
> checksum.
> 

On one mirror piece. It likely got correct data from another piece.

> The error counters returned by "dev stats" all stayed at 0 (even after
> scrubbing). This is (was) a single filesystem, no RAID.
> 

This is not device-level error. btrfs got data from block device without
error. That content of data was wrong does not necessarily mean block
device problem.

> Suppose this was an important file, should I be worried now?
> 

You have mirror and btrfs got correct data from another device
(otherwise you were not able to read file at all). Of course you should
be worried why one copy of data was not correct.

> If this was a checksum error, why does the stats command keep saying
> that zero errors have been detected?

Again - there was no error *reading* data from block device. Is
corruption_errs also zero?

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[Philip Seeger]

On 1/11/20 8:42 AM, Andrei Borzenkov wrote:

> On one mirror piece. It likely got correct data from another piece.

This may be a dumb question, but what mirror are we talking about here? 
Note that this "csum failed" message happened on a different system 
(than the "read error corrected" I quoted in the first message of this 
thread). This happened on a simple btrfs partition and by default, 
"data" isn't mirrored (fi df: single).
I wrote it in the same thread, not to cause confusion, but simply 
because I saw the same problem I'm trying to describe in another 
configuration: "dev stats" claims no errors occurred and monitoring 
tools relying on "dev stats" therefore won't be able to notify admins 
about a bad drive before.

I think this is a serious bug. Just think about what that means. A drive 
goes bad, btrfs keeps fixing errors caused by that drive but as "dev 
stats" keeps saying "all good" (which is checked hourly or daily, by a 
monitoring job), no admin will be notified. A few weeks later, a second 
drive fails, causing data loss. The whole raid array might be gone and 
even if the backups are relatively up-to-date, the work from the past 
few hours will be lost and then there's the outage and the downtime 
(everything has to be shut down and restored from the backup, which 
might take a lot of time if the backup system is slow, maybe some parts 
are stored on tapes...).

In other words: What's the point of a RAID system if the admin won't be 
able to know that a drive is bad and has to be replaced?

> This is not device-level error. btrfs got data from block device without
> error. That content of data was wrong does not necessarily mean block
> device problem.

I understand that it's unlikely that it was a block device problem, 
after all it's a new hard drive (and I ran badblocks on it which didn't 
find any errors).
But if the drive is good and the file appears to be correct and one (of 
two?) checksum matched the file's contents, why was the other checksum 
wrong? Or could it be something completely different that triggers the 
same error message?

> You have mirror and btrfs got correct data from another device
> (otherwise you were not able to read file at all). Of course you should
> be worried why one copy of data was not correct.

Which other device?

By one copy of data you mean one of two checksums (which are stored 
twice in case one copy gets corrupted like in this case apparently)?

> Again - there was no error *reading* data from block device. Is
> corruption_errs also zero?

Yes, all the error counts were zero.

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[waxhead]

I agree with this. btrfs device stats /mnt should show the number of 
filesystem errors as well. In short I think regular users (like me for 
example) would want a output that shows how many fixes has been 
performed. E.g. each time BTRFS' repair logic kicks inn an either logs a 
file as corrupt or corrects a checksum failure with a second copy it 
should be logged.

Speaking of... it would be great if btrfs device stats /mnt (or some 
other command) could offer to show a list of corrupted files with paths 
(which I assume the filesystem know about). That would make restoring 
files from backup a breeze!

-Waxhead

Philip Seeger wrote:
> On 1/11/20 8:42 AM, Andrei Borzenkov wrote:
> 
>> On one mirror piece. It likely got correct data from another piece.
> 
> This may be a dumb question, but what mirror are we talking about here? 
> Note that this "csum failed" message happened on a different system 
> (than the "read error corrected" I quoted in the first message of this 
> thread). This happened on a simple btrfs partition and by default, 
> "data" isn't mirrored (fi df: single).
> I wrote it in the same thread, not to cause confusion, but simply 
> because I saw the same problem I'm trying to describe in another 
> configuration: "dev stats" claims no errors occurred and monitoring 
> tools relying on "dev stats" therefore won't be able to notify admins 
> about a bad drive before.
> 
> I think this is a serious bug. Just think about what that means. A drive 
> goes bad, btrfs keeps fixing errors caused by that drive but as "dev 
> stats" keeps saying "all good" (which is checked hourly or daily, by a 
> monitoring job), no admin will be notified. A few weeks later, a second 
> drive fails, causing data loss. The whole raid array might be gone and 
> even if the backups are relatively up-to-date, the work from the past 
> few hours will be lost and then there's the outage and the downtime 
> (everything has to be shut down and restored from the backup, which 
> might take a lot of time if the backup system is slow, maybe some parts 
> are stored on tapes...).
> 
> In other words: What's the point of a RAID system if the admin won't be 
> able to know that a drive is bad and has to be replaced?
> 
>> This is not device-level error. btrfs got data from block device without
>> error. That content of data was wrong does not necessarily mean block
>> device problem.
> 
> I understand that it's unlikely that it was a block device problem, 
> after all it's a new hard drive (and I ran badblocks on it which didn't 
> find any errors).
> But if the drive is good and the file appears to be correct and one (of 
> two?) checksum matched the file's contents, why was the other checksum 
> wrong? Or could it be something completely different that triggers the 
> same error message?
> 
>> You have mirror and btrfs got correct data from another device
>> (otherwise you were not able to read file at all). Of course you should
>> be worried why one copy of data was not correct.
> 
> Which other device?
> 
> By one copy of data you mean one of two checksums (which are stored 
> twice in case one copy gets corrupted like in this case apparently)?
> 
>> Again - there was no error *reading* data from block device. Is
>> corruption_errs also zero?
> 
> Yes, all the error counts were zero.

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[Chris Murphy]

On Sun, Jan 12, 2020 at 10:39 AM waxhead <waxhead@dirtcellar.net> wrote:
>
> Speaking of... it would be great if btrfs device stats /mnt (or some
> other command) could offer to show a list of corrupted files with paths
> (which I assume the filesystem know about). That would make restoring
> files from backup a breeze!

Scrub does this. As well as any time a corrupt file is read. But such
information isn't stored anywhere. Path to file is reported in kernel
messages.

-- 
Chris Murphy

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[Philip Seeger]

On 1/12/20 6:39 PM, waxhead wrote:
> Speaking of... it would be great if btrfs device stats /mnt (or some 
> other command) could offer to show a list of corrupted files with paths 
> (which I assume the filesystem know about). That would make restoring 
> files from backup a breeze!

*cough* zfs status -v *cough*

Re: Monitoring not working as "dev stats" returns 0 after read error occurred

[Zygo Blaxell]

[-- Attachment #1: Type: text/plain, Size: 3330 bytes --]

On Wed, Jan 08, 2020 at 06:41:36PM +0100, philip@philip-seeger.de wrote:
> A bad drive caused i/o errors, but no notifications were sent out because
> "btrfs dev stats" fails to increase the error counter.
> 
> When checking dmesg, looking for something completely different, there were
> some error messages indicating that this drive is causing i/o errors and may
> die soon:
> 
> BTRFS info (device sda3): read error corrected: ino 194473 off 2170880
> 
> But checking the stats (as generally recommended to get notified about such
> errors) claims that no errors have occurred (nothing to see here, keep
> moving):
> 
> # btrfs dev stats / | grep sda3 | grep read
> [/dev/sda3].read_io_errs 0
> 
> Why?
> Isn't that the most important feature of a RAID system - to get notified
> about errors, to be able to replace such a drive...?
> 
> The fs is mirrored, so those errors didn't cause any data loss.

This seems to be a result of commit
0cc068e6ee59c1fffbfa977d8bf868b7551d80ac "btrfs: don't report readahead
errors and don't update statistics" which assumes that readahead errors
are ignored and have no side effects.  It turns out this is not true: in
the event of a recoverable read or csum failure, the filesystem overwrites
the bad block with good data recovered by using mirror copies or parity,
in both normal reads and readahead reads.  Later, when a non-readahead
read comes along to read the block, there's no error on the device any
more because btrfs already corrected it, so no counters are updated.

This is very bad--the whole point of dev stats is to make failure events
observable so failing hardware can be identified and replaced, and commit
0cc068e6ee makes some of those events not count.

This commit appears in kernels 5.1-rc3 and later.  A simple workaround
is to revert the commit, and let printk ratelimiting deal with the dmesg
spam issue.  I don't know if there are other errors that readahead can
generate that are not IO errors (e.g. running out of memory).  If there
are, then there will be some false positive read error counts.  These
are still better than false negative read error counts.

An alternative fix would be to have readahead not correct the data,
so readahead truly has no side-effects.  This would make the rationale
of this commit more supportable--except we'd still want to know if a
device was intermittently failing to read, so we should still count the
readahead errors anyway.

It would be nice to have a dev stats counter for corrections too.  It's a
pretty significant event for monitoring if we overwrite committed data
for any reason, but especially so if we are doing it in response to a
detected device failure.  We should definitely count those.

It would also be nice to throw some data into a tree every time an error
occurs (extent bytenr, offset, generation, error type, event count,
device or mirror ID) every time an error occurs.  A tool can read this
tree to pull out the extent bytenrs, map them back to paths (if the
generation matches; otherwise, it's an old error and the file has since
been overwritten), and produce something like the zfs status output.
But that's way beyond a bug fix.

> 
> # uname -sr
> Linux 5.2.7-100.fc29.x86_64
> # btrfs --version
> btrfs-progs v5.1
> 
> 

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]