[Bug 217030] New: [Syzkaller & bisect] There is "xfs_bmapi_convert_delalloc" WARNING in v6.2-rc7 kernel

[Bug 217030] New: [Syzkaller & bisect] There is "xfs_bmapi_convert_delalloc" WARNING in v6.2-rc7 kernel

[bugzilla-daemon]

https://bugzilla.kernel.org/show_bug.cgi?id=217030

            Bug ID: 217030
           Summary: [Syzkaller & bisect] There is
                    "xfs_bmapi_convert_delalloc" WARNING in v6.2-rc7
                    kernel
           Product: File System
           Version: 2.5
    Kernel Version: v6.2-rc7
          Hardware: All
                OS: Linux
              Tree: Mainline
            Status: NEW
          Severity: normal
          Priority: P1
         Component: XFS
          Assignee: filesystem_xfs@kernel-bugs.kernel.org
          Reporter: pengfei.xu@intel.com
        Regression: No

userspace arch: x86

There is "xfs_bmapi_convert_delalloc" WARNING in v6.2-rc7 kernel in guest:
[   31.180821] ------------[ cut here ]------------
[   31.181101] WARNING: CPU: 0 PID: 550 at fs/xfs/libxfs/xfs_bmap.c:4544
xfs_bmapi_convert_delalloc+0x793/0xf20
[   31.181692] Modules linked in:
[   31.181886] CPU: 0 PID: 550 Comm: repro Not tainted 6.2.0-rc7-4ec5183ec486
#1
[   31.182310] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014
[   31.182989] RIP: 0010:xfs_bmapi_convert_delalloc+0x793/0xf20
[   31.183342] Code: f9 ff ff e8 0f fd 08 ff 44 89 e6 bf 02 00 00 00 41 bf f5
ff ff ff e8 dc fe 08 ff 41 83 fc 02 0f 84 eb fe ff ff e8 ed fc 08 ff <0f> 0b e9
df 0
[   31.184391] RSP: 0018:ff1100000d03ef20 EFLAGS: 00010246
[   31.184703] RAX: 0000000000000000 RBX: ff1100001eb47800 RCX:
ffffffff82521274
[   31.185118] RDX: 0000000000000000 RSI: ff1100000efc8000 RDI:
0000000000000002
[   31.185531] RBP: ff1100000d03f120 R08: ff1100000d03f048 R09:
fffffbfff0eb4055
[   31.185946] R10: ffffffff875a02a7 R11: fffffbfff0eb4054 R12:
0000000000000000
[   31.186363] R13: ff1100000d03f0f8 R14: ff1100000e544000 R15:
00000000fffffff5
[   31.186774] FS:  00007fd840a14700(0000) GS:ff1100006ca00000(0000)
knlGS:0000000000000000
[   31.187306] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   31.187648] CR2: 00007f6e90b65000 CR3: 0000000013fa2004 CR4:
0000000000771ef0
[   31.188069] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[   31.188482] DR3: 0000000000000000 DR6: 00000000fffe07f0 DR7:
0000000000000400
[   31.188897] PKRU: 55555554
[   31.189069] Call Trace:
[   31.189222]  <TASK>
[   31.189370]  ? __pfx_xfs_bmapi_convert_delalloc+0x10/0x10
[   31.189707]  ? __pfx_rwsem_wake+0x10/0x10
[   31.189996]  ? write_comp_data+0x2f/0x90
[   31.190260]  xfs_map_blocks+0x562/0xe40
[   31.190527]  ? __pfx_xfs_map_blocks+0x10/0x10
[   31.190800]  ? __this_cpu_preempt_check+0x20/0x30
[   31.191113]  ? lock_is_held_type+0xe6/0x140
[   31.191371]  ? rcu_lockdep_current_cpu_online+0x4b/0x160
[   31.191710]  ? __sanitizer_cov_trace_pc+0x25/0x60
[   31.192012]  ? write_comp_data+0x2f/0x90
[   31.192270]  iomap_do_writepage+0xc6f/0x2ba0
[   31.192537]  ? write_comp_data+0x2f/0x90
[   31.192805]  ? __pfx_iomap_do_writepage+0x10/0x10
[   31.193093]  ? rcu_read_lock_sched_held+0xa9/0xd0
[   31.193389]  ? __pfx_rcu_read_lock_sched_held+0x10/0x10
[   31.193714]  ? write_comp_data+0x2f/0x90
[   31.193970]  write_cache_pages+0x573/0x12c0
[   31.194247]  ? __pfx_iomap_do_writepage+0x10/0x10
[   31.194543]  ? __pfx_write_cache_pages+0x10/0x10
[   31.194831]  ? __pfx_rcu_read_lock_sched_held+0x10/0x10
[   31.195173]  ? ncsi_channel_monitor.cold.17+0x204/0x3f7
[   31.195488]  ? lock_release+0x3f8/0x7d0
[   31.195729]  ? __this_cpu_preempt_check+0x20/0x30
[   31.196026]  ? xfs_vm_writepages+0x123/0x1c0
[   31.196298]  ? __pfx_lock_release+0x10/0x10
[   31.196561]  ? do_raw_spin_lock+0x132/0x2a0
[   31.196824]  ? __pfx_do_raw_spin_lock+0x10/0x10
[   31.197117]  ? __kasan_check_read+0x15/0x20
[   31.197381]  iomap_writepages+0x5b/0xc0
[   31.197626]  xfs_vm_writepages+0x13c/0x1c0
[   31.197885]  ? __pfx_xfs_vm_writepages+0x10/0x10
[   31.198189]  ? lock_release+0x3f8/0x7d0
[   31.198429]  ? __pfx_rcu_read_lock_sched_held+0x10/0x10
[   31.198752]  ? write_comp_data+0x2f/0x90
[   31.199021]  ? __pfx_xfs_vm_writepages+0x10/0x10
[   31.199310]  do_writepages+0x1c5/0x690
[   31.199550]  ? __pfx_do_writepages+0x10/0x10
[   31.199816]  ? do_raw_spin_unlock+0x154/0x230
[   31.200096]  ? __sanitizer_cov_trace_pc+0x25/0x60
[   31.200393]  ? wbc_attach_and_unlock_inode+0x585/0x8f0
[   31.200714]  filemap_fdatawrite_wbc+0x163/0x1d0
[   31.201005]  __filemap_fdatawrite_range+0xc9/0x100
[   31.201305]  ? __pfx___filemap_fdatawrite_range+0x10/0x10
[   31.201651]  ? write_comp_data+0x2f/0x90
[   31.201908]  filemap_write_and_wait_range.part.72+0x93/0x100
[   31.202264]  filemap_write_and_wait_range+0x48/0x60
[   31.202575]  __iomap_dio_rw+0x65e/0x1c80
[   31.202819]  ? __sanitizer_cov_trace_pc+0x25/0x60
[   31.203131]  ? timestamp_truncate+0x1ee/0x2f0
[   31.203424]  ? __pfx___iomap_dio_rw+0x10/0x10
[   31.203697]  ? write_comp_data+0x2f/0x90
[   31.203952]  ? __sanitizer_cov_trace_pc+0x25/0x60
[   31.204251]  ? write_comp_data+0x2f/0x90
[   31.204537]  iomap_dio_rw+0x4d/0xb0
[   31.204765]  xfs_file_dio_write_aligned+0x1e9/0x450
[   31.205077]  ? __pfx_xfs_file_dio_write_aligned+0x10/0x10
[   31.205412]  ? lock_is_held_type+0xe6/0x140
[   31.205676]  ? write_comp_data+0x2f/0x90
[   31.205932]  xfs_file_write_iter+0x530/0x750
[   31.206208]  ? __sanitizer_cov_trace_pc+0x25/0x60
[   31.206513]  vfs_write+0xa65/0xe60
[   31.206736]  ? __pfx_vfs_write+0x10/0x10
[   31.206999]  ? __fget_files+0x270/0x400
[   31.207259]  ? write_comp_data+0x2f/0x90
[   31.207515]  ksys_write+0x143/0x280
[   31.207742]  ? __pfx_ksys_write+0x10/0x10
[   31.208013]  __x64_sys_write+0x7c/0xc0
[   31.208248]  ? syscall_enter_from_user_mode+0x51/0x60
[   31.208561]  do_syscall_64+0x3b/0x90
[   31.208791]  entry_SYSCALL_64_after_hwframe+0x72/0xdc
[   31.209103] RIP: 0033:0x7fd846f5b59d
[   31.209324] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89
f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01
f0 8
[   31.210373] RSP: 002b:00007fd840a13e98 EFLAGS: 00000246 ORIG_RAX:
0000000000000001
[   31.210814] RAX: ffffffffffffffda RBX: 0000000000000000 RCX:
00007fd846f5b59d
[   31.211248] RDX: 0000000000001400 RSI: 0000000020000000 RDI:
0000000000000005
[   31.211663] RBP: 00007fd840a13ec0 R08: 0000000000000005 R09:
0000000000000000
[   31.212077] R10: 0000000000000000 R11: 0000000000000246 R12:
00007ffc9b897cce
[   31.212491] R13: 00007ffc9b897ccf R14: 00007ffc9b897d60 R15:
00007fd840a14700
[   31.212929]  </TASK>
[   31.213072] irq event stamp: 995
[   31.213269] hardirqs last  enabled at (1003): [<ffffffff813dd0a1>]
__up_console_sem+0x91/0xb0
[   31.213769] hardirqs last disabled at (1010): [<ffffffff813dd086>]
__up_console_sem+0x76/0xb0
[   31.214272] softirqs last  enabled at (286): [<ffffffff8536af3f>]
__do_softirq+0x53f/0x836
[   31.214754] softirqs last disabled at (211): [<ffffffff812498b0>]
irq_exit_rcu+0x100/0x140
[   31.215258] ---[ end trace 0000000000000000 ]---

