[syzbot] [ext4?] WARNING in ext4_file_write_iter

[syzbot]

Hello,

syzbot found the following issue on:

HEAD commit: f7efed9f38f8 Add linux-next specific files for 20230616
git tree: linux-next
console output: https://syzkaller.appspot.com/x/log.txt?x=144c7b07280000
kernel config: https://syzkaller.appspot.com/x/.config?x=60b1a32485a77c16
dashboard link: https://syzkaller.appspot.com/bug?extid=5050ad0fb47527b1808a
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

Unfortunately, I don't have any reproducer for this issue yet.

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/95bcbee03439/disk-f7efed9f.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/6fd295caa4de/vmlinux-f7efed9f.xz
kernel image: https://storage.googleapis.com/syzbot-assets/69c038a34b5f/bzImage-f7efed9f.xz

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+5050ad...@syzkaller.appspotmail.com

------------[ cut here ]------------
WARNING: CPU: 1 PID: 17447 at fs/ext4/file.c:611 ext4_dio_write_iter fs/ext4/file.c:611 [inline]
WARNING: CPU: 1 PID: 17447 at fs/ext4/file.c:611 ext4_file_write_iter+0x1470/0x1880 fs/ext4/file.c:720
Modules linked in:
CPU: 1 PID: 17447 Comm: syz-executor.2 Not tainted 6.4.0-rc6-next-20230616-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 05/27/2023
RIP: 0010:ext4_dio_write_iter fs/ext4/file.c:611 [inline]
RIP: 0010:ext4_file_write_iter+0x1470/0x1880 fs/ext4/file.c:720
Code: 84 03 00 00 48 8b 04 24 31 ff 8b 40 20 89 c3 89 44 24 10 83 e3 08 89 de e8 bd 5e 5b ff 85 db 0f 85 d5 fc ff ff e8 90 62 5b ff <0f> 0b e9 c9 fc ff ff e8 84 62 5b ff 48 8b 4c 24 40 4c 89 fa 4c 89
RSP: 0018:ffffc9000bc5f9e8 EFLAGS: 00010216
RAX: 000000000003523a RBX: 0000000000000000 RCX: ffffc9000b3d9000
RDX: 0000000000040000 RSI: ffffffff8228ff90 RDI: 0000000000000005
RBP: 0000000000000001 R08: 0000000000000005 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000001 R12: ffffffff8a832160
R13: 0000000000000000 R14: 0000000000000000 R15: fffffffffffffff5
FS: 00007f129f62e700(0000) GS:ffff8880b9900000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000020105000 CR3: 0000000044e0d000 CR4: 00000000003506e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<TASK>
call_write_iter include/linux/fs.h:1871 [inline]
aio_write+0x350/0x7d0 fs/aio.c:1596
__io_submit_one fs/aio.c:1968 [inline]
io_submit_one+0xf4c/0x1c50 fs/aio.c:2015
__do_sys_io_submit fs/aio.c:2074 [inline]
__se_sys_io_submit fs/aio.c:2044 [inline]
__x64_sys_io_submit+0x190/0x320 fs/aio.c:2044
do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x39/0xb0 arch/x86/entry/common.c:80
entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7f129e88c389
Code: 28 00 00 00 75 05 48 83 c4 28 c3 e8 f1 19 00 00 90 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:00007f129f62e168 EFLAGS: 00000246 ORIG_RAX: 00000000000000d1
RAX: ffffffffffffffda RBX: 00007f129e9abf80 RCX: 00007f129e88c389
RDX: 0000000020000780 RSI: 0000000000000001 RDI: 00007f129f5e4000
RBP: 00007f129e8d7493 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007fffd72c552f R14: 00007f129f62e300 R15: 0000000000022000
</TASK>


---
This report is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzk...@googlegroups.com.

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

If the bug is already fixed, let syzbot know by replying with:
#syz fix: exact-commit-title

If you want to change bug's subsystems, reply with:
#syz set subsystems: new-subsystem
(See the list of subsystem names on the web dashboard)

