Re: slab-out-of-bounds in iov_iter_revert()

From: Qian Cai
Date: Thu Sep 17 2020 - 13:49:05 EST

On Thu, 2020-09-17 at 17:44 +0100, Al Viro wrote:
> On Thu, Sep 17, 2020 at 10:10:27AM -0400, Qian Cai wrote:
>
> > [ 81.942909] generic_file_read_iter+0x23b/0x4b0
> > [ 81.942918] fuse_file_read_iter+0x280/0x4e0 [fuse]
> > [ 81.942931] ? fuse_direct_IO+0xd30/0xd30 [fuse]
> > [ 81.942949] ? _raw_spin_lock_irqsave+0x80/0xe0
> > [ 81.942957] ? timerqueue_add+0x15e/0x280
> > [ 81.942960] ? _raw_spin_lock_irqsave+0x80/0xe0
> > [ 81.942966] new_sync_read+0x3b7/0x620
> > [ 81.942968] ? __ia32_sys_llseek+0x2e0/0x2e0
>
> Interesting... Basic logics in there:
> ->direct_IO() might consume more (on iov_iter_get_pages()
> and friends) than it actually reads. We want to revert the
> excess. Suppose by the time we call ->direct_IO() we had
> N bytes already consumed and C bytes left. We expect that
> after ->direct_IO() returns K, we have C' bytes left, N + (C - C')
> consumed and N + K out of those actually read. So we revert by
> C - K - C'. You end up trying to revert beyond the beginning.
>
> Use of iov_iter_truncate() is problematic here, since it
> changes the amount of data left without having consumed anything.
> Basically, it changes the position of end, and the logics in the
> caller expects that to remain unchanged. iov_iter_reexpand() use
> should restore the position of end.
>
> How much IO does it take to trigger that on your reproducer?

That is something I don't know for sure because it is always reproducible by
running the trinity fuzzer for a few seconds (32 threads). I did another run
below (still with your patch applied) and then tried to capture some logs here:

http://people.redhat.com/qcai/iov_iter_revert/

- virtiofsd.txt: fuse server side log until it triggered.
- trinity-post-mortem.log: AFAICT, it was the final syscall of each child.
- trinity-child9.log: the child actually triggered it.

The last syscall of child9 is:
pwritev2(fd=230, vec=0x293d3f0, vlen=1, pos_l=120, pos_h=0x200000, flags=0x3)

