Re: delayed dir index insertion failure

[Kenneth Topp <ken@bllue.org>]

On 2023-09-12 07:18, Filipe Manana wrote:
> On Mon, Sep 11, 2023 at 11:14:49PM -0400, ken wrote:
>> I've been getting these reliably, so I switched to stock fedora 38
>> kernel, and I recreated the filesystem and repopulated the data from
>> backups (the filesystem failed btrfs check, didn't save the output of
>> that).  But with a fresh filesystem and all data recovered it's still
>> triggering.  Filesystem is   created "-O no-holes -d single -m raid1"
>> ontop two dm-crypt block devices.
>> mount options are "defaults,noatime,space_cache=v2"
>> 
>> I've seen some recent patches for this, not sure if that's a fix or
>> just improved diagnostics.  Happy to try something out to try to get
>> to the root cause.  The machine is under extremely heavy load during
>> bootup, which is mostly services putting in io requests which I
>> suspect could be involved.
>> 
>> details below,
> 
> Thanks for the report.
> 
> This should be the same that syzbot reported about a week ago.
> I've just sent a fix for it:
> 
> https://lore.kernel.org/linux-btrfs/903764240e39987ca676cd02913a836b3b4930c8.1694515104.git.fdmanana@suse.com/
> 
> This won't apply cleanly without the following recent patchset:
> 
> https://lore.kernel.org/linux-btrfs/cover.1694260751.git.fdmanana@suse.com/
> 
> But it's independent of it actually.
> 
> Thnaks.
> 

Unfortunately, I was not able to reproduce the issue anymore with the 
same kernel that was triggering the BUG constantly on boot up. I have 
booted up 6.4.16-rc1 both with and without your additional patches, and 
no occurrence of the issue there as well.  So unfortunately, I cannot 
say this fixed the issue, but at least I can say it's not any worse.  I 
will be running with these patches until they are upstream, and will 
report anything unexpected.

Thanks,

Ken

