WARNING in mark_buffer_dirty

WARNING in mark_buffer_dirty

[cheung wall]

Hello,


when using Healer to fuzz the latest Linux Kernel, the following crash

was triggered on:


HEAD commit: 0dd3ee31125508cd67f7e7172247f05b7fd1753a  (tag: v6.7)

git tree: upstream

console output: https://pastebin.com/raw/DnYhuiCu

kernel config: https://pastebin.com/raw/VecrLrRN

C reproducer: https://pastebin.com/raw/3tXH4hvU

Syzlang reproducer: https://pastebin.com/raw/Jxcujpb3


If you fix this issue, please add the following tag to the commit:

Reported-by: Qiang Zhang <zzqq0103.hey@gmail.com>

----------------------------------------------------------

WARNING: CPU: 0 PID: 2920 at fs/buffer.c:1176
mark_buffer_dirty+0x232/0x290
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/fs/buffer.c:1176
Modules linked in:
CPU: 0 PID: 2920 Comm: syz-executor247 Not tainted 6.7.0 #2
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.15.0-1 04/01/2014
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
RIP: 0010:mark_buffer_dirty+0x232/0x290
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/fs/buffer.c:1176
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
Code: 00 00 00 00 00 fc ff df 48 c1 ea 03 80 3c 02 00 75 69 48 8b 3b
be 04 00 00 00 e8 29 5f fd ff e9 8e fe ff ff e8 bf 5d c3 ff 90 <0f> 0b
90 e9 ea fd ff ff 48 89 df e8 de b6 ef ff e9 14 fe ff ff 48
RSP: 0018:ffff88800918f9f0 EFLAGS: 00010293
RAX: 0000000000000000 RBX: ffff88800e9897e0 RCX: ffffffffabfb13b1
RDX: ffff88800c44e600 RSI: 0000000000000008 RDI: ffff88800e9897e0
RBP: 0000000000000200 R08: 0000000000000000 R09: ffffed1001d312fc
R10: ffff88800e9897e7 R11: 0000000000000000 R12: dffffc0000000000
R13: 0000000000000000 R14: ffff88800e9897e0 R15: 0000000000000200
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
FS:  00005555557ca480(0000) GS:ffff8880a4200000(0000) knlGS:0000000000000000
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000020400000 CR3: 0000000006c94005 CR4: 0000000000770ef0
PKRU: 55555554
Call Trace:
 <TASK>
 __block_commit_write+0xe9/0x200
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/fs/buffer.c:2191
 block_write_end+0xb1/0x1f0
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/fs/buffer.c:2267
 iomap_write_end+0x461/0x8c0
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/fs/iomap/buffered-io.c:857
 iomap_write_iter
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/fs/iomap/buffered-io.c:938
[inline]
 iomap_file_buffered_write+0x4eb/0x800
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/fs/iomap/buffered-io.c:987
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
 blkdev_buffered_write
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/block/fops.c:646
[inline]
 blkdev_write_iter+0x4ae/0xa40
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/block/fops.c:696
 call_write_iter
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/./include/linux/fs.h:2020
[inline]
 new_sync_write
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/fs/read_write.c:491
[inline]
 vfs_write+0x835/0xb30
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/fs/read_write.c:584
 ksys_write+0x104/0x210
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/fs/read_write.c:637
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
sr 1:0:0:0: [sr0] tag#0 unaligned transfer
 do_syscall_x64
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/arch/x86/entry/common.c:52
[inline]
 do_syscall_64+0x46/0xf0
root/zhangqiang/kernel_fuzzing/zq-LLM-OS/llm-syz-environment/linux-6.7/arch/x86/entry/common.c:83
 entry_SYSCALL_64_after_hwframe+0x6f/0x77