Bisected and found the first bad commit is:
7348b322332d8602a4133f0b861334ea021b134a
xfs: xfs_bmap_punch_delalloc_range() should take a byte range

After reverted above commit on top of v6.2-rc7 kernel, this issue was gone.

Reproduced code from syzkaller, kconfig, v6.2-rc7 kernel reproduced dmesg are
in attached.

More detailed bisect info is in link:
https://github.com/xupengfe/syzkaller_logs/tree/main/230207_175127_xfs_bmapi_convert_delalloc

And previous syzbot seems repored the similar issue in email name:
"[syzbot] [xfs?] WARNING in xfs_bmapi_convert_delalloc"
And I just updated the above bisected info for this issue.

I hope it's helpful.

---
If you need the reproduced virtual machine environment:

git clone https://gitlab.com/xupengfe/repro_vm_env.git
cd repro_vm_env
tar -xvf repro_vm_env.tar.gz
cd repro_vm_env; ./start3.sh  // it needs qemu-system-x86_64 and I used v7.1.0
   // start3.sh will load bzImage_2241ab53cbb5cdb08a6b2d4688feb13971058f65
v6.2-rc5 kernel
   // You could change the bzImage_xxx as you want In vm and login with root, 
there is no password for root.

After login vm successfully, you could transfer reproduced binary to the VM by
below way, and reproduce the problem:
gcc -pthread -o repro repro.c
scp -P 10023 repro root@localhost:/root/