If the bug is a duplicate of another bug, reply with:
#syz dup: exact-subject-of-another-report

If you want to undo deduplication, reply with:
#syz undup

[syzbot]

syzbot has found a reproducer for the following issue on:

HEAD commit: 6843306689af Merge tag 'net-6.5-rc1' of git://git.kernel.o..
git tree: net
console output: https://syzkaller.appspot.com/x/log.txt?x=114522aca80000
kernel config: https://syzkaller.appspot.com/x/.config?x=7ad417033279f15a

dashboard link: https://syzkaller.appspot.com/bug?extid=5050ad0fb47527b1808a
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

syz repro: https://syzkaller.appspot.com/x/repro.syz?x=102cb190a80000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=17c49d90a80000

Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/f6adc10dbd71/disk-68433066.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/5c3fa1329201/vmlinux-68433066.xz
kernel image: https://storage.googleapis.com/syzbot-assets/84db3452bac5/bzImage-68433066.xz

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+5050ad...@syzkaller.appspotmail.com

------------[ cut here ]------------

WARNING: CPU: 1 PID: 5382 at fs/ext4/file.c:611 ext4_dio_write_iter fs/ext4/file.c:611 [inline]
WARNING: CPU: 1 PID: 5382 at fs/ext4/file.c:611 ext4_file_write_iter+0x1470/0x1880 fs/ext4/file.c:720
Modules linked in:
CPU: 1 PID: 5382 Comm: syz-executor288 Not tainted 6.4.0-syzkaller-11989-g6843306689af #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 05/27/2023
RIP: 0010:ext4_dio_write_iter fs/ext4/file.c:611 [inline]
RIP: 0010:ext4_file_write_iter+0x1470/0x1880 fs/ext4/file.c:720

Code: 84 03 00 00 48 8b 04 24 31 ff 8b 40 20 89 c3 89 44 24 10 83 e3 08 89 de e8 5d 5a 5b ff 85 db 0f 85 d5 fc ff ff e8 30 5e 5b ff <0f> 0b e9 c9 fc ff ff e8 24 5e 5b ff 48 8b 4c 24 40 4c 89 fa 4c 89
RSP: 0018:ffffc9000522fc30 EFLAGS: 00010293
RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
RDX: ffff8880277a3b80 RSI: ffffffff82298140 RDI: 0000000000000005

RBP: 0000000000000001 R08: 0000000000000005 R09: 0000000000000000

R10: 0000000000000000 R11: 0000000000000001 R12: ffffffff8a832a60

R13: 0000000000000000 R14: 0000000000000000 R15: fffffffffffffff5

FS: 00007f154db95700(0000) GS:ffff8880b9900000(0000) knlGS:0000000000000000

CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033

CR2: 00007f154db74718 CR3: 000000006bcc7000 CR4: 00000000003506e0

DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<TASK>
call_write_iter include/linux/fs.h:1871 [inline]

new_sync_write fs/read_write.c:491 [inline]
vfs_write+0x981/0xda0 fs/read_write.c:584
ksys_write+0x122/0x250 fs/read_write.c:637

do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x39/0xb0 arch/x86/entry/common.c:80
entry_SYSCALL_64_after_hwframe+0x63/0xcd

RIP: 0033:0x7f154dc094f9
Code: 28 00 00 00 75 05 48 83 c4 28 c3 e8 e1 15 00 00 90 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:00007f154db952f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 00007f154dc924f0 RCX: 00007f154dc094f9
RDX: 0000000000248800 RSI: 0000000020000000 RDI: 0000000000000006
RBP: 00007f154dc5f628 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 652e79726f6d656d
R13: 656c6c616b7a7973 R14: 6465646165726874 R15: 00007f154dc924f8
</TASK>


---
If you want syzbot to run the reproducer, reply with:
#syz test: git://repo/address.git branch-or-commit-hash
If you attach or paste a git patch, syzbot will apply it before testing.

[Pengfei Xu]

Above issue in dmesg is:

"WARNING: CPU: 1 PID: 5382 at fs/ext4/file.c:611 ext4_dio_write_iter fs/ext4/file.c:611 [inline]"

