help : "bad tree block start" -> btrfs forced readonly

help : "bad tree block start" -> btrfs forced readonly

[Lionel Bouton]

Hi,

our largest BTRFS filesystem is damaged but I'm unclear if it is
recoverable or not. This is a 20TB filesystem with ~13TB used in a
virtual machine using virtio-scsi backed by Ceph (Firefly 0.8.10).
The following messages have become more frequent :

fileserver kernel: sd 0:0:1:0: [sdb] tag#<number> abort

This can sometimes happen under heavy IO load and I didn't immediately
spot a new cause for them : a failing disk. Then I saw this after a
failed monthly scrub :

Mar 13 03:49:01 fileserver kernel: BTRFS: checksum error at logical
13373533028352 on dev /dev/sdb, sector 26004838336, root 257, inode
8155339, offset 131072, length 4096, links 1 (path: <damaged_file>)

This was surprising as I thought Ceph would not give back bad data. I
saw this kind too :

Mar  7 18:33:53 fileserver kernel: BTRFS warning (device sdb): csum
failed ino 8155339 off 1073152 csum 1108896639 expected csum 1374028982

The csum was always 1108896639 for different chunks so I suspect this is
the csum of a zero-filled block of data. So in case of timeouts maybe
virtio-scsi just returns a block full of zero. I actually tried to read
the affected files and saw Ceph OSD timeouts on the disk I was
suspecting of failing at the same time I got the IO error.
The disk is confirmed having relocated ~40 sectors in the same period
problems appeared, it is behind an HP SATA/SAS controller so it isn't
easy to get the whole SMART info.

I restored all files affected, launched another full scrub which passed
successfully but unfortunately the damaged got worse shortly after :