Get the bzImage for target kernel:
Please use attached kconfig and copy it to kernel_src/.config make olddefconfig
make -jx bzImage           //x should equal or less than cpu num your pc has

Fill the bzImage file into above start3.sh to load the target kernel vm.


Tips:
If you already have qemu-system-x86_64, please ignore below info.
If you want to install qemu v7.1.0 version:
git clone https://github.com/qemu/qemu.git cd qemu git checkout -f v7.1.0 mkdir
build cd build yum install -y ninja-build.x86_64 ../configure
--target-list=x86_64-softmmu --enable-kvm --enable-vnc --enable-gtk
--enable-sdl make make install

---
Thanks!

-- 
You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

Re: [Bug 217030] New: [Syzkaller & bisect] There is "xfs_bmapi_convert_delalloc" WARNING in v6.2-rc7 kernel

[Dave Chinner]

On Mon, Feb 13, 2023 at 10:57:31AM +0000, bugzilla-daemon@kernel.org wrote:
> Bisected and found the first bad commit is:
> 7348b322332d8602a4133f0b861334ea021b134a
> xfs: xfs_bmap_punch_delalloc_range() should take a byte range

I don't see how that commit makes any material difference to the
code; the ranges being punched are the same, just being passed in
different units.

The test filesystem image has a 1kB block size, and it has a bad CRC
in the root bnobt block, hence any attempt to allocate fails
immediately with a corrupt root btree block. The first write done
by the reproducer is an O_SYNC write, so it writes 0x1400 bytes into
the page cache (5 1kB blocks) and then internally the write() runs
fsync() which then fails to allocate the blocks in the writeback
path.