>> 
>> ken
>> 
>> Sep 11 22:33:09 myhostname kernel: Linux version
>> 6.4.15-200.fc38.x86_64 (mockbuild@2e6cd98d8465441c8330a02794035256)
>> (gcc (GCC) 13.2.1 20230728 (Red Hat 13.2.1-1), GNU ld version
>> 2.39-9.fc38) #1 SMP PREEMPT_DYNAMIC Thu Sep  7 00:25:01 UTC 2023
>> Sep 11 22:33:09 myhostname kernel: Command line:
>> BOOT_IMAGE=(hd0,msdos1)/vmlinuz-6.4.15-200.fc38.x86_64
>> root=LABEL=r3-root ro slub_debug=- usbcore.autosuspend=-1 rd.md=0
>> rd.lvm=0 rd.dm=0 libata.allow_tpm=1 vconsole.keymap=us rd.luks=0
>> vconsole.font
>> =latarcyrheb-sun16 quiet systemd.show_status=1 selinux=0 
>> mitigations=off
>> 
>> 
>> 
>> 
>> Sep 11 22:34:59 myhostname kernel: BTRFS error (device dm-3): err add
>> delayed dir index item(name: cockroach-stderr.log) into the insertion
>> tree of the delayed node(root id: 5, inode id: 4539217, errno: -17)
>> Sep 11 22:34:59 myhostname kernel: ------------[ cut here 
>> ]------------
>> Sep 11 22:34:59 myhostname kernel: kernel BUG at 
>> fs/btrfs/delayed-inode.c:1504!
>> Sep 11 22:34:59 myhostname kernel: invalid opcode: 0000 [#1] PREEMPT 
>> SMP NOPTI
>> Sep 11 22:34:59 myhostname kernel: CPU: 0 PID: 7159 Comm: cockroach
>> Not tainted 6.4.15-200.fc38.x86_64 #1
>> Sep 11 22:34:59 myhostname kernel: Hardware name: ASUS ESC500 G3/P9D
>> WS, BIOS 2402 06/27/2018
>> Sep 11 22:34:59 myhostname kernel: RIP:
>> 0010:btrfs_insert_delayed_dir_index+0x1da/0x260
>> Sep 11 22:34:59 myhostname kernel: Code: eb dd 48 8b 43 10 4c 8b 0b 44
>> 89 e2 48 c7 c6 00 3a 91 85 48 8b 7d 50 4c 8b 80 f7 01 00 00 41 57 48
>> 8b 4c 24 08 e8 56 67 04 00 <0f> 0b 65 8b 05 b9 e9 9c 7b 89 c0 48 0f a3
>> 05 c3 f0 cb 01 0f 83 2f
>> Sep 11 22:34:59 myhostname kernel: RSP: 0000:ffffa9980e0fbb28 EFLAGS: 
>> 00010282
>> Sep 11 22:34:59 myhostname kernel: RAX: 0000000000000000 RBX:
>> ffff8b10b8f4a3c0 RCX: 0000000000000000
>> Sep 11 22:34:59 myhostname kernel: RDX: 0000000000000000 RSI:
>> ffff8b177ec21540 RDI: ffff8b177ec21540
>> Sep 11 22:34:59 myhostname kernel: RBP: ffff8b110cf80888 R08:
>> 0000000000000000 R09: ffffa9980e0fb938
>> Sep 11 22:34:59 myhostname kernel: R10: 0000000000000003 R11:
>> ffffffff86146508 R12: 0000000000000014
>> Sep 11 22:34:59 myhostname kernel: R13: ffff8b1131ae5b40 R14:
>> ffff8b10b8f4a418 R15: 00000000ffffffef
>> Sep 11 22:34:59 myhostname kernel: FS:  00007fb14a7fe6c0(0000)
>> GS:ffff8b177ec00000(0000) knlGS:0000000000000000
>> Sep 11 22:34:59 myhostname kernel: CS:  0010 DS: 0000 ES: 0000 CR0:
>> 0000000080050033
>> Sep 11 22:34:59 myhostname kernel: CR2: 000000c00143d000 CR3:
>> 00000001b3b4e002 CR4: 00000000001706f0
>> Sep 11 22:34:59 myhostname kernel: Call Trace:
>> Sep 11 22:34:59 myhostname kernel:  <TASK>
>> Sep 11 22:34:59 myhostname kernel:  ? die+0x36/0x90
>> Sep 11 22:34:59 myhostname kernel:  ? do_trap+0xda/0x100
>> Sep 11 22:34:59 myhostname kernel:  ? 
>> btrfs_insert_delayed_dir_index+0x1da/0x260
>> Sep 11 22:34:59 myhostname kernel:  ? do_error_trap+0x6a/0x90
>> Sep 11 22:34:59 myhostname kernel:  ? 
>> btrfs_insert_delayed_dir_index+0x1da/0x260
>> Sep 11 22:34:59 myhostname kernel:  ? exc_invalid_op+0x50/0x70
>> Sep 11 22:34:59 myhostname kernel:  ? 
>> btrfs_insert_delayed_dir_index+0x1da/0x260
>> Sep 11 22:34:59 myhostname kernel:  ? asm_exc_invalid_op+0x1a/0x20
>> Sep 11 22:34:59 myhostname kernel:  ? 
>> btrfs_insert_delayed_dir_index+0x1da/0x260
>> Sep 11 22:34:59 myhostname kernel:  ? 
>> btrfs_insert_delayed_dir_index+0x1da/0x260
>> Sep 11 22:34:59 myhostname kernel:  btrfs_insert_dir_item+0x200/0x280
>> Sep 11 22:34:59 myhostname kernel:  btrfs_add_link+0xab/0x4f0
>> Sep 11 22:34:59 myhostname kernel:  ? ktime_get_real_ts64+0x47/0xe0
>> Sep 11 22:34:59 myhostname kernel:  btrfs_create_new_inode+0x7cd/0xa80
>> Sep 11 22:34:59 myhostname kernel:  btrfs_symlink+0x190/0x4d0
>> Sep 11 22:34:59 myhostname kernel:  ? schedule+0x5e/0xd0
>> Sep 11 22:34:59 myhostname kernel:  ? __d_lookup+0x7e/0xc0
>> Sep 11 22:34:59 myhostname kernel:  vfs_symlink+0x148/0x1e0
>> Sep 11 22:34:59 myhostname kernel:  do_symlinkat+0x130/0x140
>> Sep 11 22:34:59 myhostname kernel:  __x64_sys_symlinkat+0x3d/0x50
>> Sep 11 22:34:59 myhostname kernel:  do_syscall_64+0x5d/0x90
>> Sep 11 22:34:59 myhostname kernel:  ? 
>> syscall_exit_to_user_mode+0x2b/0x40
>> Sep 11 22:34:59 myhostname kernel:  ? do_syscall_64+0x6c/0x90
>> Sep 11 22:34:59 myhostname kernel:  
>> entry_SYSCALL_64_after_hwframe+0x72/0xdc
>> Sep 11 22:34:59 myhostname kernel: RIP: 0033:0x83d8d0
>> Sep 11 22:34:59 myhostname kernel: Code: 8b 7c 24 10 48 8b 74 24 18 48
>> 8b 54 24 20 49 c7 c2 00 00 00 00 49 c7 c0 00 00 00 00 49 c7 c1 00 00
>> 00 00 48 8b 44 24 08 0f 05 <48> 3d 01 f0 ff ff 76 20 48 c7 44 24 28 ff
>> ff ff ff 48 c7 44 24 30
>> Sep 11 22:34:59 myhostname kernel: RSP: 002b:000000c0012b4588 EFLAGS:
>> 00000212 ORIG_RAX: 000000000000010a
>> Sep 11 22:34:59 myhostname kernel: RAX: ffffffffffffffda RBX:
>> 000000c000080000 RCX: 000000000083d8d0
>> Sep 11 22:34:59 myhostname kernel: RDX: 000000c000d98f00 RSI:
>> ffffffffffffff9c RDI: 000000c000894680
>> Sep 11 22:34:59 myhostname kernel: RBP: 000000c0012b45f0 R08:
>> 0000000000000000 R09: 0000000000000000
>> Sep 11 22:34:59 myhostname kernel: R10: 0000000000000000 R11:
>> 0000000000000212 R12: ffffffffffffffff
>> Sep 11 22:34:59 myhostname kernel: R13: 0000000000000031 R14:
>> 0000000000000030 R15: 0000000000000066
>> Sep 11 22:34:59 myhostname kernel:  </TASK>
>> Sep 11 22:34:59 myhostname kernel: Modules linked in: rpcrdma rdma_cm
>> iw_cm ib_cm ib_core nf_conntrack_netlink br_netfilter tun wireguard
>> curve25519_x86_64 libcurve25519_generic ip6_udp_tunnel udp_tunnel
>> ip6table_nat ip6table_filter des_generic lib
>> des md4 nf_log_syslog nft_log nft_limit nft_reject_inet nf_reject_ipv4
>> nf_reject_ipv6 nft_reject xt_conntrack iptable_filter nft_ct
>> xt_multiport xt_nat xt_addrtype nft_masq xt_mark nft_redir
>> xt_MASQUERADE xt_comment iptable_nat veth nft_nat bridge nft_ch
>> ain_nat stp nf_nat llc nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4
>> overlay nf_tables nfnetlink nct6775 nct6775_core hwmon_vid jc42
>> binfmt_misc ir_rc6_decoder rc_rc6_mce ir_toy cdc_acm cdc_mbim cdc_wdm
>> cdc_ncm cdc_ether usbnet hid_logitech_hidpp joydev dm_
>> crypt hid_logitech_dj intel_rapl_msr amdgpu ppdev r8152 at24 mii
>> mei_hdcp mei_pxp iTCO_wdt intel_pmc_bxt iTCO_vendor_support
>> intel_rapl_common rt73usb x86_pkg_temp_thermal rt2x00usb rt2x00lib
>> intel_powerclamp coretemp iwlmvm r820t kvm_intel snd_hda_codec
>> _realtek rtl2832 snd_hda_codec_generic i2c_mux
>> Sep 11 22:34:59 myhostname kernel:  snd_hda_codec_hdmi kvm mac80211
>> irqbypass dvb_usb_rtl28xxu snd_hda_intel rapl snd_usb_audio eeepc_wmi
>> snd_intel_dspcfg iommu_v2 snd_intel_sdw_acpi dvb_usb_v2 drm_buddy
>> iwlwifi dvb_core asus_wmi snd_hda_codec snd_
>> usbmidi_lib ledtrig_audio snd_rawmidi gpu_sched sparse_keymap libarc4
>> platform_profile snd_hda_core mc wmi_bmof intel_cstate intel_uncore
>> snd_hwdep drm_suballoc_helper mxm_wmi pcspkr snd_seq i2c_i801
>> drm_ttm_helper cfg80211 snd_seq_device i2c_smbus ttm s
>> nd_pcm drm_display_helper lpc_ich mei_me mei snd_timer cec snd
>> soundcore rfkill ie31200_edac parport_pc parport nfsd auth_rpcgss
>> nfs_acl lockd grace sunrpc loop zram usb_storage crct10dif_pclmul
>> crc32_pclmul crc32c_intel polyval_clmulni polyval_generic f
>> irewire_ohci ghash_clmulni_intel firewire_core sha512_ssse3 crc_itu_t
>> mpt3sas igb i2c_algo_bit raid_class dca scsi_transport_sas video wmi
>> scsi_dh_rdac scsi_dh_emc scsi_dh_alua ip6_tables ip_tables
>> pkcs8_key_parser dm_multipath i2c_dev fuse
>> Sep 11 22:34:59 myhostname kernel: ---[ end trace 0000000000000000 
>> ]---
>> Sep 11 22:34:59 myhostname kernel: RIP:
>> 0010:btrfs_insert_delayed_dir_index+0x1da/0x260
>> Sep 11 22:34:59 myhostname kernel: Code: eb dd 48 8b 43 10 4c 8b 0b 44
>> 89 e2 48 c7 c6 00 3a 91 85 48 8b 7d 50 4c 8b 80 f7 01 00 00 41 57 48
>> 8b 4c 24 08 e8 56 67 04 00 <0f> 0b 65 8b 05 b9 e9 9c 7b 89 c0 48 0f a3
>> 05 c3 f0 cb 01 0f 83 2f
>> Sep 11 22:34:59 myhostname kernel: RSP: 0000:ffffa9980e0fbb28 EFLAGS: 
>> 00010282
>> Sep 11 22:34:59 myhostname kernel: RAX: 0000000000000000 RBX:
>> ffff8b10b8f4a3c0 RCX: 0000000000000000
>> Sep 11 22:34:59 myhostname kernel: RDX: 0000000000000000 RSI:
>> ffff8b177ec21540 RDI: ffff8b177ec21540
>> Sep 11 22:34:59 myhostname kernel: RBP: ffff8b110cf80888 R08:
>> 0000000000000000 R09: ffffa9980e0fb938
>> Sep 11 22:34:59 myhostname kernel: R10: 0000000000000003 R11:
>> ffffffff86146508 R12: 0000000000000014
>> Sep 11 22:34:59 myhostname kernel: R13: ffff8b1131ae5b40 R14:
>> ffff8b10b8f4a418 R15: 00000000ffffffef
>> Sep 11 22:34:59 myhostname kernel: FS:  00007fb14a7fe6c0(0000)
>> GS:ffff8b177ec00000(0000) knlGS:0000000000000000
>> Sep 11 22:34:59 myhostname kernel: CS:  0010 DS: 0000 ES: 0000 CR0:
>> 0000000080050033
>> Sep 11 22:34:59 myhostname kernel: CR2: 000000c00143d000 CR3:
>> 00000001b3b4e002 CR4: 00000000001706f0