Mar 16 23:30:09 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415463870464
Mar 16 23:30:09 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415463870464
Mar 16 23:30:09 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415463870464
Mar 16 23:30:09 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415463870464
Mar 16 23:30:10 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415463870464
Mar 16 23:30:10 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415463870464
Mar 16 23:30:10 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415463870464
Mar 16 23:30:10 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415463870464
Mar 16 23:30:10 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415463870464
Mar 16 23:30:20 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415463870464
Mar 16 23:30:20 fileserver kernel: ------------[ cut here ]------------
Mar 16 23:30:20 fileserver kernel: WARNING: CPU: 2 PID: 3556 at
fs/btrfs/super.c:260 __btrfs_abort_transaction+0x46/0x110()
Mar 16 23:30:20 fileserver kernel: BTRFS: Transaction aborted (error -5)
Mar 16 23:30:20 fileserver kernel: Modules linked in: nfsd auth_rpcgss
oid_registry nfs_acl ipv6 binfmt_misc mousedev 8250 processor
crc32c_intel psmouse thermal_sys serial_core button dm_zero dm_thin_pool
dm_persistent_data dm_bio_prison dm_service_time dm_round_robin
dm_queue_length dm_multipath dm_log_userspace dm_delay virtio_console
xts gf128mul aes_x86_64 cbc sha512_generic sha256_generic sha1_generic
scsi_transport_iscsi fuse overlay xfs libcrc32c nfs lockd grace sunrpc
fscache jfs reiserfs multipath linear raid10 raid1 raid0 dm_raid raid456
async_raid6_recov async_memcpy async_pq async_xor async_tx md_mod
dm_snapshot dm_bufio dm_crypt dm_mirror dm_region_hash dm_log usbhid
xhci_pci xhci_hcd ohci_pci ohci_hcd uhci_hcd usb_storage ehci_pci
ehci_hcd usbcore usb_common sr_mod cdrom sg virtio_net
Mar 16 23:30:20 fileserver kernel: CPU: 2 PID: 3556 Comm:
btrfs-transacti Not tainted 4.1.15-gentoo-r1 #2
Mar 16 23:30:20 fileserver kernel: Hardware name: QEMU Standard PC
(i440FX + PIIX, 1996), BIOS
rel-1.9.3-0-ge2fc41e-prebuilt.qemu-project.org 04/01/2014
Mar 16 23:30:20 fileserver kernel:  0000000000000000 ffffffff8163e153
ffffffff81518242 ffff88082c1ebd28
Mar 16 23:30:20 fileserver kernel:  ffffffff8104ab7c ffff88042f73b600
00000000fffffffb ffff88082c68c800
Mar 16 23:30:20 fileserver kernel:  ffffffff8154f9d0 00000000000004a4
ffffffff8104abf5 ffffffff81636528
Mar 16 23:30:20 fileserver kernel: Call Trace:
Mar 16 23:30:20 fileserver kernel:  [<ffffffff81518242>] ?
dump_stack+0x40/0x50
Mar 16 23:30:20 fileserver kernel:  [<ffffffff8104ab7c>] ?
warn_slowpath_common+0x7c/0xb0
Mar 16 23:30:20 fileserver kernel:  [<ffffffff8104abf5>] ?
warn_slowpath_fmt+0x45/0x50
Mar 16 23:30:20 fileserver kernel:  [<ffffffff81252096>] ?
__btrfs_abort_transaction+0x46/0x110
Mar 16 23:30:20 fileserver kernel:  [<ffffffff812d3e6e>] ?
__btrfs_run_delayed_items+0xde/0x1d0
Mar 16 23:30:20 fileserver kernel:  [<ffffffff81280068>] ?
btrfs_commit_transaction+0x2b8/0xa60
Mar 16 23:30:20 fileserver kernel:  [<ffffffff8128089b>] ?
start_transaction+0x8b/0x5a0
Mar 16 23:30:20 fileserver kernel:  [<ffffffff8127bd0d>] ?
transaction_kthread+0x1cd/0x240
Mar 16 23:30:20 fileserver kernel:  [<ffffffff8127bb40>] ?
btrfs_cleanup_transaction+0x530/0x530
Mar 16 23:30:20 fileserver kernel:  [<ffffffff81066e8c>] ? kthread+0xbc/0xe0
Mar 16 23:30:20 fileserver kernel:  [<ffffffff81066dd0>] ?
kthread_create_on_node+0x180/0x180
Mar 16 23:30:20 fileserver kernel:  [<ffffffff8151da22>] ?
ret_from_fork+0x42/0x70
Mar 16 23:30:20 fileserver kernel:  [<ffffffff81066dd0>] ?
kthread_create_on_node+0x180/0x180
Mar 16 23:30:20 fileserver kernel: ---[ end trace f03445c45d440372 ]---
Mar 16 23:30:20 fileserver kernel: BTRFS: error (device sdb) in
__btrfs_run_delayed_items:1188: errno=-5 IO failure
Mar 16 23:30:20 fileserver kernel: BTRFS info (device sdb): forced readonly
Mar 16 23:30:20 fileserver kernel: BTRFS warning (device sdb): Skipping
commit of aborted transaction.
Mar 16 23:30:20 fileserver kernel: BTRFS: error (device sdb) in
cleanup_transaction:1692: errno=-5 IO failure
Mar 16 23:30:22 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415463870464
Mar 16 23:30:22 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415463870464

I removed the failing disk from the cluster and rebooted the server. The
filesystem mounted fine but some time later I got these :

Mar 17 03:49:48 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415464230912
Mar 17 03:49:48 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415464230912
Mar 17 03:49:48 fileserver kernel: BTRFS (device sdb): bad tree block
start 72340172838076673 3415464230912

The filesystem didn't remount readonly this time but I installed a new
kernel (4.9.6 with the r1 Gentoo patchset insteal of 4.1.15-r1) and
rebooted again. I have a snapshot of the full device at the time of each
reboot if it can help (I can relatively easily make rw copies and work
on them without affecting the ro snapshots) and an earlier one from 4
weeks ago.

Can someone please help me determine if I can save this filesystem and
how ? I suspect there isn't much damage in quantity (there were only a
handful of damaged sectors before the disk was removed). I'm just not
sure how I can check if the internal BTRFS structures are still sound
and won't create a snowball effect destroying much more.