RIP: 0033:0x7f9c88c542fd
Code: c3 e8 b7 24 00 00 0f 1f 80 00 00 00 00 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 ff ff 73 01 c3 48 c7 c1 b8 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007ffd984ca008 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 00000000000bc285 RCX: 00007f9c88c542fd
RDX: 00000000fffffec2 RSI: 0000000020000040 RDI: 0000000000000003
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffd984ca04c
R13: 00007ffd984ca070 R14: 0000000000000370 R15: 00007f9c88ca5025
 </TASK>

Re: WARNING in mark_buffer_dirty

[Matthew Wilcox]

This might be an iomap bug, so adding Christoph & Darrick.

On Sat, Mar 16, 2024 at 12:29:36PM +0800, cheung wall wrote:
> HEAD commit: 0dd3ee31125508cd67f7e7172247f05b7fd1753a  (tag: v6.7)
> WARNING: CPU: 0 PID: 2920 at fs/buffer.c:1176
> mark_buffer_dirty+0x232/0x290

This is WARN_ON_ONCE(!buffer_uptodate(bh)), so we're trying to mark a
buffer dirty when that buffer is not uptodate.

> RIP: 0010:mark_buffer_dirty+0x232/0x290
> fs/buffer.c:1176
> Call Trace:
>  <TASK>
>  __block_commit_write+0xe9/0x200
> fs/buffer.c:2191

... but line 2190 and 91 are:

                        set_buffer_uptodate(bh);
                        mark_buffer_dirty(bh);

and the folio is locked.  So how do we clear the uptodate flag on the
buffer without the folio locked?

>  block_write_end+0xb1/0x1f0
> fs/buffer.c:2267
>  iomap_write_end+0x461/0x8c0
> fs/iomap/buffered-io.c:857
>  iomap_write_iter
> fs/iomap/buffered-io.c:938
> [inline]
>  iomap_file_buffered_write+0x4eb/0x800
> fs/iomap/buffered-io.c:987
>  blkdev_buffered_write
> block/fops.c:646
> [inline]
>  blkdev_write_iter+0x4ae/0xa40
> block/fops.c:696
>  call_write_iter

Re: WARNING in mark_buffer_dirty

[Jan Kara]

On Sat 16-03-24 04:54:10, Matthew Wilcox wrote:
> 
> This might be an iomap bug, so adding Christoph & Darrick.
> 
> On Sat, Mar 16, 2024 at 12:29:36PM +0800, cheung wall wrote:
> > HEAD commit: 0dd3ee31125508cd67f7e7172247f05b7fd1753a  (tag: v6.7)
> > WARNING: CPU: 0 PID: 2920 at fs/buffer.c:1176
> > mark_buffer_dirty+0x232/0x290
> 
> This is WARN_ON_ONCE(!buffer_uptodate(bh)), so we're trying to mark a
> buffer dirty when that buffer is not uptodate.
> 
> > RIP: 0010:mark_buffer_dirty+0x232/0x290
> > fs/buffer.c:1176
> > Call Trace:
> >  <TASK>
> >  __block_commit_write+0xe9/0x200
> > fs/buffer.c:2191
> 
> ... but line 2190 and 91 are:
> 
>                         set_buffer_uptodate(bh);
>                         mark_buffer_dirty(bh);
> 
> and the folio is locked.  So how do we clear the uptodate flag on the
> buffer without the folio locked?

Given this happens on block device page cache, I can imagine there's
someone operating on the cache directly using buffer heads without locking
the page. Filesystems do this all the time. I don't see the reproducer doing
anything like that but who knows...

								Honza

> >  block_write_end+0xb1/0x1f0
> > fs/buffer.c:2267
> >  iomap_write_end+0x461/0x8c0
> > fs/iomap/buffered-io.c:857
> >  iomap_write_iter
> > fs/iomap/buffered-io.c:938
> > [inline]
> >  iomap_file_buffered_write+0x4eb/0x800
> > fs/iomap/buffered-io.c:987
> >  blkdev_buffered_write
> > block/fops.c:646
> > [inline]
> >  blkdev_write_iter+0x4ae/0xa40
> > block/fops.c:696
> >  call_write_iter
> 
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: WARNING in mark_buffer_dirty

