Re: [PATCH] io_uring: always let io_iopoll_complete() complete polled io.

[Pavel Begunkov <asml.silence@gmail.com>]

On 05/12/2020 12:32, Joseph Qi wrote:
> On 12/5/20 4:31 AM, Pavel Begunkov wrote:
>> On 03/12/2020 02:30, Joseph Qi wrote:
>>> This patch can also fix another BUG I'm looking at:
>>>
>>> [   61.359713] BUG: KASAN: double-free or invalid-free in io_dismantle_req+0x938/0xf40
>>> ...
>>> [   61.409315] refcount_t: underflow; use-after-free.
>>> [   61.410261] WARNING: CPU: 1 PID: 1022 at lib/refcount.c:28 refcount_warn_saturate+0x266/0x2a0
>>> ...
>>>
>>> It blames io_put_identity() has been called more than once and then
>>> identity->count is underflow.
>>
>> Joseph, regarding your double-free
>> 1. did you figure out how exactly this happens?
> From the a little deep analysis, it looks like it caused by a corrupted
> identity->count. Sorry for the misleading before.
> 
>> 2. is it appears consistently so you can be sure that it's fixed> 3. do you have a reproducer?
> 
> Yes, it's a syzkaller C reproducer. It can be reproduced every
> time before applying this patch.
> Attached please find the defails.

Perfect, thanks. It's important to understand for what's really happening,
so I can find similar problems or make it more resilient.

If that's one of those recent syzkaller reports posted to
io-uring@vger.kernel.org, please reply to it so we can keep track
on what is fixed.