This writeback failure then calls ->discard_page() on the write range,
which punches out the delalloc block underneath the failed write.

At the same time, the other thread is doing a direct IO write, and
it sees there are dirty page cache pages over the page cache and it
attempts to writeback the page. It calls into ->map_blocks which
then sees a delalloc extent and tries to convert it. By the time
writeback has locked the folio, locked the ILOCK and runs the
delalloc extent conversion, the delalloc extent has been punched,
and it fails to find the delalloc extent to convert. It then issues
the WARN_ON() reported in this bug report.

I don't think this a failure that is a result of the commit that the
bisect identified - I think the race condition has been there for a
lot longer, and for some reason we've perturbed the code enough
to now expose the race condition occasionally. i.e. the
->discard_folio path is not invalidating the folio or marking it
with an error when we punch the backing store from under it, so it's
remaining dirty in the page cache but without any backing store for
writeback.

Hence I suspect the problem here is that we aren't calling
folio_set_error() on folios that we fail the first delalloc block
conversion on (i.e. count is zero) so this isn't operating like an
IO error. i.e. page_endio() calls folio_set_error() when a
writeback IO fails, and we are not doing that when we call
->discard_folio so the folio remains dirty and uptodate.  Hence
after a failed writeback due to allocation failure, we have the
situation where a dirty page has no backing store, and it seems a
future writeback can trip over that state.

Hence I suspect this commit first exposed the issue being reported
here:

