btrfs errors over NFS

[Steve Leung <sjleung@shaw.ca>]

Hi list,

  TL;DR: ran into some btrfs errors and weird behaviour, but things generally seem 
  to work.  Just posting some details in case it helps devs or other users.

I've run into a btrfs error trying to do a -j8 build of android on a btrfs 
filesystem exported over NFSv3.  That in itself might be unwise, but should be 
legal.  :)  This is on 64-bit Arch, kernel 4.13.3, and the filesystem is RAID1 on 4 
devices, with nearly 4TiB unallocated.

The build itself failed when part of the build process noticed that a file got 
created with mode 000.  i.e. in "ls -l" the mode column looked like ?---------.

That much happened without any errors in dmesg, though the NFS client complained 
about some inodes having a mode of 0.

Then when I tried to delete those files, I got the error below:

[21476.546060] BTRFS error (device sdc1): err add delayed dir index item(index: 17) into the deletion tree of the delayed node(root id: 21780, inode id: 15668343, errno: -17)
[21476.546194] ------------[ cut here ]------------
[21476.546196] kernel BUG at fs/btrfs/delayed-inode.c:1552!
[21476.546231] invalid opcode: 0000 [#1] PREEMPT SMP
[21476.546258] Modules linked in: ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack libcrc32c iptable_filter tun coretemp kvm_intel kvm iTCO_wdt ppdev gpio_ich iTCO_vendor_support evdev i915 input_leds psmouse pcspkr irqbypass i2c_i801 snd_hda_codec_idt snd_hda_codec_generic mac_hid lpc_ich tpm_tis tpm_tis_core parport_pc tpm parport video drm_kms_helper drm syscopyarea winbond_cir sysfillrect sysimgblt rc_core led_class snd_hda_intel snd_hda_codec snd_hda_core snd_hwdep snd_pcm snd_timer shpchp snd button e1000e soundcore intel_agp intel_gtt acpi_cpufreq mei_me mei fb_sys_fops i2c_algo_bit ptp pps_core sch_fq_codel nfsd auth_rpcgss oid_registry nfs_acl lockd grace sunrpc ip_tables x_tables crc32c_generic btrfs xor raid6_pq sr_mod cdrom
[21476.546623]  sd_mod hid_generic usbhid hid serio_raw atkbd libps2 uhci_hcd pata_it821x ahci libahci libata firewire_ohci scsi_mod firewire_core crc_itu_t i8042 serio ehci_pci ehci_hcd usbcore usb_common
[21476.546725] CPU: 0 PID: 984 Comm: rm Not tainted 4.13.3-1-ARCH #1
[21476.546756] Hardware name:                  /DG33TL, BIOS DPP3510J.86A.0572.2009.0715.2346 07/15/2009
[21476.546801] task: ffff943668131b80 task.stack: ffffaa3840da4000
[21476.546854] RIP: 0010:btrfs_delete_delayed_dir_index+0x24d/0x330 [btrfs]
[21476.546889] RSP: 0018:ffffaa3840da7d18 EFLAGS: 00010286
[21476.546918] RAX: 0000000000000000 RBX: ffff94367c074b90 RCX: 0000000000000000
[21476.546953] RDX: 0000000000000000 RSI: ffff9436abc0dc78 RDI: ffff9436abc0dc78
[21476.546989] RBP: ffffaa3840da7d88 R08: 0000000000000323 R09: 0000000000000000
[21476.547025] R10: ffffaa3840da7bd8 R11: 00000000ffffffff R12: ffff943583503100
[21476.547060] R13: ffff94367c074bd8 R14: ffff94367c074bd0 R15: ffff943583503218
[21476.547096] FS:  00007f57da0f6500(0000) GS:ffff9436abc00000(0000) knlGS:0000000000000000
[21476.547138] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[21476.547167] CR2: 00007f57d9c809c0 CR3: 000000005e39b000 CR4: 00000000000006f0
[21476.547203] Call Trace:
[21476.547235]  __btrfs_unlink_inode+0x1bc/0x550 [btrfs]
[21476.547278]  btrfs_unlink_inode+0x1c/0x50 [btrfs]
[21476.547317]  btrfs_unlink+0x88/0xe0 [btrfs]
[21476.547343]  vfs_unlink+0x111/0x1c0
[21476.547365]  ? __lookup_hash+0x22/0xa0
[21476.547389]  do_unlinkat+0x2b1/0x310
[21476.547412]  SyS_unlinkat+0x1b/0x30
[21476.547434]  entry_SYSCALL_64_fastpath+0x1a/0xa5
[21476.547460] RIP: 0033:0x7f57d9c303d7
[21476.547481] RSP: 002b:00007fff4bc1a6b8 EFLAGS: 00000246 ORIG_RAX: 0000000000000107
[21476.547520] RAX: ffffffffffffffda RBX: 00005644fee69540 RCX: 00007f57d9c303d7
[21476.547556] RDX: 0000000000000000 RSI: 00005644fee68310 RDI: 00000000ffffff9c
[21476.547591] RBP: 00005644fee69648 R08: 0000000000000003 R09: 0000000000000000
[21476.547627] R10: 0000000000000100 R11: 0000000000000246 R12: 00005644fee68280
[21476.547662] R13: 00007fff4bc1a7f0 R14: 00005644fd37094f R15: 0000000000000000
[21476.547700] Code: ff ff ff 48 8b 43 10 4c 8b 03 41 b9 ef ff ff ff 48 8b 55 b0 48 8b 7d a8 48 c7 c6 b0 99 3f c0 48 8b 88 38 03 00 00 e8 f3 0d f7 ff <0f> 0b 48 8b 4d a8 49 8b 7e 38 8b 81 70 10 00 00 48 8d b1 c8 01 
[21476.547840] RIP: btrfs_delete_delayed_dir_index+0x24d/0x330 [btrfs] RSP: ffffaa3840da7d18
[21476.549333] ---[ end trace 41039f5467d88882 ]---

After that, a bunch of processes started hanging and I eventually stopped being 
able to do useful things on the machine, so I hard rebooted it.

It booted back up fine.  I tried scrubbing the filesystem at that point and scrub 
returned with no errors.  I then noticed 4.13.5 had some btrfs fixes so I upgraded 
to that.  Now, I still have one bogus file in a directory - it's in the directory 
listing but nothing can stat the file to change it or remove it.  i.e.:

  > ls -l
  /bin/ls: cannot access 'tab_unselected_pressed_holo.9.png': No such file or directory
  total 0
  -????????? ? ? ? ?            ? tab_unselected_pressed_holo.9.png

  > stat tab_unselected_pressed_holo.9.png 
  stat: cannot stat 'tab_unselected_pressed_holo.9.png': No such file or directory

  > rm tab_unselected_pressed_holo.9.png 
  rm: cannot remove 'tab_unselected_pressed_holo.9.png': No such file or directory

  > cp /dev/null tab_unselected_pressed_holo.9.png 
  > ls -l
  total 0
  -rw-r--r-- 1 steve steve 0 Oct 12 10:43 tab_unselected_pressed_holo.9.png
  -rw-r--r-- 1 steve steve 0 Oct 12 10:43 tab_unselected_pressed_holo.9.png

  > rm tab_unselected_pressed_holo.9.png 

  > ls -l
  /bin/ls: cannot access 'tab_unselected_pressed_holo.9.png': No such file or directory
  total 0
  -????????? ? ? ? ?            ? tab_unselected_pressed_holo.9.png

I'm guessing a btrfs check would fix this but haven't gotten around to running it 
yet.

After moving aside the dir with the bogus file, I was able to complete the Android 
build successfully, but noticed these warnings in the log afterward:

[11319.762849] ------------[ cut here ]------------
[11319.762883] WARNING: CPU: 1 PID: 451 at fs/btrfs/ctree.h:1559 btrfs_update_device+0x1be/0x1d0 [btrfs]
[11319.762884] Modules linked in: ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack libcrc32c iptable_filter tun coretemp kvm_intel iTCO_wdt iTCO_vendor_support i915 gpio_ich ppdev kvm video i2c_algo_bit drm_kms_helper snd_hda_codec_idt snd_hda_codec_generic irqbypass drm syscopyarea psmouse sysfillrect snd_hda_intel pcspkr i2c_i801 e1000e mei_me sysimgblt snd_hda_codec evdev fb_sys_fops input_leds mei lpc_ich snd_hda_core snd_hwdep snd_pcm snd_timer snd soundcore parport_pc parport mac_hid ptp pps_core shpchp winbond_cir rc_core intel_agp intel_gtt led_class agpgart tpm_tis tpm_tis_core tpm button acpi_cpufreq nfsd auth_rpcgss oid_registry nfs_acl lockd grace sunrpc sch_fq_codel ip_tables x_tables crc32c_generic btrfs xor raid6_pq hid_generic
[11319.762937]  sr_mod cdrom sd_mod usbhid hid serio_raw atkbd libps2 uhci_hcd firewire_ohci pata_it821x ahci libahci libata firewire_core scsi_mod crc_itu_t i8042 serio ehci_pci ehci_hcd usbcore usb_common
[11319.762957] CPU: 1 PID: 451 Comm: nfsd Not tainted 4.13.5-1-ARCH #1
[11319.762959] Hardware name:                  /DG33TL, BIOS DPP3510J.86A.0572.2009.0715.2346 07/15/2009
[11319.762960] task: ffff90dce9e5b700 task.stack: ffff9e1fc1448000
[11319.762975] RIP: 0010:btrfs_update_device+0x1be/0x1d0 [btrfs]
[11319.762977] RSP: 0018:ffff9e1fc144b468 EFLAGS: 00010206
[11319.762978] RAX: 0000000000000fff RBX: ffff90dd227d7a80 RCX: 000003a3816d1e00
[11319.762980] RDX: 0000000000000004 RSI: 0000000000007e98 RDI: ffff90dc990fbb58
[11319.762981] RBP: ffff9e1fc144b4b0 R08: 0000000000007e9c R09: ffff9e1fc144b420
[11319.762982] R10: 0000000000001000 R11: 0000000000000007 R12: ffff90dd21f77c00
[11319.762984] R13: 0000000000000000 R14: 0000000000007e78 R15: ffff90dc990fbb58
[11319.762985] FS:  0000000000000000(0000) GS:ffff90dd2bc80000(0000) knlGS:0000000000000000
[11319.762987] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[11319.762988] CR2: 00005572c6c61c90 CR3: 000000016741a000 CR4: 00000000000006e0
[11319.762990] Call Trace:
[11319.763008]  btrfs_finish_chunk_alloc+0x136/0x4f0 [btrfs]
[11319.763020]  ? btrfs_free_path.part.31+0x21/0x30 [btrfs]
[11319.763033]  btrfs_create_pending_block_groups+0x135/0x250 [btrfs]
[11319.763045]  ? btrfs_create_pending_block_groups+0x135/0x250 [btrfs]
[11319.763060]  __btrfs_end_transaction+0x8e/0x2e0 [btrfs]
[11319.763231]  btrfs_end_transaction+0x10/0x20 [btrfs]
[11319.763243]  find_free_extent+0xc05/0x1020 [btrfs]
[11319.763257]  btrfs_reserve_extent+0x9b/0x190 [btrfs]
[11319.763272]  cow_file_range.isra.67+0x13a/0x420 [btrfs]
[11319.763287]  run_delalloc_range+0x359/0x380 [btrfs]
[11319.763302]  ? find_lock_delalloc_range.constprop.56+0x1cf/0x1f0 [btrfs]
[11319.763317]  writepage_delalloc.isra.45+0xbc/0x170 [btrfs]
[11319.763332]  __extent_writepage+0x17c/0x320 [btrfs]
[11319.763348]  extent_write_cache_pages.constprop.53+0x1cd/0x460 [btrfs]
[11319.763364]  extent_writepages+0x5d/0x90 [btrfs]
[11319.763378]  ? btrfs_releasepage+0x20/0x20 [btrfs]
[11319.763392]  btrfs_writepages+0x28/0x30 [btrfs]
[11319.763396]  do_writepages+0x48/0xd0
[11319.763400]  ? exportfs_decode_fh+0x100/0x390
[11319.763404]  __filemap_fdatawrite_range+0xc1/0x100
[11319.763405]  ? __filemap_fdatawrite_range+0xc1/0x100
[11319.763408]  ? iter_div_u64_rem+0x20/0x20
[11319.763411]  filemap_fdatawrite_range+0x13/0x20
[11319.763425]  btrfs_fdatawrite_range+0x20/0x50 [btrfs]
[11319.763440]  start_ordered_ops+0x19/0x30 [btrfs]
[11319.763454]  btrfs_sync_file+0x76/0x420 [btrfs]
[11319.763457]  ? get_empty_filp+0xc9/0x1b0
[11319.763461]  vfs_fsync_range+0x4b/0xb0
[11319.763473]  nfsd_commit+0xb1/0xe0 [nfsd]
[11319.763481]  nfsd3_proc_commit+0x6e/0xd0 [nfsd]
[11319.763487]  nfsd_dispatch+0xfb/0x230 [nfsd]
[11319.763499]  svc_process_common+0x4a6/0x680 [sunrpc]
[11319.763507]  svc_process+0xec/0x1c0 [sunrpc]
[11319.763513]  nfsd+0xf4/0x160 [nfsd]
[11319.763516]  kthread+0x125/0x140
[11319.763522]  ? nfsd_destroy+0x70/0x70 [nfsd]
[11319.763524]  ? kthread_create_on_node+0x70/0x70
[11319.763528]  ret_from_fork+0x25/0x30
[11319.763530] Code: 4c 89 ff 45 31 c0 ba 10 00 00 00 4c 89 f6 e8 fa 21 ff ff 4c 89 ff e8 62 f3 fc ff e9 d3 fe ff ff 41 bd f4 ff ff ff e9 d0 fe ff ff <0f> ff eb b6 e8 d9 e3 c5 d0 66 0f 1f 84 00 00 00 00 00 66 66 66 
[11319.763568] ---[ end trace 40295351501208ff ]---

[11330.152285] ------------[ cut here ]------------
[11330.152319] WARNING: CPU: 0 PID: 203 at fs/btrfs/ctree.h:1559 btrfs_update_device+0x1be/0x1d0 [btrfs]
[11330.152320] Modules linked in: ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack libcrc32c iptable_filter tun coretemp kvm_intel iTCO_wdt iTCO_vendor_support i915 gpio_ich ppdev kvm video i2c_algo_bit drm_kms_helper snd_hda_codec_idt snd_hda_codec_generic irqbypass drm syscopyarea psmouse sysfillrect snd_hda_intel pcspkr i2c_i801 e1000e mei_me sysimgblt snd_hda_codec evdev fb_sys_fops input_leds mei lpc_ich snd_hda_core snd_hwdep snd_pcm snd_timer snd soundcore parport_pc parport mac_hid ptp pps_core shpchp winbond_cir rc_core intel_agp intel_gtt led_class agpgart tpm_tis tpm_tis_core tpm button acpi_cpufreq nfsd auth_rpcgss oid_registry nfs_acl lockd grace sunrpc sch_fq_codel ip_tables x_tables crc32c_generic btrfs xor raid6_pq hid_generic
[11330.152389]  sr_mod cdrom sd_mod usbhid hid serio_raw atkbd libps2 uhci_hcd firewire_ohci pata_it821x ahci libahci libata firewire_core scsi_mod crc_itu_t i8042 serio ehci_pci ehci_hcd usbcore usb_common
[11330.152409] CPU: 0 PID: 203 Comm: btrfs-cleaner Tainted: G        W       4.13.5-1-ARCH #1
[11330.152410] Hardware name:                  /DG33TL, BIOS DPP3510J.86A.0572.2009.0715.2346 07/15/2009
[11330.152411] task: ffff90dd221ec4c0 task.stack: ffff9e1fc13f4000
[11330.152427] RIP: 0010:btrfs_update_device+0x1be/0x1d0 [btrfs]
[11330.152428] RSP: 0018:ffff9e1fc13f7d28 EFLAGS: 00010206
[11330.152430] RAX: 0000000000000fff RBX: ffff90dd227d7c40 RCX: 000003a3816d1e00
[11330.152431] RDX: 0000000000000004 RSI: 0000000000007e98 RDI: ffff90dcf76e2578
[11330.152432] RBP: ffff9e1fc13f7d70 R08: 0000000000007e9c R09: ffff9e1fc13f7ce0
[11330.152434] R10: 0000000000001000 R11: 0000000000000007 R12: ffff90dd21f77c00
[11330.152435] R13: 0000000000000000 R14: 0000000000007e78 R15: ffff90dcf76e2578
[11330.152437] FS:  0000000000000000(0000) GS:ffff90dd2bc00000(0000) knlGS:0000000000000000
[11330.152438] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[11330.152440] CR2: 00007fec55264d30 CR3: 00000001703bf000 CR4: 00000000000006f0
[11330.152441] Call Trace:
[11330.152459]  btrfs_remove_chunk+0x365/0x890 [btrfs]
[11330.152474]  btrfs_delete_unused_bgs+0x30d/0x3b0 [btrfs]
[11330.152488]  cleaner_kthread+0x165/0x180 [btrfs]
[11330.152493]  kthread+0x125/0x140
[11330.152507]  ? __btree_submit_bio_start+0x20/0x20 [btrfs]
[11330.152513]  ? kthread_create_on_node+0x70/0x70
[11330.152516]  ret_from_fork+0x25/0x30
[11330.152518] Code: 4c 89 ff 45 31 c0 ba 10 00 00 00 4c 89 f6 e8 fa 21 ff ff 4c 89 ff e8 62 f3 fc ff e9 d3 fe ff ff 41 bd f4 ff ff ff e9 d0 fe ff ff <0f> ff eb b6 e8 d9 e3 c5 d0 66 0f 1f 84 00 00 00 00 00 66 66 66 
[11330.152556] ---[ end trace 4029535150120900 ]---

That first warning appeared 13 times in the logs, and the second one appeared only 
once.

I haven't rebooted the machine since observing these warnings.  Things seem to be 
working ok.  Please let me know if there's anything interesting to be learned from 
it.

Thanks!

Steve