> 
>> 4. can you paste a full log of this BUG? (not cutting the stacktrace)
>>
> 
> [   61.358485] ==================================================================
> [   61.359713] BUG: KASAN: double-free or invalid-free in io_dismantle_req+0x938/0xf40
> [   61.360820]
> [   61.361096] CPU: 0 PID: 1022 Comm: io_wqe_worker-0 Not tainted 5.10.0-rc5+ #1
> [   61.362079] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011
> [   61.362904] Call Trace:
> [   61.363370]  dump_stack+0x107/0x163
> [   61.363914]  ? io_dismantle_req+0x938/0xf40
> [   61.364584]  print_address_description.constprop.0+0x3e/0x60
> [   61.365583]  ? vprintk_func+0x98/0x140
> [   61.366246]  ? io_dismantle_req+0x938/0xf40
> [   61.366940]  ? io_dismantle_req+0x938/0xf40
> [   61.367643]  kasan_report_invalid_free+0x51/0x80
> [   61.368428]  ? io_dismantle_req+0x938/0xf40
> [   61.369192]  __kasan_slab_free+0x141/0x160
> [   61.369904]  kfree+0xd1/0x390
> [   61.370526]  io_dismantle_req+0x938/0xf40
> [   61.371199]  __io_free_req+0x95/0x5b0
> [   61.371823]  io_put_req+0x77/0xa0
> [   61.372386]  io_worker_handle_work+0xef3/0x1c00
> [   61.373130]  io_wqe_worker+0xc94/0x11a0
> [   61.373782]  ? io_worker_handle_work+0x1c00/0x1c00
> [   61.374579]  ? __kthread_parkme+0x11d/0x1d0
> [   61.375244]  ? io_worker_handle_work+0x1c00/0x1c00
> [   61.375968]  ? io_worker_handle_work+0x1c00/0x1c00
> [   61.376705]  kthread+0x396/0x470
> [   61.377271]  ? _raw_spin_unlock_irq+0x24/0x30
> [   61.377965]  ? kthread_mod_delayed_work+0x180/0x180
> [   61.378780]  ret_from_fork+0x22/0x30
> [   61.379457]
> [   61.379794] Allocated by task 1023:
> [   61.380413]  kasan_save_stack+0x1b/0x40
> [   61.381048]  __kasan_kmalloc.constprop.0+0xc2/0xd0
> [   61.381798]  kmem_cache_alloc_trace+0x17b/0x310
> [   61.382459]  io_uring_alloc_task_context+0x48/0x2b0
> [   61.383217]  io_uring_add_task_file+0x1f2/0x290
> [   61.383916]  io_uring_create+0x1745/0x2500
> [   61.384582]  io_uring_setup+0xbf/0x110
> [   61.385197]  do_syscall_64+0x33/0x40
> [   61.385797]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
> [   61.386580]
> [   61.386905] The buggy address belongs to the object at ffff8881091d0800
> [   61.386905]  which belongs to the cache kmalloc-512 of size 512
> [   61.388735] The buggy address is located 264 bytes inside of
> [   61.388735]  512-byte region [ffff8881091d0800, ffff8881091d0a00)
> [   61.390398] The buggy address belongs to the page:
> [   61.391107] page:00000000f5dbd49a refcount:1 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x1091d0
> [   61.392496] head:00000000f5dbd49a order:2 compound_mapcount:0 compound_pincount:0
> [   61.393642] flags: 0x17fffc00010200(slab|head)
> [   61.394341] raw: 0017fffc00010200 dead000000000100 dead000000000122 ffff888100041280
> [   61.395436] raw: 0000000000000000 0000000080100010 00000001ffffffff ffff888100bf0301
> [   61.396571] page dumped because: kasan: bad access detected
> [   61.397432] page->mem_cgroup:ffff888100bf0301
> [   61.398123]
> [   61.398443] Memory state around the buggy address:
> [   61.399217]  ffff8881091d0800: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> [   61.400382]  ffff8881091d0880: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> [   61.401549] >ffff8881091d0900: 00 00 00 00 00 00 00 00 00 00 00 00 fc fc fc fc
> [   61.402654]                       ^
> [   61.403232]  ffff8881091d0980: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
> [   61.404343]  ffff8881091d0a00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc
> [   61.405506] ==================================================================
> [   61.406619] Disabling lock debugging due to kernel taint
> [   61.408513] ------------[ cut here ]------------
> [   61.409315] refcount_t: underflow; use-after-free.
> [   61.410261] WARNING: CPU: 1 PID: 1022 at lib/refcount.c:28 refcount_warn_saturate+0x266/0x2a0
> [   61.411489] Modules linked in:
> [   61.411989] CPU: 1 PID: 1022 Comm: io_wqe_worker-0 Tainted: G    B             5.10.0-rc5+ #1
> [   61.413202] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011
> [   61.414026] RIP: 0010:refcount_warn_saturate+0x266/0x2a0
> [   61.415488] Code: 01 31 ff 89 de e8 4a bc 34 ff 84 db 0f 85 bb fe ff ff e8 dd ba 34 ff 48 c7 c7 00 54 c7 83 c6 05 c2 b2 20 03 01 e8 40 56 22 01 <0f> 0b e9 9c fe ff ff 48 89 ef e8 2b 1d 77 ff e9 c9 fd ff ff e8 b1
> [   61.418943] RSP: 0018:ffff88810e467c98 EFLAGS: 00010286
> [   61.420053] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
> [   61.421434] RDX: 0000000000000000 RSI: ffffffff81348588 RDI: ffffed1021c8cf89
> [   61.422871] RBP: ffff8881091d0948 R08: ffff88810a4e2240 R09: ffffed1023466048
> [   61.424551] R10: ffff88811a33023b R11: ffffed1023466047 R12: ffff8881091d0908
> [   61.425955] R13: ffff8881090e30c8 R14: ffff8881091d0948 R15: ffff8881049b3300
> [   61.427361] FS:  0000000000000000(0000) GS:ffff88811a300000(0000) knlGS:0000000000000000
> [   61.428920] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [   61.430036] CR2: 00007ff46b29eef8 CR3: 000000010df64004 CR4: 00000000003706e0
> [   61.431380] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [   61.432794] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [   61.434178] Call Trace:
> [   61.434797]  io_dismantle_req+0x907/0xf40
> [   61.435676]  __io_free_req+0x95/0x5b0
> [   61.436408]  io_put_req+0x77/0xa0
> [   61.437141]  io_worker_handle_work+0xef3/0x1c00
> [   61.438073]  io_wqe_worker+0xc94/0x11a0
> [   61.438868]  ? io_worker_handle_work+0x1c00/0x1c00
> [   61.439862]  ? __kthread_parkme+0x11d/0x1d0
> [   61.440767]  ? io_worker_handle_work+0x1c00/0x1c00
> [   61.441760]  ? io_worker_handle_work+0x1c00/0x1c00
> [   61.442766]  kthread+0x396/0x470
> [   61.443491]  ? _raw_spin_unlock_irq+0x24/0x30
> [   61.444348]  ? kthread_mod_delayed_work+0x180/0x180
> [   61.445325]  ret_from_fork+0x22/0x30
> [   61.446118] irq event stamp: 38
> [   61.446867] hardirqs last  enabled at (37): [<ffffffff818e95d7>] kfree+0x1c7/0x390
> [   61.448351] hardirqs last disabled at (38): [<ffffffff834976e0>] _raw_spin_lock_irqsave+0x50/0x60
> [   61.449826] softirqs last  enabled at (0): [<ffffffff811a5989>] copy_process+0x18a9/0x67d0
> [   61.450930] softirqs last disabled at (0): [<0000000000000000>] 0x0
> [   61.451756] ---[ end trace 67489de2f872e2d0 ]---
> [   61.498486] audit: type=1326 audit(1606805588.425:5): auid=0 uid=0 gid=0 ses=1 pid=1027 comm="a.out" exe="/root/a.out" sig=31 arch=c000003e syscall=202 compat=0 ip=0x7ff46abfc239 code=0x0
> [   61.503570] ------------[ cut here ]------------
> [   61.504505] WARNING: CPU: 0 PID: 725 at fs/io_uring.c:7769 __io_uring_free+0x179/0x1e0
> [   61.506114] Modules linked in:
> [   61.506869] CPU: 0 PID: 725 Comm: kworker/u4:3 Tainted: G    B   W         5.10.0-rc5+ #1
> [   61.508567] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011
> [   61.509774] Workqueue: events_unbound io_ring_exit_work
> [   61.510863] RIP: 0010:__io_uring_free+0x179/0x1e0
> [   61.511979] Code: 00 00 fc ff df 48 c1 ea 03 80 3c 02 00 75 6c 48 c7 83 b0 07 00 00 00 00 00 00 5b 5d 41 5c 41 5d 41 5e 41 5f c3 e8 37 96 9a ff <0f> 0b e9 6e ff ff ff e8 2b 96 9a ff 0f 0b e9 de fe ff ff 4c 89 e7
> [   61.515559] RSP: 0018:ffff888109b17cb0 EFLAGS: 00010293
> [   61.516733] RAX: ffff888108fa2240 RBX: ffff888100f04480 RCX: ffffffff81b22c24
> [   61.518237] RDX: 0000000000000000 RSI: ffffffff81b22cb9 RDI: 0000000000000005
> [   61.519635] RBP: ffff8881091d0800 R08: ffff888108fa2240 R09: ffffed102123a12a
> [   61.521169] R10: ffff8881091d094b R11: ffffed102123a129 R12: 00000000c0000000
> [   61.522662] R13: ffff888100f04c30 R14: ffff8881091d0950 R15: ffff8881091d0908
> [   61.523840] FS:  0000000000000000(0000) GS:ffff88811a200000(0000) knlGS:0000000000000000
> [   61.525130] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [   61.526063] CR2: 00007f05a8ecbfc0 CR3: 0000000108f80001 CR4: 00000000003706f0
> [   61.527285] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [   61.528435] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [   61.529717] Call Trace:
> [   61.530384]  __put_task_struct+0x104/0x400
> [   61.531340]  io_ring_exit_work+0x777/0x9d0
> [   61.532279]  process_one_work+0x8aa/0x1520
> [   61.533275]  ? check_flags+0x60/0x60
> [   61.534085]  ? pwq_dec_nr_in_flight+0x360/0x360
> [   61.535067]  ? rwlock_bug.part.0+0x90/0x90
> [   61.535885]  worker_thread+0x9b/0xe20
> [   61.536535]  ? process_one_work+0x1520/0x1520
> [   61.537242]  ? process_one_work+0x1520/0x1520
> [   61.537902]  kthread+0x396/0x470
> [   61.538570]  ? _raw_spin_unlock_irq+0x24/0x30
> [   61.539239]  ? kthread_mod_delayed_work+0x180/0x180
> [   61.540058]  ret_from_fork+0x22/0x30
> [   61.540678] irq event stamp: 1626
> [   61.541272] hardirqs last  enabled at (1625): [<ffffffff83497894>] _raw_spin_unlock_irq+0x24/0x30
> [   61.542633] hardirqs last disabled at (1626): [<ffffffff834860e4>] __schedule+0x1114/0x2190
> [   61.543882] softirqs last  enabled at (1586): [<ffffffff81a477ea>] wb_workfn+0x64a/0x830
> [   61.545094] softirqs last disabled at (1582): [<ffffffff817b63c7>] wb_wakeup_delayed+0x67/0xf0
> [   61.546416] ---[ end trace 67489de2f872e2d1 ]---
> 

-- 
Pavel Begunkov