[ 77.125816] BUG: KASAN: stack-out-of-bounds in iov_iter_revert+0x693/0x8c0
[ 77.127079] Read of size 8 at addr ffff8886efd5fda8 by task trinity-c9/1593
[ 77.128292]
[ 77.128581] CPU: 10 PID: 1593 Comm: trinity-c9 Not tainted 5.9.0-rc5-iter+ #2
[ 77.129798] Hardware name: Red Hat KVM, BIOS 1.14.0-1.module+el8.3.0+7638+07cf13d2 04/01/2014
[ 77.131175] Call Trace:
[ 77.131934] dump_stack+0x7c/0xb0
[ 77.132500] ? iov_iter_revert+0x693/0x8c0
[ 77.133254] print_address_description.constprop.7+0x1e/0x230
[ 77.134287] ? kmsg_dump_rewind_nolock+0xd9/0xd9
[ 77.135103] ? _raw_write_lock_irqsave+0xe0/0xe0
[ 77.135933] ? iov_iter_revert+0x693/0x8c0
[ 77.136651] ? iov_iter_revert+0x693/0x8c0
[ 77.137345] kasan_report.cold.9+0x37/0x7c
[ 77.138033] ? iov_iter_revert+0x693/0x8c0
[ 77.138768] iov_iter_revert+0x693/0x8c0
[ 77.139433] ? dentry_needs_remove_privs.part.30+0x40/0x40
[ 77.140684] ? generic_write_checks+0x1d2/0x3d0
[ 77.141477] generic_file_direct_write+0x2ed/0x430
[ 77.142601] fuse_file_write_iter+0x5d8/0xb10 [fuse]
[ 77.143857] ? fuse_perform_write+0xed0/0xed0 [fuse]
[ 77.145062] do_iter_readv_writev+0x3a6/0x700
[ 77.146071] ? no_seek_end_llseek_size+0x20/0x20
[ 77.146568] kexec-bzImage64: File is too short to be a bzImage
[ 77.147277] do_iter_write+0x12f/0x5f0
[ 77.149501] ? timerqueue_add+0x15e/0x280
[ 77.150187] vfs_writev+0x172/0x2d0
[ 77.150837] ? vfs_iter_write+0xc0/0xc0
[ 77.151493] ? hrtimer_start_range_ns+0x495/0x900
[ 77.152316] ? hrtimer_run_softirq+0x210/0x210
[ 77.153087] ? _raw_spin_lock_irq+0x7b/0xd0
[ 77.153842] ? _raw_write_unlock_irqrestore+0x50/0x50
[ 77.154733] ? do_setitimer+0x2e5/0x590
[ 77.155393] ? alarm_setitimer+0xa0/0x110
[ 77.156059] do_pwritev+0x151/0x200
[ 77.156657] ? __ia32_sys_writev+0xb0/0xb0
[ 77.157336] do_syscall_64+0x33/0x40
[ 77.157928] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 77.158762] RIP: 0033:0x7fb8beed278d
[ 77.159316] 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 ff ff 73 01 c3 48 8b 0d cb 56 2c 00 f7 d8 64 89 08
[ 77.162391] RSP: 002b:00007ffcc8dcabc8 EFLAGS: 00000246 ORIG_RAX: 0000000000000148
[ 77.163672] RAX: ffffffffffffffda RBX: 0000000000000148 RCX: 00007fb8beed278d
[ 77.164921] RDX: 0000000000000001 RSI: 000000000293d3f0 RDI: 00000000000000e6
[ 77.166115] RBP: 0000000000000148 R08: 0000000000200000 R09: 0000000000000003
[ 77.167315] R10: 0000000000000078 R11: 0000000000000246 R12: 0000000000000002
[ 77.168494] R13: 00007fb8bf57c058 R14: 00007fb8bf5c26c0 R15: 00007fb8bf57c000
[ 77.169656]
[ 77.169914] The buggy address belongs to the page:
[ 77.170723] page:000000006280f5ba refcount:0 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x6efd5f
[ 77.172271] flags: 0x17ffffc0000000()
[ 77.172906] raw: 0017ffffc0000000 0000000000000000 ffffea001bb87308 0000000000000000
[ 77.174299] raw: 0000000000000000 0000000000000000 00000000ffffffff 0000000000000000
[ 77.175651] page dumped because: kasan: bad access detected
[ 77.176583]
[ 77.176848] addr ffff8886efd5fda8 is located in stack of task trinity-c9/1593 at offset 184 in frame:
[ 77.178352] vfs_writev+0x0/0x2d0
[ 77.178924]
[ 77.179158] this frame has 3 objects:
[ 77.179823] [32, 40) 'iov'
[ 77.179824] [96, 136) 'iter'
[ 77.180269] [192, 320) 'iovstack'
[ 77.180788]
[ 77.181768] Memory state around the buggy address:
[ 77.182927] ffff8886efd5fc80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 f1 f1
[ 77.184704] ffff8886efd5fd00: f1 f1 00 f2 f2 f2 f2 f2 f2 f2 00 00 00 00 00 f2
[ 77.186457] >ffff8886efd5fd80: f2 f2 f2 f2 f2 f2 00 00 00 00 00 00 00 00 00 00
[ 77.188214] ^
[ 77.189388] ffff8886efd5fe00: 00 00 00 00 00 00 f3 f3 f3 f3 00 00 00 00 00 00
[ 77.191019] ffff8886efd5fe80: 00 00 00 00 00 00 f1 f1 f1 f1 00 f2 f2 f2 00 00
[ 77.192846] ==================================================================
[ 77.194428] Disabling lock debugging due to kernel taint