I found the similar behavior issue:
"WARNING: CPU: 0 PID: 182134 at fs/ext4/file.c:611 ext4_dio_write_iter fs/ext4/file.c:611 [inline]"
repro.report shows similar details.

Updated the bisect info for the above similar issue:
Bisected and the problem commit was:
"
310ee0902b8d9d0a13a5a13e94688a5863fa29c2: ext4: allow concurrent unaligned dio overwrites
"
After reverted the commit on top of v6.5-rc3, this issue was gone.

All information: https://github.com/xupengfe/syzkaller_logs/tree/main/230730_134501_ext4_file_write_iter
Reproduced code: https://github.com/xupengfe/syzkaller_logs/blob/main/230730_134501_ext4_file_write_iter/repro.c
repro.prog(syscall reproduced steps): https://github.com/xupengfe/syzkaller_logs/blob/main/230730_134501_ext4_file_write_iter/repro.prog
repro.report: https://github.com/xupengfe/syzkaller_logs/blob/main/230730_134501_ext4_file_write_iter/repro.report
Bisect log: https://github.com/xupengfe/syzkaller_logs/blob/main/230730_134501_ext4_file_write_iter/bisect_info.log
Kconfig: https://github.com/xupengfe/syzkaller_logs/blob/main/230730_134501_ext4_file_write_iter/kconfig_origin
Issue dmesg: https://github.com/xupengfe/syzkaller_logs/blob/main/230730_134501_ext4_file_write_iter/6eaae198076080886b9e7d57f4ae06fa782f90ef_dmesg.log

Best Regards,
Thanks!

[syzbot]

> #syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git 6843306689af

Your commands are accepted, but please keep syzkall...@googlegroups.com mailing list in CC next time. It serves as a history of what happened with each bug report. Thank you.

>
> diff --git a/fs/ext4/file.c b/fs/ext4/file.c
> index c457c8517f0f..1fe74735b4e4 100644
> --- a/fs/ext4/file.c
> +++ b/fs/ext4/file.c
> @@ -608,7 +608,10 @@ static ssize_t ext4_dio_write_iter(struct kiocb *iocb, struct iov_iter *from)
> iomap_ops = &ext4_iomap_overwrite_ops;
> ret = iomap_dio_rw(iocb, from, iomap_ops, &ext4_dio_write_ops,
> dio_flags, NULL, 0);
> - WARN_ON_ONCE(ret == -EAGAIN && !(iocb->ki_flags & IOCB_NOWAIT));
> + if (ret == -EAGAIN) {
> + WARN_ON(dio_flags == IOMAP_DIO_OVERWRITE_ONLY);
> + WARN_ON(!(iocb->ki_flags & IOCB_NOWAIT));
> + }
> if (ret == -ENOTBLK)
> ret = 0;
>
>

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:
WARNING in ext4_file_write_iter

------------[ cut here ]------------
WARNING: CPU: 0 PID: 5938 at fs/ext4/file.c:613 ext4_dio_write_iter fs/ext4/file.c:613 [inline]
WARNING: CPU: 0 PID: 5938 at fs/ext4/file.c:613 ext4_file_write_iter+0x1698/0x1950 fs/ext4/file.c:723
Modules linked in:
CPU: 0 PID: 5938 Comm: syz-executor.1 Not tainted 6.4.0-syzkaller-11989-g6843306689af-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 07/12/2023
RIP: 0010:ext4_dio_write_iter fs/ext4/file.c:613 [inline]
RIP: 0010:ext4_file_write_iter+0x1698/0x1950 fs/ext4/file.c:723
Code: 89 ee e8 5b 5f 8c ff e9 75 fb ff ff e8 e1 ba 5a ff 49 89 df e9 26 fe ff ff e8 d4 ba 5a ff 0f 0b e9 70 fd ff ff e8 c8 ba 5a ff <0f> 0b e9 a9 fd ff ff e8 ec 48 ae ff e9 3e ee ff ff e8 e2 48 ae ff
RSP: 0018:ffffc9000307fc28 EFLAGS: 00010293

RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000

RDX: ffff88802d699dc0 RSI: ffffffff822af7e8 RDI: 0000000000000005
RBP: 0000000000000000 R08: 0000000000000005 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000094000 R12: 0000000000000000
R13: ffff8880688252b0 R14: ffffc9000307fe00 R15: fffffffffffffff5
FS: 00007f1dc1fdb6c0(0000) GS:ffff8880b9800000(0000) knlGS:0000000000000000

CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033

CR2: 000056318965a131 CR3: 0000000065426000 CR4: 00000000003506f0

DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<TASK>
call_write_iter include/linux/fs.h:1871 [inline]
new_sync_write fs/read_write.c:491 [inline]

vfs_write+0x60a/0xdf0 fs/read_write.c:584
ksys_write+0x126/0x250 fs/read_write.c:637
do_syscall_x64 arch/x86/entry/common.c:50 [inline]
do_syscall_64+0x38/0xb0 arch/x86/entry/common.c:80
entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7f1dc127cb29
Code: 28 00 00 00 75 05 48 83 c4 28 c3 e8 e1 20 00 00 90 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 b0 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007f1dc1fdb0c8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 00007f1dc139bf80 RCX: 00007f1dc127cb29

RDX: 0000000000248800 RSI: 0000000020000000 RDI: 0000000000000006

RBP: 00007f1dc12c847a R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 000000000000000b R14: 00007f1dc139bf80 R15: 00007fffd847a4e8
</TASK>


Tested on:

commit: 68433066 Merge tag 'net-6.5-rc1' of git://git.kernel.o..
git tree: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
console output: https://syzkaller.appspot.com/x/log.txt?x=160f403ea80000
kernel config: https://syzkaller.appspot.com/x/.config?x=2a211c03cef60366
dashboard link: https://syzkaller.appspot.com/bug?extid=5050ad0fb47527b1808a
compiler: gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40
patch: https://syzkaller.appspot.com/x/patch.diff?x=109a7c96a80000

[Brian Foster]

Hi Pengfei,

Thanks for narrowing this down (and sorry for missing the earlier
report). Unfortunately I've not been able to reproduce this locally
using the generated reproducer. I tried both running the test program on
a local test vm as well as booting the generated disk image directly.

That said, I have received another report of this warning that happens
to be related to io_uring. The cause in that particular case is that
io_uring sets IOCB_HIPRI, which iomap dio turns into
REQ_POLLED|REQ_NOWAIT on the bio without necessarily having IOCB_NOWAIT
set on the request. This means we can expect -EAGAIN returns from the
storage layer without necessarily passing DIO_OVERWRITE_ONLY to iomap,
which in turn basically means that the warning added by this commit is
wrong.

I did submit the test patch at the link [1] referenced below to syzbot
to see if the OVERWRITE_ONLY flag is set and the results I got this
morning only showed the original !IOCB_NOWAIT warning. So while I still
do not know the source of the -EAGAIN in the syzbot test (and I would
like to), this shows that the overwrite flag is not involved and thus
the -EAGAIN is presumably unrelated to that logic.

So in summary I think the right fix is to just remove the overwrite flag
and warning from this ext4 codepath. It was always intended as an extra
precaution to support the warning, and the latter is clearly wrong. I'll
submit another test change in a separate mail just to see if syzbot
finds anything else and plan to send a proper patch to the list. In the
meantime, if you have any suggestions to help reproduce via the
generated program, I'm still interested in trying to grok where that
particular -EAGAIN comes from.. Thanks.

Brian

[1] https://syzkaller.appspot.com/x/patch.diff?x=109a7c96a80000

[Brian Foster]

#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master