commit e9c3a8e820ed0eeb2be05072f29f80d1b79f053b
Author: Darrick J. Wong <djwong@kernel.org>
Date:   Mon May 16 15:27:38 2022 -0700

    iomap: don't invalidate folios after writeback errors
    
    XFS has the unique behavior (as compared to the other Linux filesystems)
    that on writeback errors it will completely invalidate the affected
    folio and force the page cache to reread the contents from disk.  All
    other filesystems leave the page mapped and up to date.
    
    This is a rude awakening for user programs, since (in the case where
    write fails but reread doesn't) file contents will appear to revert to
    old disk contents with no notification other than an EIO on fsync.  This
    might have been annoying back in the days when iomap dealt with one page
    at a time, but with multipage folios, we can now throw away *megabytes*
    worth of data for a single write error.
    
    On *most* Linux filesystems, a program can respond to an EIO on write by
    redirtying the entire file and scheduling it for writeback.  This isn't
    foolproof, since the page that failed writeback is no longer dirty and
    could be evicted, but programs that want to recover properly *also*
    have to detect XFS and regenerate every write they've made to the file.
    
    When running xfs/314 on arm64, I noticed a UAF when xfs_discard_folio
    invalidates multipage folios that could be undergoing writeback.  If,
    say, we have a 256K folio caching a mix of written and unwritten
    extents, it's possible that we could start writeback of the first (say)
    64K of the folio and then hit a writeback error on the next 64K.  We
    then free the iop attached to the folio, which is really bad because
    writeback completion on the first 64k will trip over the "blocks per
    folio > 1 && !iop" assertion.
    
    This can't be fixed by only invalidating the folio if writeback fails at
    the start of the folio, since the folio is marked !uptodate, which trips
    other assertions elsewhere.  Get rid of the whole behavior entirely.
    
    Signed-off-by: Darrick J. Wong <djwong@kernel.org>
    Reviewed-by: Matthew Wilcox (Oracle) <willy@infradead.org>
    Reviewed-by: Jeff Layton <jlayton@kernel.org>
    Reviewed-by: Christoph Hellwig <hch@lst.de>

diff --git a/fs/iomap/buffered-io.c b/fs/iomap/buffered-io.c
index 8fb9b2797fc5..94b53cbdefad 100644
--- a/fs/iomap/buffered-io.c
+++ b/fs/iomap/buffered-io.c
@@ -1387,7 +1387,6 @@ iomap_writepage_map(struct iomap_writepage_ctx *wpc,
                if (wpc->ops->discard_folio)
                        wpc->ops->discard_folio(folio, pos);
                if (!count) {
-                       folio_clear_uptodate(folio);
                        folio_unlock(folio);
                        goto done;
                }

This commit removed the invalidation of the folio after discarding
it's backing store via ->discard_folio, hence allowing writeback of
dirty folios that have no storage reservation or delalloc extent
backing the dirty folio.

This, to me, looks like the underlying problem here. If we are not
invalidating the cached data on writeback allocation failure, we must
not punch out the storage reservation backing the dirty cached data
as we are going to retry the write at some point in the future and
hence still need the storage reservation for the dirty folio....

..... and removing ->discard_folio() then results in delalloc
extents that cannot be converted by writeback and so when we go to
reclaim the inode during cache eviction we now have delalloc extents
on the inode and that trips assert failures because writeback is
it assumes that writeback will always resolve delalloc extents
either by conversion or discarding them.

Ok, the simple solution trips over other assumptions.  More
investigation required....

-Dave.
-- 
Dave Chinner
david@fromorbit.com

[Bug 217030] [Syzkaller & bisect] There is "xfs_bmapi_convert_delalloc" WARNING in v6.2-rc7 kernel

[bugzilla-daemon]

https://bugzilla.kernel.org/show_bug.cgi?id=217030

--- Comment #1 from Dave Chinner (david@fromorbit.com) ---
On Mon, Feb 13, 2023 at 10:57:31AM +0000, bugzilla-daemon@kernel.org wrote:
> Bisected and found the first bad commit is:
> 7348b322332d8602a4133f0b861334ea021b134a
> xfs: xfs_bmap_punch_delalloc_range() should take a byte range

I don't see how that commit makes any material difference to the
code; the ranges being punched are the same, just being passed in
different units.

The test filesystem image has a 1kB block size, and it has a bad CRC
in the root bnobt block, hence any attempt to allocate fails
immediately with a corrupt root btree block. The first write done
by the reproducer is an O_SYNC write, so it writes 0x1400 bytes into
the page cache (5 1kB blocks) and then internally the write() runs
fsync() which then fails to allocate the blocks in the writeback
path.

This writeback failure then calls ->discard_page() on the write range,
which punches out the delalloc block underneath the failed write.

At the same time, the other thread is doing a direct IO write, and
it sees there are dirty page cache pages over the page cache and it
attempts to writeback the page. It calls into ->map_blocks which
then sees a delalloc extent and tries to convert it. By the time
writeback has locked the folio, locked the ILOCK and runs the
delalloc extent conversion, the delalloc extent has been punched,
and it fails to find the delalloc extent to convert. It then issues
the WARN_ON() reported in this bug report.

I don't think this a failure that is a result of the commit that the
bisect identified - I think the race condition has been there for a
lot longer, and for some reason we've perturbed the code enough
to now expose the race condition occasionally. i.e. the
->discard_folio path is not invalidating the folio or marking it
with an error when we punch the backing store from under it, so it's
remaining dirty in the page cache but without any backing store for
writeback.

Hence I suspect the problem here is that we aren't calling
folio_set_error() on folios that we fail the first delalloc block
conversion on (i.e. count is zero) so this isn't operating like an
IO error. i.e. page_endio() calls folio_set_error() when a
writeback IO fails, and we are not doing that when we call
->discard_folio so the folio remains dirty and uptodate.  Hence
after a failed writeback due to allocation failure, we have the
situation where a dirty page has no backing store, and it seems a
future writeback can trip over that state.

Hence I suspect this commit first exposed the issue being reported
here:

commit e9c3a8e820ed0eeb2be05072f29f80d1b79f053b
Author: Darrick J. Wong <djwong@kernel.org>
Date:   Mon May 16 15:27:38 2022 -0700

    iomap: don't invalidate folios after writeback errors

    XFS has the unique behavior (as compared to the other Linux filesystems)
    that on writeback errors it will completely invalidate the affected
    folio and force the page cache to reread the contents from disk.  All
    other filesystems leave the page mapped and up to date.

    This is a rude awakening for user programs, since (in the case where
    write fails but reread doesn't) file contents will appear to revert to
    old disk contents with no notification other than an EIO on fsync.  This
    might have been annoying back in the days when iomap dealt with one page
    at a time, but with multipage folios, we can now throw away *megabytes*
    worth of data for a single write error.

    On *most* Linux filesystems, a program can respond to an EIO on write by
    redirtying the entire file and scheduling it for writeback.  This isn't
    foolproof, since the page that failed writeback is no longer dirty and
    could be evicted, but programs that want to recover properly *also*
    have to detect XFS and regenerate every write they've made to the file.

    When running xfs/314 on arm64, I noticed a UAF when xfs_discard_folio
    invalidates multipage folios that could be undergoing writeback.  If,
    say, we have a 256K folio caching a mix of written and unwritten
    extents, it's possible that we could start writeback of the first (say)
    64K of the folio and then hit a writeback error on the next 64K.  We
    then free the iop attached to the folio, which is really bad because
    writeback completion on the first 64k will trip over the "blocks per
    folio > 1 && !iop" assertion.

    This can't be fixed by only invalidating the folio if writeback fails at
    the start of the folio, since the folio is marked !uptodate, which trips
    other assertions elsewhere.  Get rid of the whole behavior entirely.

    Signed-off-by: Darrick J. Wong <djwong@kernel.org>
    Reviewed-by: Matthew Wilcox (Oracle) <willy@infradead.org>
    Reviewed-by: Jeff Layton <jlayton@kernel.org>
    Reviewed-by: Christoph Hellwig <hch@lst.de>

diff --git a/fs/iomap/buffered-io.c b/fs/iomap/buffered-io.c
index 8fb9b2797fc5..94b53cbdefad 100644
--- a/fs/iomap/buffered-io.c
+++ b/fs/iomap/buffered-io.c
@@ -1387,7 +1387,6 @@ iomap_writepage_map(struct iomap_writepage_ctx *wpc,
                if (wpc->ops->discard_folio)
                        wpc->ops->discard_folio(folio, pos);
                if (!count) {
-                       folio_clear_uptodate(folio);
                        folio_unlock(folio);
                        goto done;
                }

This commit removed the invalidation of the folio after discarding
it's backing store via ->discard_folio, hence allowing writeback of
dirty folios that have no storage reservation or delalloc extent
backing the dirty folio.

This, to me, looks like the underlying problem here. If we are not
invalidating the cached data on writeback allocation failure, we must
not punch out the storage reservation backing the dirty cached data
as we are going to retry the write at some point in the future and
hence still need the storage reservation for the dirty folio....

..... and removing ->discard_folio() then results in delalloc
extents that cannot be converted by writeback and so when we go to
reclaim the inode during cache eviction we now have delalloc extents
on the inode and that trips assert failures because writeback is
it assumes that writeback will always resolve delalloc extents
either by conversion or discarding them.

Ok, the simple solution trips over other assumptions.  More
investigation required....

-Dave.

-- 
You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.

[Bug 217030] [Syzkaller & bisect] There is "xfs_bmapi_convert_delalloc" WARNING in v6.2-rc7 kernel

[bugzilla-daemon]

https://bugzilla.kernel.org/show_bug.cgi?id=217030

--- Comment #2 from xupengfe (pengfei.xu@intel.com) ---
Hi Dave,

Thanks a lot for your comments!
I just used bisect scripts to find the above commit. And I reverted the commit
and the issue was gone.

Maybe it's not accurate for the root cause.

Your comments could give more clue for the problem solving.

Thanks!

-- 
You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.