On 09/04/2019 07:36 AM, Chris Murphy wrote:
> On Tue, Sep 3, 2019 at 10:41 PM Edmund Urbani <edmund.urb...@liland.com>
> wrote:
>> Also there are a few of these:
>> Sep 1 21:10:17 phoenix kernel: ata6.00: exception Emask 0x0 SAct
>> 0x10000020 SErr 0x0 action 0x0
>> Sep 1 21:10:17 phoenix kernel: ata6.00: irq_stat 0x40000008
>> Sep 1 21:10:17 phoenix kernel: ata6.00: failed command: READ FPDMA QUEUED
>> Sep 1 21:10:17 phoenix kernel: ata6.00: cmd
>> 60/20:28:80:66:09/00:00:50:01:00/40 tag 5 ncq dma 16384 in\x0a
>> res 41/40:00:88:66:09/00:00:50:01:00/40 Emask 0x409 (media error) <F>
>> Sep 1 21:10:17 phoenix kernel: ata6.00: status: { DRDY ERR }
>> Sep 1 21:10:17 phoenix kernel: ata6.00: error: { UNC }
>> Sep 1 21:10:17 phoenix kernel: ata6.00: configured for UDMA/133
>> Sep 1 21:10:17 phoenix kernel: sd 5:0:0:0: [sdf] tag#5 UNKNOWN(0x2003)
>> Result: hostbyte=0x00 driverbyte=0x08
>> Sep 1 21:10:17 phoenix kernel: sd 5:0:0:0: [sdf] tag#5 Sense Key : 0x3
>> [current]
>> Sep 1 21:10:17 phoenix kernel: sd 5:0:0:0: [sdf] tag#5 ASC=0x11 ASCQ=0x4
>> Sep 1 21:10:17 phoenix kernel: sd 5:0:0:0: [sdf] tag#5 CDB: opcode=0x88
>> 88 00 00 00 00 01 50 09 66 80 00 00 00 20 00 00
>> Sep 1 21:10:17 phoenix kernel: print_req_error: I/O error, dev sdf,
>> sector 5637760640
>> Sep 1 21:10:17 phoenix kernel: BTRFS error (device sdb1): bdev
>> /dev/sdf1 errs: wr 0, rd 289, flush 0, corrupt 0, gen 0
>> Sep 1 21:10:17 phoenix kernel: ata6: EH complete
>> Sep 1 21:10:17 phoenix kernel: BTRFS warning (device sdb1): sdb1
>> checksum verify failed on 70943861833728 wanted 49137758 found 776101D6
>> level 0
>> Sep 1 21:10:17 phoenix kernel: BTRFS warning (device sdb1): sdb1
>> checksum verify failed on 70943861833728 wanted 49137758 found 776101D6
>> level 0
>> Sep 1 21:10:17 phoenix kernel: BTRFS warning (device sdb1): sdb1
>> checksum verify failed on 70943861833728 wanted 49137758 found 776101D6
>> level 0
>> Sep 1 21:10:17 phoenix kernel: BTRFS warning (device sdb1): sdb1
>> checksum verify failed on 70943861833728 wanted 49137758 found 776101D6
>> level 0
>> Sep 1 21:10:17 phoenix kernel: BTRFS warning (device sdb1): sdb1
>> checksum verify failed on 70943861833728 wanted 49137758 found 776101D6
>> level 0
>> Sep 1 21:10:17 phoenix kernel: BTRFS warning (device sdb1): sdb1
>> checksum verify failed on 70943861833728 wanted 49137758 found 776101D6
>> level 0
>> Sep 1 21:10:17 phoenix kernel: BTRFS warning (device sdb1): sdb1
>> checksum verify failed on 70943861833728 wanted 49137758 found 776101D6
>> level 0
>> Sep 1 21:10:17 phoenix kernel: BTRFS warning (device sdb1): sdb1
>> checksum verify failed on 70943861833728 wanted 49137758 found 776101D6
>> level 0
>> Sep 1 21:10:17 phoenix kernel: BTRFS warning (device sdb1): sdb1
>> checksum verify failed on 70943861833728 wanted 49137758 found 776101D6
>> level 0
> OK so the file system is not degraded, but sdb1 is giving you
> problems, so you've deleted it and its in the process of being removed
> (fs shrink, move chunks, and restripe).
I am about to install the old sdb in another system to try ddrescue on
it and see what I can salvage.
>
> Here /dev/sdf has issued an uncorrectable read error. Classic case of
> bad sector. And btrfs is trying to get data off sdb1 to try and fix
> it, but this fails with checksum errors multiple times. So basically
> it is a two device failure for the stripe currently being read. It
> should still be possible to recover the stripe unless there is one
> more error from another drive - but the included dmesg doesn't go on
> far enough to tell us how this event turned out.
I suspect that whatever is in sector 5637760640 on sdf is metadata. I
grepped the log for it and that bad sector pops up 10000+ times.
>
>
>> I am still looking for log entries related to the filesystem going
>> read-only. Not sure when exactly that happened and the logs are spammed
>> with plenty of the above...
> They're relevant because if there's a third failure at the same time,
> and if it affects metadata, reconstruction isn't possible, the
> metadata is missing. So then it's, what's missing and can it be
> manually reconstructed. It's super tedious.
>
apparently, this is where it went read-only:
Sep 3 00:31:31 phoenix kernel: ata1.01: exception Emask 0x0 SAct 0x0
SErr 0x0 action 0x0
Sep 3 00:31:31 phoenix kernel: ata1.01: BMDMA stat 0x64
Sep 3 00:31:31 phoenix kernel: ata1.01: failed command: READ DMA EXT
Sep 3 00:31:31 phoenix kernel: ata1.01: cmd
25/00:20:80:72:5a/00:00:a9:00:00/f0 tag 0 dma 16384 in\x0a res
51/40:20:80:72:5a/40:00:a9:00:00/f0 Emask 0x9 (media error)
Sep 3 00:31:31 phoenix kernel: ata1.01: status: { DRDY ERR }
Sep 3 00:31:31 phoenix kernel: ata1.01: error: { UNC }
Sep 3 00:31:31 phoenix kernel: ata1.00: configured for UDMA/100
Sep 3 00:31:31 phoenix kernel: ata1.01: configured for UDMA/100
Sep 3 00:31:31 phoenix kernel: sd 0:0:1:0: [sdb] tag#0 UNKNOWN(0x2003)
Result: hostbyte=0x00 driverbyte=0x08
Sep 3 00:31:31 phoenix kernel: sd 0:0:1:0: [sdb] tag#0 Sense Key : 0x3
[current]
Sep 3 00:31:31 phoenix kernel: sd 0:0:1:0: [sdb] tag#0 ASC=0x11 ASCQ=0x4
Sep 3 00:31:31 phoenix kernel: sd 0:0:1:0: [sdb] tag#0 CDB: opcode=0x88
88 00 00 00 00 00 a9 5a 72 80 00 00 00 20 00 00
Sep 3 00:31:31 phoenix kernel: print_req_error: I/O error, dev sdb,
sector 2841277056
Sep 3 00:31:31 phoenix kernel: BTRFS error (device sdb1): bdev
/dev/sdb1 errs: wr 0, rd 14786, flush 0, corrupt 0, gen 0
Sep 3 00:31:31 phoenix kernel: ata1: EH complete
Sep 3 00:31:31 phoenix kernel: BTRFS info (device sdb1): read error
corrected: ino 0 off 34958490861568 (dev /dev/sdb1 sector 2841275008)
Sep 3 00:31:31 phoenix kernel: BTRFS info (device sdb1): read error
corrected: ino 0 off 34958490865664 (dev /dev/sdb1 sector 2841275016)
Sep 3 00:31:31 phoenix kernel: BTRFS info (device sdb1): read error
corrected: ino 0 off 34958490869760 (dev /dev/sdb1 sector 2841275024)
Sep 3 00:31:31 phoenix kernel: BTRFS info (device sdb1): read error
corrected: ino 0 off 34958490873856 (dev /dev/sdb1 sector 2841275032)
Sep 3 00:31:39 phoenix kernel: ata1.01: exception Emask 0x0 SAct 0x0
SErr 0x0 action 0x0
Sep 3 00:31:39 phoenix kernel: ata1.01: BMDMA stat 0x64
Sep 3 00:31:39 phoenix kernel: ata1.01: failed command: READ DMA EXT
Sep 3 00:31:39 phoenix kernel: ata1.01: cmd
25/00:20:60:74:5b/00:00:a9:00:00/f0 tag 0 dma 16384 in\x0a res
51/40:20:60:74:5b/40:00:a9:00:00/f0 Emask 0x9 (media error)
Sep 3 00:31:39 phoenix kernel: ata1.01: status: { DRDY ERR }
Sep 3 00:31:39 phoenix kernel: ata1.01: error: { UNC }
Sep 3 00:31:39 phoenix kernel: ata1.00: configured for UDMA/100
Sep 3 00:31:39 phoenix kernel: ata1.01: configured for UDMA/100
Sep 3 00:31:39 phoenix kernel: sd 0:0:1:0: [sdb] tag#0 UNKNOWN(0x2003)
Result: hostbyte=0x00 driverbyte=0x08
Sep 3 00:31:39 phoenix kernel: sd 0:0:1:0: [sdb] tag#0 Sense Key : 0x3
[current]
Sep 3 00:31:39 phoenix kernel: sd 0:0:1:0: [sdb] tag#0 ASC=0x11 ASCQ=0x4
Sep 3 00:31:39 phoenix kernel: sd 0:0:1:0: [sdb] tag#0 CDB: opcode=0x88
88 00 00 00 00 00 a9 5b 74 60 00 00 00 20 00 00
Sep 3 00:31:39 phoenix kernel: print_req_error: I/O error, dev sdb,
sector 2841343072
Sep 3 00:31:39 phoenix kernel: BTRFS error (device sdb1): bdev
/dev/sdb1 errs: wr 0, rd 14787, flush 0, corrupt 0, gen 0
Sep 3 00:31:39 phoenix kernel: ata1: EH complete
Sep 3 00:31:39 phoenix kernel: btree_readpage_end_io_hook: 8 callbacks
suppressed
Sep 3 00:31:39 phoenix kernel: BTRFS error (device sdb1): bad tree
block start 3417494780583899951 34958760591360
Sep 3 00:31:39 phoenix kernel: BTRFS error (device sdb1): bad tree
block start 3417494780583899951 34958760591360
Sep 3 00:31:39 phoenix kernel: BTRFS error (device sdb1): bad tree
block start 3417494780583899951 34958760591360
Sep 3 00:31:39 phoenix kernel: BTRFS error (device sdb1): bad tree
block start 3417494780583899951 34958760591360
Sep 3 00:31:39 phoenix kernel: BTRFS error (device sdb1): bad tree
block start 3417494780583899951 34958760591360
Sep 3 00:31:39 phoenix kernel: BTRFS error (device sdb1): bad tree
block start 3417494780583899951 34958760591360
Sep 3 00:31:39 phoenix kernel: BTRFS error (device sdb1): bad tree
block start 3417494780583899951 34958760591360
Sep 3 00:31:39 phoenix kernel: BTRFS error (device sdb1): bad tree
block start 3417494780583899951 34958760591360
Sep 3 00:31:39 phoenix kernel: BTRFS error (device sdb1): bad tree
block start 3417494780583899951 34958760591360
Sep 3 00:31:39 phoenix kernel: BTRFS: error (device sdb1) in
__btrfs_free_extent:7084: errno=-5 IO failure
Sep 3 00:31:39 phoenix kernel: BTRFS info (device sdb1): forced readonly
Sep 3 00:31:39 phoenix kernel: BTRFS: error (device sdb1) in
btrfs_run_delayed_refs:3089: errno=-5 IO failure
Sep 3 00:31:39 phoenix kernel: BTRFS error (device sdb1): pending csums
is 24776704
>
>
>
>>>> [ 8904.358088] BTRFS info (device sda1): allowing degraded mounts
>>>> [ 8904.358089] BTRFS info (device sda1): disk space caching is enabled
>>>> [ 8904.358091] BTRFS info (device sda1): has skinny extents
>>>> [ 8904.361743] BTRFS warning (device sda1): devid 8 uuid
>>>> 0e8b4aff-6d64-4d31-a135-705421928f94 is missing
>>>> [ 8905.705036] BTRFS info (device sda1): bdev (null) errs: wr 0, rd
>>>> 14809, flush 0, corrupt 4, gen 0
>>>> [ 8905.705041] BTRFS info (device sda1): bdev /dev/sda1 errs: wr 0, rd
>>>> 4, flush 0, corrupt 0, gen 0
>>>> [ 8905.705052] BTRFS info (device sda1): bdev /dev/sdf1 errs: wr 0, rd
>>>> 10543, flush 0, corrupt 0, gen 0
>>>> [ 8905.705062] BTRFS info (device sda1): bdev /dev/sdc1 errs: wr 0, rd
>>>> 8, flush 0, corrupt 0, gen 0
>>> four devices with read errors
>>>
>>> When was the last time the volume was scrubbed? Do you know for sure
>>> these errors have not gone up at all since the last successful scrub?
>>> And were any errors reported for that last scrub?
>> Oh, that must have been quite a while ago. Sometime in 2018? Maybe? All
>> these drives have been up and running for several years now. sda and sdc
>> should still be fine, the replaced drive is sdb and sdf is next in line.
> There's evidence of four drives with problems at some point in time.
> And there's evidence in the kernel messages above of at least two
> problems at the same time with the same stripe. So, all it takes is
> one more problem with that stripe, and then that stripe can't be
> recovered - and if it's a metadata stripe? That's 512KiB of metadata
> lost, which is quite a lot, it probably kills the file system,
> depending on where it happens. If it's data - no big deal. Btrfs won't
> even care, it will just report EIO and the path to the bad file, and
> continue on.
>
> The whole point of regular scrubs is to prevent single sector
> corruptions and failures. If you don't do that, they can accumulate
> over time and then it's a huge problem when just one drive dies. So
> when did you last do a scrub? Are they all the same make model drive?
> Do they all have the same SCT ERC value? And is that value, for all
> drives, less than the value found at /sys/block/sdN/device/timeout ?
I'll make sure to setup a cron job for monthly scrubbing once this is
over. I really can't remember exactly when I last did a manual scrub.
They are all WD Red 3TB, though not all the same generation.
smartctl reports these models:
Device Model: WDC WD30EFRX-68AX9N0
Device Model: WDC WD30EFRX-68EUZN0
The timeout under /sys is 30 for all of them.
I am not sure what you mean by SCT ERC value and where to look for that.
Here's all the info smartctl gives me about sda:
smartctl 6.6 2017-11-05 r4594 [x86_64-linux-5.2.9-gentoo] (local build)
Copyright (C) 2002-17, Bruce Allen, Christian Franke, www.smartmontools.org
=== START OF INFORMATION SECTION ===
Model Family: Western Digital Red
Device Model: WDC WD30EFRX-68AX9N0
Serial Number: WD-WMC1T1311633
LU WWN Device Id: 5 0014ee 602ee2554
Firmware Version: 80.00A80
User Capacity: 3,000,592,982,016 bytes [3.00 TB]
Sector Sizes: 512 bytes logical, 4096 bytes physical
Device is: In smartctl database [for details use: -P show]
ATA Version is: ACS-2 (minor revision not indicated)
SATA Version is: SATA 3.0, 6.0 Gb/s (current: 3.0 Gb/s)
Local Time is: Wed Sep 4 06:04:20 2019 -00
SMART support is: Available - device has SMART capability.
SMART support is: Enabled
=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED
General SMART Values:
Offline data collection status: (0x00) Offline data collection activity
was never started.
Auto Offline Data Collection:
Disabled.
Self-test execution status: ( 0) The previous self-test routine
completed
without error or no self-test
has ever
been run.
Total time to complete Offline
data collection: (40320) seconds.
Offline data collection
capabilities: (0x7b) SMART execute Offline immediate.
Auto Offline data collection
on/off support.
Suspend Offline collection upon new
command.
Offline surface scan supported.
Self-test supported.
Conveyance Self-test supported.
Selective Self-test supported.
SMART capabilities: (0x0003) Saves SMART data before entering
power-saving mode.
Supports SMART auto save timer.
Error logging capability: (0x01) Error logging supported.
General Purpose Logging supported.
Short self-test routine
recommended polling time: ( 2) minutes.
Extended self-test routine
recommended polling time: ( 404) minutes.
Conveyance self-test routine
recommended polling time: ( 5) minutes.
SCT capabilities: (0x70bd) SCT Status supported.
SCT Error Recovery Control
supported.
SCT Feature Control supported.
SCT Data Table supported.
SMART Attributes Data Structure revision number: 16
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME FLAG VALUE WORST THRESH TYPE
UPDATED WHEN_FAILED RAW_VALUE
1 Raw_Read_Error_Rate 0x002f 200 200 051 Pre-fail
Always - 0
3 Spin_Up_Time 0x0027 178 177 021 Pre-fail
Always - 6058
4 Start_Stop_Count 0x0032 100 100 000 Old_age
Always - 61
5 Reallocated_Sector_Ct 0x0033 200 200 140 Pre-fail
Always - 0
7 Seek_Error_Rate 0x002e 100 253 000 Old_age
Always - 0
9 Power_On_Hours 0x0032 020 020 000 Old_age
Always - 58487
10 Spin_Retry_Count 0x0032 100 253 000 Old_age
Always - 0
11 Calibration_Retry_Count 0x0032 100 253 000 Old_age
Always - 0
12 Power_Cycle_Count 0x0032 100 100 000 Old_age
Always - 61
192 Power-Off_Retract_Count 0x0032 200 200 000 Old_age
Always - 43
193 Load_Cycle_Count 0x0032 200 200 000 Old_age
Always - 17
194 Temperature_Celsius 0x0022 110 098 000 Old_age
Always - 40
196 Reallocated_Event_Count 0x0032 200 200 000 Old_age
Always - 0
197 Current_Pending_Sector 0x0032 200 200 000 Old_age
Always - 0
198 Offline_Uncorrectable 0x0030 100 253 000 Old_age
Offline - 0
199 UDMA_CRC_Error_Count 0x0032 200 200 000 Old_age
Always - 0
200 Multi_Zone_Error_Rate 0x0008 200 200 000 Old_age
Offline - 0
SMART Error Log Version: 1
No Errors Logged
SMART Self-test log structure revision number 1
Num Test_Description Status Remaining
LifeTime(hours) LBA_of_first_error
# 1 Extended offline Completed without error 00%
13 -
SMART Selective self-test log data structure revision number 1
SPAN MIN_LBA MAX_LBA CURRENT_TEST_STATUS
1 0 0 Not_testing
2 0 0 Not_testing
3 0 0 Not_testing
4 0 0 Not_testing
5 0 0 Not_testing
Selective self-test flags (0x0):
After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.
>
>
>
>>>
>>>> I have tried all the mount / restore options listed here:
>>>> https://forums.unraid.net/topic/46802-faq-for-unraid-v6/page/2/?tab=comments#comment-543490
>>> Good. Stick with ro attempts for now. Including if you want to try a
>>> newer kernel. If it succeeds to mount ro, my advice is to update
>>> backups so at least critical information isn't lost. Back up while you
>>> can. Any repair attempt makes changes that will risk the data being
>>> permanently lost. So it's important to be really deliberate about any
>>> changes.
>> I'll let you know, when I have the new kernel up and running.
> I think you should have all the original drives installed, and try to
> mount -o ro first. And if that doesn't work, try -o ro,degraded, and
> then we'll just have to see which drive it doesn't like.
>
>
>
> --
> Chris Murphy
Well, I already tried mounting with 5.2.9 in the meantime without
success (without the original sdb drive). It still does not mount (mount
-o ro,degraded /dev/sda1 /mnt/shared/):
[ 209.459309] BTRFS info (device sdg1): allowing degraded mounts
[ 209.459313] BTRFS info (device sdg1): disk space caching is enabled
[ 209.459314] BTRFS info (device sdg1): has skinny extents
[ 209.461246] BTRFS warning (device sdg1): devid 8 uuid
0e8b4aff-6d64-4d31-a135-705421928f94 is missing
[ 209.544603] BTRFS warning (device sdg1): devid 8 uuid
0e8b4aff-6d64-4d31-a135-705421928f94 is missing
[ 211.401375] BTRFS info (device sdg1): bdev (efault) errs: wr 0, rd
14809, flush 0, corrupt 4, gen 0
[ 211.401388] BTRFS info (device sdg1): bdev /dev/sdf1 errs: wr 0, rd
10543, flush 0, corrupt 0, gen 0
[ 211.401391] BTRFS info (device sdg1): bdev /dev/sda1 errs: wr 0, rd
4, flush 0, corrupt 0, gen 0
[ 211.401394] BTRFS info (device sdg1): bdev /dev/sdc1 errs: wr 0, rd
8, flush 0, corrupt 0, gen 0
[ 215.381805] BTRFS error (device sdg1): bad tree block start, want
34958581399552 have 12170572967447269873
[ 215.382603] BTRFS error (device sdg1): bad tree block start, want
34958581399552 have 12170572967447269873
[ 215.386155] BTRFS error (device sdg1): bad tree block start, want
34958581399552 have 12170572967447269873
[ 215.389539] BTRFS error (device sdg1): bad tree block start, want
34958581399552 have 12170572967447269873
[ 215.393053] BTRFS error (device sdg1): bad tree block start, want
34958581399552 have 12170572967447269873
[ 215.395223] BTRFS error (device sdg1): bad tree block start, want
34958581399552 have 12170572967447269873
[ 215.397188] BTRFS error (device sdg1): bad tree block start, want
34958581399552 have 12170572967447269873
[ 215.399307] BTRFS error (device sdg1): bad tree block start, want
34958581399552 have 12170572967447269873
[ 215.402410] BTRFS error (device sdg1): bad tree block start, want
34958581399552 have 12170572967447269873
[ 215.402447] BTRFS error (device sdg1): failed to read block groups: -5
[ 215.844527] BTRFS error (device sdg1): open_ctree failed
I'm planning to install the copy of sdb once ddrescue is done.
Regards,
Edmund
--
*Liland IT GmbH*
Ferlach ● Wien ● München
Tel: +43 463 220111
Tel: +49 89
458 15 940
off...@liland.com
https://Liland.com <https://Liland.com>
Copyright © 2019 Liland IT GmbH
Diese Mail enthaelt vertrauliche und/oder
rechtlich geschuetzte Informationen.
Wenn Sie nicht der richtige Adressat
sind oder diese Email irrtuemlich erhalten haben, informieren Sie bitte
sofort den Absender und vernichten Sie diese Mail. Das unerlaubte Kopieren
sowie die unbefugte Weitergabe dieser Mail ist nicht gestattet.
This
email may contain confidential and/or privileged information.
If you are
not the intended recipient (or have received this email in error) please
notify the sender immediately and destroy this email. Any unauthorised
copying, disclosure or distribution of the material in this email is
strictly forbidden.
