Re: Spurious "ghost" "parent transid verify failed" messages on 5.0.5 + lockdep warning

[Zygo Blaxell <ce3g8jdj@umail.furryterror.org>]

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.