[Eric Biggers]

On Wed, Nov 15, 2017 at 11:46:00PM -0800, syzbot wrote:
> WARNING: CPU: 3 PID: 13366 at fs/buffer.c:1108
> mark_buffer_dirty+0x48b/0x5d0 fs/buffer.c:1108
> Kernel panic - not syncing: panic_on_warn set ...
> 
> hub 1-0:1.0: activate --> -22
> CPU: 3 PID: 13366 Comm: syzkaller183798 Not tainted
> 4.14.0-rc8-next-20171109+ #11
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
> Call Trace:
>  __dump_stack lib/dump_stack.c:17 [inline]
>  dump_stack+0x194/0x257 lib/dump_stack.c:53
>  panic+0x1e4/0x41c kernel/panic.c:183
>  __warn+0x1c4/0x1e0 kernel/panic.c:546
>  report_bug+0x211/0x2d0 lib/bug.c:184
>  fixup_bug+0x40/0x90 arch/x86/kernel/traps.c:176
>  do_trap_no_signal arch/x86/kernel/traps.c:210 [inline]
>  do_trap+0x260/0x390 arch/x86/kernel/traps.c:259
>  do_error_trap+0x120/0x390 arch/x86/kernel/traps.c:296
> hub 1-0:1.0: activate --> -22
>  do_invalid_op+0x1b/0x20 arch/x86/kernel/traps.c:309
>  invalid_op+0x18/0x20 arch/x86/entry/entry_64.S:926
> RIP: 0010:mark_buffer_dirty+0x48b/0x5d0 fs/buffer.c:1108
> RSP: 0018:ffff88007ab27188 EFLAGS: 00010293
> RAX: ffff880079fa6500 RBX: ffff88007a727d20 RCX: ffffffff81bbfe5b
> RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff88007a727d20
> RBP: ffff88007ab27298 R08: 0000000000000200 R09: ffffea0001e53580
> R10: 0000000000000040 R11: ffffed000f29ac3f R12: 1ffff1000f564e32
> R13: dffffc0000000000 R14: ffff88007ab27270 R15: 0000000000000000
> hub 1-0:1.0: activate --> -22
>  __block_commit_write.isra.32+0x13b/0x2f0 fs/buffer.c:2060
>  block_write_end+0x99/0x1c0 fs/buffer.c:2138
>  blkdev_write_end+0xc3/0x280 fs/block_dev.c:593
>  generic_perform_write+0x3a4/0x600 mm/filemap.c:3149
> hub 1-0:1.0: activate --> -22
>  __generic_file_write_iter+0x366/0x5b0 mm/filemap.c:3263
>  blkdev_write_iter+0x207/0x3e0 fs/block_dev.c:1893
>  call_write_iter include/linux/fs.h:1772 [inline]
>  do_iter_readv_writev+0x531/0x7f0 fs/read_write.c:653
>  do_iter_write+0x15a/0x540 fs/read_write.c:932
>  vfs_iter_write+0x77/0xb0 fs/read_write.c:945
>  iter_file_splice_write+0x7db/0xf30 fs/splice.c:749
>  do_splice_from fs/splice.c:851 [inline]
>  direct_splice_actor+0x125/0x180 fs/splice.c:1018
>  splice_direct_to_actor+0x2c1/0x820 fs/splice.c:973
> hub 1-0:1.0: activate --> -22
>  do_splice_direct+0x2a7/0x3d0 fs/splice.c:1061
>  do_sendfile+0x5d5/0xe90 fs/read_write.c:1413
>  SYSC_sendfile64 fs/read_write.c:1468 [inline]
>  SyS_sendfile64+0xbd/0x160 fs/read_write.c:1460
>  entry_SYSCALL_64_fastpath+0x1f/0x96

Still happens on latest Linus tree as of today, though it takes a little while
(~30 seconds) for the C reproducer to trigger the WARN.