It is still currently used in this state in production and I'm trying to
avoid a painful switch to a remote, slow snapshot from yesterday while
beginning a very long recovery from scratch (this is at least a 2 weeks
procedure maybe more).
I'll catch some sleep right now (it's 5:28 AM here) but I'll be able to
work on this in 3 or 4 hours.

Best regards,

Lionel

Re: help : "bad tree block start" -> btrfs forced readonly

[Lionel Bouton]

Le 17/03/2017 à 05:32, Lionel Bouton a écrit :
> Hi,
>
> [...]
> I'll catch some sleep right now (it's 5:28 AM here) but I'll be able to
> work on this in 3 or 4 hours.

I woke up to this :

Mar 17 06:56:30 fileserver kernel: btree_readpage_end_io_hook: 104476
callbacks suppressed
Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
block start 72340172838076673 3415463870464
Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
block start 72340172838076673 3415463870464
Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
block start 72340172838076673 3415463870464
Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
block start 72340172838076673 3415463870464
Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
block start 72340172838076673 3415463870464
Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
block start 72340172838076673 3415463870464
Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
block start 72340172838076673 3415463870464
Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
block start 72340172838076673 3415463870464
Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
block start 72340172838076673 3415463870464
Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
block start 72340172838076673 3415463870464

and the server was unusable.

I just moved the client to a read-only backup server and we are trying
to find out if we can salvage this or if we start the full restore
procedure.

Help ?

Lionel

Re: help : "bad tree block start" -> btrfs forced readonly

[Hans van Kranenburg]

On 03/17/2017 09:11 AM, Lionel Bouton wrote:
> Le 17/03/2017 à 05:32, Lionel Bouton a écrit :
>> Hi,
>>
>> [...]
>> I'll catch some sleep right now (it's 5:28 AM here) but I'll be able to
>> work on this in 3 or 4 hours.
> 
> I woke up to this :
> 
> Mar 17 06:56:30 fileserver kernel: btree_readpage_end_io_hook: 104476
> callbacks suppressed
> Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
> block start 72340172838076673 3415463870464
> Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
> block start 72340172838076673 3415463870464
> Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
> block start 72340172838076673 3415463870464
> Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
> block start 72340172838076673 3415463870464
> Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
> block start 72340172838076673 3415463870464
> Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
> block start 72340172838076673 3415463870464
> Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
> block start 72340172838076673 3415463870464
> Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
> block start 72340172838076673 3415463870464
> Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
> block start 72340172838076673 3415463870464
> Mar 17 06:56:30 fileserver kernel: BTRFS error (device sdb): bad tree
> block start 72340172838076673 3415463870464

The error is about a page of metadata (tree block) that is damaged or
has been lost.

Your btrfs is reading the metadata page at location 3415463870464
(virtual address space). Inside the page, the address is stored again as
a method of verification.

The error means that it expected to see metadata items that live in a
block at position 3415463870464 in your filesystem virtual address
space, but instead it encounters some data, from which the bytes in the
location where that address should be translate back to 72340172838076673.

I needed to look at the kernel source code to figure this out, the error
is not very descriptive.

found_start = btrfs_header_bytenr(eb);
if (found_start != eb->start) {
    btrfs_err_rl(fs_info, "bad tree block start %llu %llu",
        found_start, eb->start);
    ret = -EIO;
    goto err;
}

> and the server was unusable.

The impact depends heavily on what part of the metadata it is, which
tree it's from, how much tree is hidden behind it etc.

You can try btrfs-debug-tree -b 3415463870464 <blockdevice> to see if it
outputs any readable information. If this was a metadata page, it would
have at least a corrupted bytenr field, otherwise it's likely not
something in the btrfs metadata format.

> I just moved the client to a read-only backup server and we are trying
> to find out if we can salvage this or if we start the full restore
> procedure.

-- 
Hans van Kranenburg

Re: help : "bad tree block start" -> btrfs forced readonly

[Lionel Bouton]

Hi,

Le 17/03/2017 à 09:43, Hans van Kranenburg a écrit :
> btrfs-debug-tree -b 3415463870464

Here is what it gives me back :

