Re: [syzbot] WARNING in iomap_iter

Ritesh Harjani
2022-02-13T14:34:44Z

On 22/02/12 12:41PM, syzbot wrote:
> syzbot has found a reproducer for the following issue on:
>
> HEAD commit: 83e396641110 Merge tag 'soc-fixes-5.17-1' of git://git.ker..
> git tree: upstream
> console output: https://syzkaller.appspot.com/x/log.txt?x=11fe01a4700000
> kernel config: https://syzkaller.appspot.com/x/.config?x=88e0a6a3dbf057cf
> dashboard link: https://syzkaller.appspot.com/bug?extid=a8e049cd3abd342936b6
> compiler: Debian clang version 11.0.1-2, GNU ld (GNU Binutils for Debian) 2.35.2
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14f8cad2700000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=132c16ba700000

FYI - I could reproduce with above C reproduer on my setup 5.17-rc3.
I was also able to hit it with XFS <below stack shows that>

So here is some initial analysis on this one. I haven't completely debugged it
though. I am just putting my observations here for others too.

It seems iomap_dio_rw is getting called with a negative iocb->ki_pos value.
(I haven't yet looked into when can this happen. Is it due to negative loop
device mapping range offset or something?)

i.e.
(gdb) p iocb->ki_pos
$101 = -2147483648
(gdb) p /x iocb->ki_pos
$102 = 0xffffffff80000000
(gdb)

This when passed to ->iomap_begin() sometimes is resulting into iomap->offset
which is a positive value and hence hitting below warn_on_once in
iomap_iter_done().

WARN_ON_ONCE(iter->iomap.offset > iter->pos)

1. So I think the question here is what does it mean when xfs/ext4_file_read_iter()
is called with negative iocb->ki_pos value?
2. Also when can iocb->ki_pos be negative?

<Stack Track on XFS>
======================

[ 998.417802] ------------[ cut here ]------------
[ 998.420195] WARNING: CPU: 0 PID: 1579 at fs/iomap/iter.c:33
iomap_iter+0x301/0x320
[ 998.424610] Modules linked in:
[ 998.425683] CPU: 0 PID: 1579 Comm: kworker/u2:5 Tainted:
G W 5.17.0-rc3+ #0
[ 998.428085] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.13.0-1ubuntu1 04
[ 998.430830] Workqueue: loop0 loop_rootcg_workfn
[ 998.432300] RIP: 0010:iomap_iter+0x301/0x320
[ 998.433647] Code: 89 f2 e8 72 f1 ff ff 65 ff 0d bb d0 ce 7e 0f 85 c4 fe ff ff
e8 2f 3e cdc
[ 998.438518] RSP: 0018:ffffc90000c13b30 EFLAGS: 00010307
[ 998.440490] RAX: 0000000000010000 RBX: ffffc90000c13bc0 RCX: 000000000000000c
[ 998.442576] RDX: ffffffff80000000 RSI: 0000000000001000 RDI: 0000000000000000
[ 998.444625] RBP: ffffc90000c13b50 R08: 0000000000000003 R09: ffff88814ceb9b00
[ 998.446768] R10: ffff88815122e000 R11: 000000000000000f R12: ffffffff82657c90
[ 998.453038] R13: ffffc90000c13be8 R14: ffffc90000c13c30 R15: ffffffff82657c90
[ 998.455533] FS: 0000000000000000(0000) GS:ffff88852bc00000(0000)
knlGS:0000000000000000
[ 998.458136] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 998.460069] CR2: 00007ffff4443000 CR3: 0000000105e7e000 CR4: 00000000000006f0
[ 998.462447] Call Trace:
[ 998.463108] <TASK>
[ 998.464510] __iomap_dio_rw+0x25b/0x840
[ 998.466005] iomap_dio_rw+0xe/0x30
[ 998.467476] xfs_file_dio_read+0xb9/0xf0
[ 998.469044] xfs_file_read_iter+0xc1/0xe0
[ 998.470623] lo_rw_aio+0x27a/0x2a0
[ 998.472042] loop_process_work+0x2c7/0x8c0
[ 998.473621] ? finish_task_switch+0xbc/0x260
[ 998.475232] ? __switch_to+0x2cf/0x480
[ 998.476832] loop_rootcg_workfn+0x1b/0x20
[ 998.478431] process_one_work+0x1b7/0x380
[ 998.479958] worker_thread+0x4d/0x380
[ 998.481440] ? process_one_work+0x380/0x380
[ 998.482992] kthread+0xff/0x130
[ 998.484420] ? kthread_complete_and_exit+0x20/0x20
[ 998.486122] ret_from_fork+0x22/0x30
[ 998.487616] </TASK>
[ 998.488199] ---[ end trace 0000000000000000 ]---

