XFS: Assertion failed: del->br_blockcount > 0, file: fs/xfs/libxfs/xfs_bmap.c, line: 5124

XFS: Assertion failed: del->br_blockcount > 0, file: fs/xfs/libxfs/xfs_bmap.c, line: 5124

[Ross Zwisler]

I'm able to consistently hit the following XFS assertion with v4.9-rc8 and
xfstest xfs/118 (log is passed through kasan_symbolize.py):

  run fstests xfs/118 at 2016-12-09 14:36:28
  XFS (ram0): Unmounting Filesystem
  XFS (ram0): Mounting V5 Filesystem
  XFS (ram0): Ending clean mount
  XFS: Assertion failed: del->br_blockcount > 0, file: fs/xfs/libxfs/xfs_bmap.c, line: 5124
  ------------[ cut here ]------------
  kernel BUG at fs/xfs/xfs_message.c:113!
  invalid opcode: 0000 [#1] SMP
  Modules linked in: brd nd_pmem dax_pmem nd_btt dax nd_e820 libnvdimm
  CPU: 6 PID: 3146 Comm: xfs_fsr Not tainted 4.9.0-rc8 #2
  Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.1-1.fc24 04/01/2014
  task: ffff8800b2eb8000 task.stack: ffffc9000aa3c000
  RIP: 0010:[<ffffffff8150c720>]  [<ffffffff8150c720>] assfail+0x20/0x30
  RSP: 0018:ffffc9000aa3f960  EFLAGS: 00010246
  RAX: 0000000000000000 RBX: ffffc9000aa3fb28 RCX: 0000000000000000
  RDX: 00000000ffffffc0 RSI: 000000000000000a RDI: ffffffff81ec034a
  RBP: ffffc9000aa3f960 R08: 0000000000000000 R09: 0000000000000000
  R10: 000000000000000a R11: f000000000000000 R12: ffff8800b437e1c8
  R13: ffff8800b437e180 R14: 0000000000000000 R15: ffff8800b437e180
  FS:  00007f83b9d57700(0000) GS:ffff880515400000(0000) knlGS:0000000000000000
  CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
  CR2: 00007f83b9d35008 CR3: 00000000b2c20000 CR4: 00000000001406e0
  Stack:
   ffffc9000aa3faa0 ffffffff8149aec4 ffffc9000aa3f980 ffffffff81036a69
   ffffc9000aa3f9a0 ffffc9000aa3fa00 ffff880512ade100 0000000000000000
   ffffc9000aa3fc50 ffffc9000aa3fa1c ffff8800b437e1c8 ffff8800b437e1e8
  Call Trace:
   [<ffffffff8149aec4>] xfs_bmap_del_extent+0x104/0x19d0 fs/xfs/libxfs/xfs_bmap.c:5124
   [<ffffffff8149d028>] __xfs_bunmapi+0x898/0x1290 fs/xfs/libxfs/xfs_bmap.c:5726
   [<ffffffff8149da4b>] xfs_bunmapi+0x2b/0x40 fs/xfs/libxfs/xfs_bmap.c:5827
   [<ffffffff8150656e>] xfs_itruncate_extents+0x27e/0x5f0 fs/xfs/xfs_inode.c:1603
   [<ffffffff81506b01>] xfs_inactive_truncate+0xd1/0x130 fs/xfs/xfs_inode.c:1768
   [<ffffffff815087c4>] xfs_inactive+0x1c4/0x240 fs/xfs/xfs_inode.c:1933
   [<ffffffff81513d48>] xfs_fs_destroy_inode+0xd8/0x2e0 fs/xfs/xfs_super.c:958
   [<ffffffff812b872b>] destroy_inode+0x3b/0x60 fs/inode.c:264
   [<ffffffff812b8875>] evict+0x125/0x180 fs/inode.c:570
   [<     inline     >] iput_final fs/inode.c:1515
   [<ffffffff812b8b37>] iput+0x207/0x2d0 fs/inode.c:1542
   [<ffffffff812b0cc3>] dentry_unlink_inode+0xc3/0x160 fs/dcache.c:343
   [<ffffffff812b1ad6>] __dentry_kill+0xb6/0x160 fs/dcache.c:538
   [<     inline     >] dentry_kill fs/dcache.c:579
   [<ffffffff812b3a7e>] dput+0x2be/0x3e0 fs/dcache.c:791
   [<ffffffff81299a0e>] __fput+0x17e/0x1f0 fs/file_table.c:226
   [<ffffffff81299abe>] ____fput+0xe/0x10 fs/file_table.c:244
   [<ffffffff810d47d0>] task_work_run+0x80/0xa0 kernel/task_work.c:116
   [<     inline     >] tracehook_notify_resume ./include/linux/tracehook.h:191
   [<ffffffff81003315>] exit_to_usermode_loop+0xa5/0xb0 arch/x86/entry/common.c:160
   [<     inline     >] prepare_exit_to_usermode arch/x86/entry/common.c:190
   [<ffffffff81003dc9>] syscall_return_slowpath+0xc9/0x140 arch/x86/entry/common.c:259
   [<ffffffff81b40e22>] entry_SYSCALL_64_fastpath+0xc0/0xc2 arch/x86/entry/entry_64.S:244
  Code: 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55 48 89 f1 41 89 d0 48 c7 c6 c0 91 f0 81 48 89 fa 31 ff 48 89 e5 e8 b0 f8 ff ff <0f> 0b 0f 1f 40 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00
  RIP  [<ffffffff8150c720>] assfail+0x20/0x30 fs/xfs/xfs_message.c:111
   RSP <ffffc9000aa3f960>
  ---[ end trace aa1781e3c0104dbc ]---
  XFS (ram1): Unmounting Filesystem
  systemd-journald[625]: Sent WATCHDOG=1 notification.

Here's the xfstest output, in case that's helpful:

  # ./check xfs/118
  FSTYP         -- xfs (debug)
  PLATFORM      -- Linux/x86_64 lorwyn 4.9.0-rc8
  MKFS_OPTIONS  -- -f -bsize=4096 /dev/ram0
  MOUNT_OPTIONS -- -o context=system_u:object_r:nfs_t:s0 /dev/ram0 /mnt/xfstests_scratch
  
  xfs/118	 - output mismatch (see /root/xfstests/results//xfs/118.out.bad)
      --- tests/xfs/118.out	2016-12-09 14:25:26.996375536 -0700
      +++ /root/xfstests/results//xfs/118.out.bad	2016-12-09 14:36:30.364407590 -0700
      @@ -1,2 +1,3 @@
       QA output created by 118
       Silence is golden
      +./tests/xfs/118: line 95:  3146 Segmentation fault      $XFS_FSR_PROG -vd $SCRATCH_MNT/newfile* >> $seqres.full 2>&1
      ...
      (Run 'diff -u tests/xfs/118.out /root/xfstests/results//xfs/118.out.bad'  to see the entire diff)
  umount: /mnt/xfstests_scratch: target is busy
          (In some cases useful info about processes that
           use the device is found by lsof(8) or fuser(1).)
  _check_xfs_filesystem: filesystem on /dev/ram0 has dirty log (see /root/xfstests/results//xfs/118.full)
  _check_xfs_filesystem: filesystem on /dev/ram0 is inconsistent (c) (see /root/xfstests/results//xfs/118.full)
  _check_xfs_filesystem: filesystem on /dev/ram0 is inconsistent (r) (see /root/xfstests/results//xfs/118.full)
  _check_dmesg: something found in dmesg (see /root/xfstests/results//xfs/118.dmesg)
  Ran: xfs/118
  Failures: xfs/118
  Failed 1 of 1 tests

I initially hit this with a pair of PMEM partitions, but was able to reproduce
it with two 2 GiB BRD ramdisks as my TEST_DEV and SCRATCH_DEV. 

I'm running with xfsprogs v4.8.0 and the following xfstest commit:
	adcc60c  build: allow building with latest xfslibs on 32-bit Linux

Kernel v4.8 is also able to his this same issue.

Thanks,
- Ross

Re: XFS: Assertion failed: del->br_blockcount > 0, file: fs/xfs/libxfs/xfs_bmap.c, line: 5124

[Dave Chinner]

On Fri, Dec 09, 2016 at 03:42:14PM -0700, Ross Zwisler wrote:
> I'm able to consistently hit the following XFS assertion with v4.9-rc8 and
> xfstest xfs/118 (log is passed through kasan_symbolize.py):

commit 4dfce57db635 ("xfs: fix up xfs_swap_extent_forks inline
extent handling") in the XFS for-next tree.

Ross - when you get a failure in a brand new test in xfstests
(xfs/118 was merged about a month ago), it's worth checking whether
the problem is already fixed in the XFS for-next tree. In general,
the regression tests exercising such bugs aren't merged until the
fix has been committed...

> Kernel v4.8 is also able to his this same issue.

Yes. The above commit is marked for stable, so it will be appearing
in all those older kernels in the next few weeks...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: XFS: Assertion failed: del->br_blockcount > 0, file: fs/xfs/libxfs/xfs_bmap.c, line: 5124

[Ross Zwisler]

On Sun, Dec 11, 2016 at 7:52 PM, Dave Chinner <david@fromorbit.com> wrote:
> On Fri, Dec 09, 2016 at 03:42:14PM -0700, Ross Zwisler wrote:
>> I'm able to consistently hit the following XFS assertion with v4.9-rc8 and
>> xfstest xfs/118 (log is passed through kasan_symbolize.py):
>
> commit 4dfce57db635 ("xfs: fix up xfs_swap_extent_forks inline
> extent handling") in the XFS for-next tree.
>
> Ross - when you get a failure in a brand new test in xfstests
> (xfs/118 was merged about a month ago), it's worth checking whether
> the problem is already fixed in the XFS for-next tree. In general,
> the regression tests exercising such bugs aren't merged until the
> fix has been committed...

Ah, thanks Dave.  This make sense, and I'll be sure to do this from now on.

- Ross