btrfs-debug-tree -b 3415463870464 /dev/sdb
btrfs-progs v4.6.1
checksum verify failed on 3415463870464 found A85405B7 wanted 01010101
checksum verify failed on 3415463870464 found A85405B7 wanted 01010101
bytenr mismatch, want=3415463870464, have=72340172838076673
ERROR: failed to read 3415463870464

Is there a way to remove part of the tree and keep the rest ? It could
help minimize the time needed to restore data.

Lionel

Re: help : "bad tree block start" -> btrfs forced readonly

[Hans van Kranenburg]

On 03/17/2017 10:27 AM, Lionel Bouton wrote:
> Hi,
> 
> Le 17/03/2017 à 09:43, Hans van Kranenburg a écrit :
>> btrfs-debug-tree -b 3415463870464
> 
> Here is what it gives me back :
> 
> btrfs-debug-tree -b 3415463870464 /dev/sdb
> btrfs-progs v4.6.1
> checksum verify failed on 3415463870464 found A85405B7 wanted 01010101
> checksum verify failed on 3415463870464 found A85405B7 wanted 01010101
> bytenr mismatch, want=3415463870464, have=72340172838076673
> ERROR: failed to read 3415463870464

So in the place where checksum is supposed to be stored, it has 01010101
and recomputing the checksum of the garbage results in A85405B7. Found /
wanted is also confusing here, since 01010101 is what it found, but
A85405B7 is what it 'found out'.

> Is there a way to remove part of the tree and keep the rest ? It could
> help minimize the time needed to restore data.

No, that's not how it works. Those trees are not file/directory
structure trees.

You can try btrfs-debug-tree <blockdevice> and see how far it gets
dumping everything it can find, and then search for 3415463870464 in the
output. Somewhere, there has to be another object (one level higher)
which points to this address. If you find it, you can find out in which
tree the block lives.

-- 
Hans van Kranenburg

Re: help : "bad tree block start" -> btrfs forced readonly

[Roman Mamedov]

On Fri, 17 Mar 2017 10:27:11 +0100
Lionel Bouton <lionel-subscription@bouton.name> wrote:

> Hi,
> 
> Le 17/03/2017 à 09:43, Hans van Kranenburg a écrit :
> > btrfs-debug-tree -b 3415463870464
> 
> Here is what it gives me back :
> 
> btrfs-debug-tree -b 3415463870464 /dev/sdb
> btrfs-progs v4.6.1
> checksum verify failed on 3415463870464 found A85405B7 wanted 01010101
> checksum verify failed on 3415463870464 found A85405B7 wanted 01010101
> bytenr mismatch, want=3415463870464, have=72340172838076673
> ERROR: failed to read 3415463870464
> 
> Is there a way to remove part of the tree and keep the rest ? It could
> help minimize the time needed to restore data.

If you are able to experiment with writable snapshots, you could try using
"btrfs-corrupt-block" to kill the bad block, and see what btrfsck makes out of
the rest. In a similar case I got little to no damage to the overall FS.
http://www.spinics.net/lists/linux-btrfs/msg53061.html

-- 
With respect,
Roman

Re: help : "bad tree block start" -> btrfs forced readonly

[Lionel Bouton]

Le 17/03/2017 à 10:51, Roman Mamedov a écrit :
> On Fri, 17 Mar 2017 10:27:11 +0100
> Lionel Bouton <lionel-subscription@bouton.name> wrote:
>
>> Hi,
>>
>> Le 17/03/2017 à 09:43, Hans van Kranenburg a écrit :
>>> btrfs-debug-tree -b 3415463870464
>> Here is what it gives me back :
>>
>> btrfs-debug-tree -b 3415463870464 /dev/sdb
>> btrfs-progs v4.6.1
>> checksum verify failed on 3415463870464 found A85405B7 wanted 01010101
>> checksum verify failed on 3415463870464 found A85405B7 wanted 01010101
>> bytenr mismatch, want=3415463870464, have=72340172838076673
>> ERROR: failed to read 3415463870464
>>
>> Is there a way to remove part of the tree and keep the rest ? It could
>> help minimize the time needed to restore data.
> If you are able to experiment with writable snapshots, you could try using
> "btrfs-corrupt-block" to kill the bad block, and see what btrfsck makes out of
> the rest. In a similar case I got little to no damage to the overall FS.
> http://www.spinics.net/lists/linux-btrfs/msg53061.html
>
I've launched btrfs check in read-only mode :

