On Tue, Mar 12, 2019 at 12:00:25AM -0400, Zygo Blaxell wrote:
> On 4.14.x and 4.20.14 kernels (probably all the ones in between too,
> but I haven't tested those), I get what I call "ghost parent transid
> verify failed" errors. Here's an unedited recent example from dmesg:
>
> [16180.649285] BTRFS error (device dm-3): parent transid verify failed
> on 1218181971968 wanted 9698 found 9744
These happen much less often on 5.0.x, but they still happen from time
to time.
5.0.5 also produced a lockdep warning last night, the first such warning
I have seen with this call trace:
[Tue Apr 2 23:00:28 2019] WARNING: CPU: 1 PID: 4213 at
kernel/locking/lockdep.c:702 register_lock_class+0x2f2/0x590
[Tue Apr 2 23:00:28 2019] Modules linked in: crct10dif_pclmul
crc32_pclmul crc32c_intel ghash_clmulni_intel ppdev joydev dm_cache_smq
dm_cache dm_persistent_data dm_bio_prison dm_bufio dm_mod aesni_intel
aes_x86_64 snd_pcm crypto_simd cryptd glue_helper snd_timer sr_mod cdrom snd
soundcore sg parport_pc input_leds psmouse rtc_cmos ide_pci_generic pcspkr
serio_raw floppy parport piix bochs_drm ide_core i2c_piix4 evbug evdev
qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
[Tue Apr 2 23:00:28 2019] CPU: 1 PID: 4213 Comm: btrfs-cleaner Not
tainted 5.0.5-zb64-4eaee293f832+ #1
[Tue Apr 2 23:00:28 2019] Hardware name: QEMU Standard PC (i440FX +
PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[Tue Apr 2 23:00:28 2019] RIP: 0010:register_lock_class+0x2f2/0x590
[Tue Apr 2 23:00:28 2019] Code: 40 b2 f8 8d 89 c2 e8 9d 94 00 00 66 90
85 d2 74 11 48 c7 c7 c8 45 5e 8c e8 eb fb ff ff e8 fb b2 c2 00 45 31 ff e9 f6
fd ff ff <0f> 0b 8b 05 ee 41 e8 02 e9 c0 fd ff ff 65 48 8b 04 25 00 6e 01 00
[Tue Apr 2 23:00:28 2019] RSP: 0018:ffffb15f40893ab0 EFLAGS: 00010087
[Tue Apr 2 23:00:28 2019] RAX: ffffffff8c906af0 RBX: 0000000000000282
RCX: 0000000000000000
[Tue Apr 2 23:00:28 2019] RDX: ffffffff8e085a18 RSI: 000000000000076e
RDI: 0000000000000000
[Tue Apr 2 23:00:28 2019] RBP: 0000000000000000 R08: ffffffff8b4dd33d
R09: 0000000000000000
[Tue Apr 2 23:00:28 2019] R10: 0000000000000000 R11: ffff908c2a09a720
R12: 0000000000000000
[Tue Apr 2 23:00:28 2019] R13: 0000000000000001 R14: ffff908c2a09a720
R15: ffffffff8d623b60
[Tue Apr 2 23:00:28 2019] FS: 0000000000000000(0000)
GS:ffff908d3a000000(0000) knlGS:0000000000000000
[Tue Apr 2 23:00:28 2019] CS: 0010 DS: 0000 ES: 0000 CR0:
0000000080050033
[Tue Apr 2 23:00:28 2019] CR2: 00007f65819ea1f0 CR3: 00000001328d2006
CR4: 00000000001606e0
[Tue Apr 2 23:00:28 2019] Call Trace:
[Tue Apr 2 23:00:28 2019] ? __lock_acquire+0x477/0x1b30
[Tue Apr 2 23:00:28 2019] __lock_acquire+0xb1/0x1b30
[Tue Apr 2 23:00:28 2019] ? btrfs_tree_lock+0x9d/0x250
[Tue Apr 2 23:00:28 2019] ? __lock_acquire+0x477/0x1b30
[Tue Apr 2 23:00:28 2019] ? lock_acquire+0xbc/0x1c0
[Tue Apr 2 23:00:28 2019] lock_acquire+0xbc/0x1c0
[Tue Apr 2 23:00:28 2019] ? btrfs_tree_lock+0x9d/0x250
[Tue Apr 2 23:00:28 2019] _raw_write_lock+0x30/0x70
[Tue Apr 2 23:00:28 2019] ? btrfs_tree_lock+0x9d/0x250
[Tue Apr 2 23:00:28 2019] btrfs_tree_lock+0x9d/0x250
[Tue Apr 2 23:00:28 2019] ? mark_page_accessed+0x13d/0x160
[Tue Apr 2 23:00:28 2019] ? mark_extent_buffer_accessed+0x67/0x80
[Tue Apr 2 23:00:28 2019] do_walk_down+0x126/0x610
[Tue Apr 2 23:00:28 2019] ? do_raw_spin_unlock+0x49/0xc0
[Tue Apr 2 23:00:28 2019] walk_down_tree+0xb8/0x100
[Tue Apr 2 23:00:28 2019] btrfs_drop_snapshot+0x3a4/0x8d0
[Tue Apr 2 23:00:28 2019] btrfs_clean_one_deleted_snapshot+0xb2/0x110
[Tue Apr 2 23:00:28 2019] cleaner_kthread+0x11f/0x180
[Tue Apr 2 23:00:28 2019] kthread+0x106/0x140
[Tue Apr 2 23:00:28 2019] ? btrfs_destroy_pinned_extent+0x1b0/0x1b0
[Tue Apr 2 23:00:28 2019] ? kthread_park+0x90/0x90
[Tue Apr 2 23:00:28 2019] ret_from_fork+0x3a/0x50
[Tue Apr 2 23:00:28 2019] irq event stamp: 131299397
[Tue Apr 2 23:00:28 2019] hardirqs last enabled at (131299397):
[<ffffffff8b2bd4fe>] kmem_cache_alloc+0x1fe/0x310
[Tue Apr 2 23:00:28 2019] hardirqs last disabled at (131299396):
[<ffffffff8b2bd3b5>] kmem_cache_alloc+0xb5/0x310
[Tue Apr 2 23:00:28 2019] softirqs last enabled at (131299388):
[<ffffffff8c0003a4>] __do_softirq+0x3a4/0x45f
[Tue Apr 2 23:00:28 2019] softirqs last disabled at (131299339):
[<ffffffff8b0a3d54>] irq_exit+0xe4/0xf0
[Tue Apr 2 23:00:28 2019] ---[ end trace 3fa5835f7315f7f2 ]---
The comments around lockdep.c:702 talk about trampling on memory,
which could be a use-after-free bug. The spurious parent transid
verify failures also behave like a use-after-free bug. Both events have
occurred only while snapshots are being deleted. This smells a lot like
a use-after-free bug in the btrfs snapshot delete code.
Some time later:
[Wed Apr 3 09:05:20 2019] BTRFS error (device dm-3): parent transid
verify failed on 2071098556416 wanted 13332 found 13308
[Wed Apr 3 09:05:21 2019] BTRFS error (device dm-3): parent transid
verify failed on 2071098556416 wanted 13332 found 13308
In this case the test machine was running a workload that includes
continuous snapshot deletes--snapshots are created in parallel by a
process that tries to keep 20-100 snapshots being deleted at all times
(in addition to the usual 10 rsyncs + bees dedupe).
The log messages here are 10 hours apart, and the first appeared 3 hours
after boot. Normally, there will be a few "parent transid verify failed"
messages per 24 hours of snapshot delete time.