Re: WARNING in mark_buffer_dirty

[Eric Biggers]

On Wed, Nov 15, 2017 at 11:46:00PM -0800, syzbot wrote:
> WARNING: CPU: 3 PID: 13366 at fs/buffer.c:1108
> mark_buffer_dirty+0x48b/0x5d0 fs/buffer.c:1108
> Kernel panic - not syncing: panic_on_warn set ...
> 
> hub 1-0:1.0: activate --> -22
> CPU: 3 PID: 13366 Comm: syzkaller183798 Not tainted
> 4.14.0-rc8-next-20171109+ #11
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
> Call Trace:
>  __dump_stack lib/dump_stack.c:17 [inline]
>  dump_stack+0x194/0x257 lib/dump_stack.c:53
>  panic+0x1e4/0x41c kernel/panic.c:183
>  __warn+0x1c4/0x1e0 kernel/panic.c:546
>  report_bug+0x211/0x2d0 lib/bug.c:184
>  fixup_bug+0x40/0x90 arch/x86/kernel/traps.c:176
>  do_trap_no_signal arch/x86/kernel/traps.c:210 [inline]
>  do_trap+0x260/0x390 arch/x86/kernel/traps.c:259
>  do_error_trap+0x120/0x390 arch/x86/kernel/traps.c:296
> hub 1-0:1.0: activate --> -22
>  do_invalid_op+0x1b/0x20 arch/x86/kernel/traps.c:309
>  invalid_op+0x18/0x20 arch/x86/entry/entry_64.S:926
> RIP: 0010:mark_buffer_dirty+0x48b/0x5d0 fs/buffer.c:1108
> RSP: 0018:ffff88007ab27188 EFLAGS: 00010293
> RAX: ffff880079fa6500 RBX: ffff88007a727d20 RCX: ffffffff81bbfe5b
> RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff88007a727d20
> RBP: ffff88007ab27298 R08: 0000000000000200 R09: ffffea0001e53580
> R10: 0000000000000040 R11: ffffed000f29ac3f R12: 1ffff1000f564e32
> R13: dffffc0000000000 R14: ffff88007ab27270 R15: 0000000000000000
> hub 1-0:1.0: activate --> -22
>  __block_commit_write.isra.32+0x13b/0x2f0 fs/buffer.c:2060
>  block_write_end+0x99/0x1c0 fs/buffer.c:2138
>  blkdev_write_end+0xc3/0x280 fs/block_dev.c:593
>  generic_perform_write+0x3a4/0x600 mm/filemap.c:3149
> hub 1-0:1.0: activate --> -22
>  __generic_file_write_iter+0x366/0x5b0 mm/filemap.c:3263
>  blkdev_write_iter+0x207/0x3e0 fs/block_dev.c:1893
>  call_write_iter include/linux/fs.h:1772 [inline]
>  do_iter_readv_writev+0x531/0x7f0 fs/read_write.c:653
>  do_iter_write+0x15a/0x540 fs/read_write.c:932
>  vfs_iter_write+0x77/0xb0 fs/read_write.c:945
>  iter_file_splice_write+0x7db/0xf30 fs/splice.c:749
>  do_splice_from fs/splice.c:851 [inline]
>  direct_splice_actor+0x125/0x180 fs/splice.c:1018
>  splice_direct_to_actor+0x2c1/0x820 fs/splice.c:973
> hub 1-0:1.0: activate --> -22
>  do_splice_direct+0x2a7/0x3d0 fs/splice.c:1061
>  do_sendfile+0x5d5/0xe90 fs/read_write.c:1413
>  SYSC_sendfile64 fs/read_write.c:1468 [inline]
>  SyS_sendfile64+0xbd/0x160 fs/read_write.c:1460
>  entry_SYSCALL_64_fastpath+0x1f/0x96

Still happens on latest Linus tree as of today, though it takes a little while
(~30 seconds) for the C reproducer to trigger the WARN.