btrfs check -p /dev/sdb
Checking filesystem on /dev/sdb
UUID: dbbde1f0-d8a0-4c7c-a7b8-17237e98e525
checksum verify failed on 3415463755776 found A85405B7 wanted 01010101
checksum verify failed on 3415463755776 found A85405B7 wanted 01010101
bytenr mismatch, want=3415463755776, have=72340172838076673
checksum verify failed on 3415464001536 found A85405B7 wanted 01010101
checksum verify failed on 3415464001536 found A85405B7 wanted 01010101
bytenr mismatch, want=3415464001536, have=72340172838076673
checksum verify failed on 3415464640512 found A85405B7 wanted 01010101
checksum verify failed on 3415464640512 found A85405B7 wanted 01010101
bytenr mismatch, want=3415464640512, have=72340172838076673

This goes on for pages... I probably missed some output and then there
are lots of errors like this one :

ref mismatch on [3415470456832 16384] extent item 1, found 0
Backref 3415470456832 root 3420 not referenced back 0x268013d0
Incorrect global backref count on 3415470456832 found 1 wanted 0
backpointer mismatch on [3415470456832 16384]
owner ref check failed [3415470456832 16384]

...

Followed by lots of this :

ref mismatch on [11010388205568 278528] extent item 1, found 0
checksum verify failed on 3415464869888 found A85405B7 wanted 01010101
checksum verify failed on 3415464869888 found A85405B7 wanted 01010101
bytenr mismatch, want=3415464869888, have=72340172838076673
Incorrect local backref count on 11010388205568 root 257 owner 7487206
offset 0 found 0 wanted 1 back 0x72335670
Backref disk bytenr does not match extent record, bytenr=11010388205568,
ref bytenr=0
backpointer mismatch on [11010388205568 278528]
owner ref check failed [11010388205568 278528]

...

I stopped there : am I correct in thinking that it will take ages to try
to salvage this without any guarantee that I'll get a substantial amount
of the 10 million files on this filesystem ?

I'm considering trying to use a 4 week old snapshot of the device to
find out if it was corrupted or not instead. It will still be a pain if
it works but rsync for less than a month of data is at least an order of
magnitude faster than a full restore.

Lionel

Re: help : "bad tree block start" -> btrfs forced readonly

[Lionel Bouton]

Hi,

some news from the coal mine...

Le 17/03/2017 à 11:03, Lionel Bouton a écrit :
> [...]
> I'm considering trying to use a 4 week old snapshot of the device to
> find out if it was corrupted or not instead. It will still be a pain if
> it works but rsync for less than a month of data is at least an order of
> magnitude faster than a full restore.

btrfs check -p /dev/sdb is running on this 4 week old snapshot. The
extents check passed without any error, it is currently checking the
free space (and it's just done while I was writing this and is doing fs
roots).

I'm not sure of the list of checks it performs. I assume the free
space^H... fs roots can't be much longer than the rest (on a ~13TB of
20TB used filesystem with ~ 10 million files and half a dozen subvolumes).
It took less than an hour to check extents. I'll give it another hour
and stop it if its not done : it's already passing stages than the live
data couldn't get to.

I may be wrong but I suspect Ceph is innocent of any wrong-doing here :
I think there's a high probability that if Ceph could corrupt its data
in our configuration the snapshot would have been corrupted too (most of
its data is shared with the live data). I wonder if QEMU or the VM
kernel managed to transform IO timeouts (which clearly happened below
Ceph and were passed to the VM in many instances) into garbage reads
which ended in garbage writes. If it isn't in QEMU and happened in the
kernel this was with 4.1.15 so it might be a corrected kernel bug in
either the block or fs layers. I'm not especially ecstatic at the
prospect of testing this behavior again but I will automate more Ceph
snapshots in the future (and the VM is now on 4.9.6).

Best regards,

Lionel