-ritesh

>
> IMPORTANT: if you fix the issue, please add the following tag to the commit:
> Reported-by: syzbot+a8e049cd3abd342936b6@syzkaller.appspotmail.com
>
> ------------[ cut here ]------------
> WARNING: CPU: 1 PID: 10 at fs/iomap/iter.c:33 iomap_iter_done fs/iomap/iter.c:33 [inline]
> WARNING: CPU: 1 PID: 10 at fs/iomap/iter.c:33 iomap_iter+0x7ca/0x890 fs/iomap/iter.c:78
> Modules linked in:
> CPU: 1 PID: 10 Comm: kworker/u4:1 Not tainted 5.17.0-rc3-syzkaller-00247-g83e396641110 #0
> Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
> Workqueue: loop0 loop_rootcg_workfn
> RIP: 0010:iomap_iter_done fs/iomap/iter.c:33 [inline]
> RIP: 0010:iomap_iter+0x7ca/0x890 fs/iomap/iter.c:78
> Code: e8 3b 81 83 ff eb 0c e8 34 81 83 ff eb 05 e8 2d 81 83 ff 44 89 e8 48 83 c4 40 5b 41 5c 41 5d 41 5e 41 5f 5d c3 e8 16 81 83 ff <0f> 0b e9 9e fe ff ff e8 0a 81 83 ff 0f 0b e9 d0 fe ff ff e8 fe 80
> RSP: 0018:ffffc90000cf73c8 EFLAGS: 00010293
> RAX: ffffffff82022d4a RBX: ffffffff80000000 RCX: ffff888011fe9d00
> RDX: 0000000000000000 RSI: ffffffff80000000 RDI: 00000fff80000000
> RBP: 00000fff80000000 R08: ffffffff82022be1 R09: ffffed100fd4dc19
> R10: ffffed100fd4dc19 R11: 0000000000000000 R12: ffffc90000cf75c8
> R13: 1ffff9200019eebe R14: 1ffff9200019eeb9 R15: ffffc90000cf75f0
> FS: 0000000000000000(0000) GS:ffff8880b9b00000(0000) knlGS:0000000000000000
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00007fbf80df2b88 CR3: 000000007e8f6000 CR4: 00000000003506e0
> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> Call Trace:
> <TASK>
> __iomap_dio_rw+0xa8e/0x1e00 fs/iomap/direct-io.c:589
> iomap_dio_rw+0x38/0x80 fs/iomap/direct-io.c:680
> ext4_dio_read_iter fs/ext4/file.c:77 [inline]
> ext4_file_read_iter+0x52f/0x6c0 fs/ext4/file.c:128
> lo_rw_aio+0xc75/0x1060
> loop_handle_cmd drivers/block/loop.c:1846 [inline]
> loop_process_work+0x6a4/0x22b0 drivers/block/loop.c:1886
> process_one_work+0x850/0x1130 kernel/workqueue.c:2307
> worker_thread+0xab1/0x1300 kernel/workqueue.c:2454
> kthread+0x2a3/0x2d0 kernel/kthread.c:377
> ret_from_fork+0x1f/0x30
> </TASK>
>