diff --git a/fs/ext4/file.c b/fs/ext4/file.c
index c457c8517f0f..5642a3466c5d 100644
--- a/fs/ext4/file.c
+++ b/fs/ext4/file.c
@@ -504,9 +504,7 @@ static ssize_t ext4_dio_write_checks(struct kiocb *iocb, struct iov_iter *from,
* non-overwrite or extending, so drain all outstanding dio and set the
* force wait dio flag.
*/
- if (*ilock_shared && unaligned_io) {
- *dio_flags = IOMAP_DIO_OVERWRITE_ONLY;
- } else if (!*ilock_shared && (unaligned_io || *extend)) {
+ if (!*ilock_shared && (unaligned_io || *extend)) {
if (iocb->ki_flags & IOCB_NOWAIT) {
ret = -EAGAIN;
goto out;
@@ -608,7 +606,6 @@ static ssize_t ext4_dio_write_iter(struct kiocb *iocb, struct iov_iter *from)

iomap_ops = &ext4_iomap_overwrite_ops;
ret = iomap_dio_rw(iocb, from, iomap_ops, &ext4_dio_write_ops,
dio_flags, NULL, 0);
- WARN_ON_ONCE(ret == -EAGAIN && !(iocb->ki_flags & IOCB_NOWAIT));

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+5050ad...@syzkaller.appspotmail.com

Tested on:

commit: c1a515d3 Merge tag 'perf-tools-fixes-for-v6.5-2-2023-0..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=17939bc1a80000
kernel config: https://syzkaller.appspot.com/x/.config?x=df103238a07f256e
dashboard link: https://syzkaller.appspot.com/bug?extid=5050ad0fb47527b1808a
compiler: gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40
patch: https://syzkaller.appspot.com/x/patch.diff?x=115d865da80000

Note: testing is done by a robot and is best-effort only.

[Pengfei Xu]

Hi Brian,

Thanks for your patch! I'm glad it's helpful.

It could not be reproduced immediately and it takes more than 200s to
reproduce this issue, anyway here is my reproduced steps.
As following link info for example, it's not my reproduced environment and it's
alsmost the same for issue reproducing:
https://lore.kernel.org/all/0000000000007f...@google.com/T/#mf1678f17b7b7c4b3cc73abef436aac68787397ae
-> disk image: https://storage.googleapis.com/syzbot-assets/f6adc10dbd71/disk-68433066.raw.xz
-> kernel image: https://storage.googleapis.com/syzbot-assets/84db3452bac5/bzImage-68433066.xz

I used below simple script to boot up vm:
"
#!/bin/bash

bzimage=$1

[[ -z "$bzimage" ]] && bzimage="./bzImage-68433066"
qemu-system-x86_64 \
-m 2G \
-smp 2 \
-kernel $bzimage \
-append "console=ttyS0 root=/dev/sda1 earlyprintk=serial net.ifnames=0 thunderbolt.dyndbg" \
-drive file=./disk-68433066.raw,format=raw \
-net user,host=10.0.2.10,hostfwd=tcp:127.0.0.1:10023-:22 \
-cpu host \
-net nic,model=e1000 \
-enable-kvm \
-nographic \
2>&1 | tee vmd.log
"

gcc -pthread -o repro repro.c
scp -P 10023 repro root@localhost:/root/

And then access to above vm and execute the reproduced binary to reproduce.
Sometimes it takes some time to reproduce the problem.
Hope the above information helps you to reproduce the problem next time.

I saw syzbot already verified your latest patch and it's passed.
https://syzkaller.appspot.com/x/log.txt?x=17939bc1a80000

Best Regards,
Thanks!

[Brian Foster]

Thanks! This was very useful as I've been able to reproduce fairly
reliably using this script. I suspect something was sufficiently
different in my guest env that made this difficult to reproduce for
whatever reason.

The source of the -EAGAIN in this particular case is the
mmap_read_lock_killable() call down in __get_user_pages_locked(). I
haven't fully characterized test behavior, but I suppose this is being
interrupted somehow or another. From there, this only occasionally
reproduces the ext4 warning because the iomap iteration code
(iomap_dio_bio_iter()) only returns the error when no progress has been
made to that point, otherwise it's a short write.

So this is indeed different from the io_uring variant I described
earlier, but is still another instance of an -EAGAIN return unrelated to
the overwrite logic or *_NOWAIT.

Brian