Re: usercopy whitelist woe in scsi_sense_cache

[Kees Cook]

On Mon, Apr 9, 2018 at 12:02 PM, Oleksandr Natalenko
<oleksandr@xxxxxxxxxxxxxx> wrote:
>
> Hi.
>
> (fancy details for linux-block and BFQ people go below)
>
> 09.04.2018 20:32, Kees Cook wrote:
>>
>> Ah, this detail I didn't have. I've changed my environment to
>>
>> build with:
>>
>> CONFIG_BLK_MQ_PCI=y
>> CONFIG_BLK_MQ_VIRTIO=y
>> CONFIG_IOSCHED_BFQ=y
>>
>> boot with scsi_mod.use_blk_mq=1
>>
>> and select BFQ in the scheduler:
>>
>> # cat /sys/block/sd?/queue/scheduler
>> mq-deadline kyber [bfq] none
>> mq-deadline kyber [bfq] none
>>
>> Even with this, I'm not seeing anything yet...
>
>
> Thanks for looking into it anyway. I was experimenting today a little bit, and for me it looks like setting queue_depth and nr_requests to minimal values speeds up the reproducing. Could you please try it too? Something like:
>
> echo 1 | tee /sys/block/sd*/queue/nr_requests

I can't get this below "4".

> echo 1 | tee /sys/block/sd*/device/queue_depth

I've got this now too.

> Also, now I have a more solid proof that this is related to I/O scheduling.
>
> I was hammering my VM, and after a couple of usercopy warnings/bugs I can reliably trigger I/O hang. I was able to obtain the stack traces of tasks in D state. Listing them here below. dmcrypt_write:

Ah! dm-crypt too. I'll see if I can get that added easily to my tests.

> ===
> [ 1615.409622] dmcrypt_write   D    0   236      2 0x80000000
> [ 1615.413422] Call Trace:
> [ 1615.415428]  ? __schedule+0x336/0xf40
> [ 1615.417824]  ? blk_mq_sched_dispatch_requests+0x117/0x190
> [ 1615.421423]  ? __sbitmap_get_word+0x2a/0x80
> [ 1615.424202]  schedule+0x32/0xc0
> [ 1615.426521]  io_schedule+0x12/0x40
> [ 1615.432414]  blk_mq_get_tag+0x181/0x2a0
> [ 1615.434881]  ? elv_merge+0x79/0xe0
> [ 1615.437447]  ? wait_woken+0x80/0x80
> [ 1615.439553]  blk_mq_get_request+0xf9/0x400
> [ 1615.444653]  blk_mq_make_request+0x10b/0x640
> [ 1615.448025]  generic_make_request+0x124/0x2d0
> [ 1615.450716]  ? raid10_unplug+0xfb/0x180 [raid10]
> [ 1615.454069]  raid10_unplug+0xfb/0x180 [raid10]
> [ 1615.456729]  blk_flush_plug_list+0xc1/0x250
> [ 1615.460276]  blk_finish_plug+0x27/0x40
> [ 1615.464103]  dmcrypt_write+0x233/0x240 [dm_crypt]
> [ 1615.467443]  ? wake_up_process+0x20/0x20
> [ 1615.470845]  ? crypt_iv_essiv_dtr+0x60/0x60 [dm_crypt]
> [ 1615.475272]  ? kthread+0x113/0x130
> [ 1615.477652]  kthread+0x113/0x130
> [ 1615.480567]  ? kthread_create_on_node+0x70/0x70
> [ 1615.483268]  ret_from_fork+0x35/0x40
> ===
>
> One of XFS threads, too:

And XFS! You love your corner cases. ;)

>
> ===
> [ 1616.133298] xfsaild/dm-7    D    0   316      2 0x80000000
> [ 1616.136679] Call Trace:
> [ 1616.138845]  ? __schedule+0x336/0xf40
> [ 1616.141581]  ? preempt_count_add+0x68/0xa0
> [ 1616.147214]  ? _raw_spin_unlock+0x16/0x30
> [ 1616.149813]  ? _raw_spin_unlock_irqrestore+0x20/0x40
> [ 1616.152478]  ? try_to_del_timer_sync+0x4d/0x80
> [ 1616.154734]  schedule+0x32/0xc0
> [ 1616.156579]  _xfs_log_force+0x146/0x290 [xfs]
> [ 1616.159322]  ? wake_up_process+0x20/0x20
> [ 1616.162175]  xfsaild+0x1a9/0x820 [xfs]
> [ 1616.164695]  ? xfs_trans_ail_cursor_first+0x80/0x80 [xfs]
> [ 1616.167567]  ? kthread+0x113/0x130
> [ 1616.169722]  kthread+0x113/0x130
> [ 1616.171908]  ? kthread_create_on_node+0x70/0x70
> [ 1616.174073]  ? do_syscall_64+0x74/0x190
> [ 1616.179008]  ? SyS_exit_group+0x10/0x10
> [ 1616.182306]  ret_from_fork+0x35/0x40
> ===
>
> journald is another victim:
>
> ===
> [ 1616.184343] systemd-journal D    0   354      1 0x00000104
> [ 1616.187282] Call Trace:
> [ 1616.189464]  ? __schedule+0x336/0xf40
> [ 1616.191781]  ? call_function_single_interrupt+0xa/0x20
> [ 1616.194788]  ? _raw_spin_lock_irqsave+0x25/0x50
> [ 1616.197592]  schedule+0x32/0xc0
> [ 1616.200171]  schedule_timeout+0x202/0x470
> [ 1616.202851]  ? preempt_count_add+0x49/0xa0
> [ 1616.206227]  wait_for_common+0xbb/0x180
> [ 1616.209877]  ? wake_up_process+0x20/0x20
> [ 1616.212511]  do_coredump+0x335/0xea0
> [ 1616.214861]  ? schedule+0x3c/0xc0
> [ 1616.216775]  ? futex_wait_queue_me+0xbb/0x110
> [ 1616.218894]  ? _raw_spin_unlock+0x16/0x30
> [ 1616.220868]  ? futex_wait+0x143/0x240
> [ 1616.223450]  get_signal+0x250/0x5c0
> [ 1616.225965]  do_signal+0x36/0x610
> [ 1616.228246]  ? __seccomp_filter+0x3b/0x260
> [ 1616.231000]  ? __check_object_size+0x9f/0x1a0
> [ 1616.233716]  exit_to_usermode_loop+0x85/0xa0
> [ 1616.238413]  do_syscall_64+0x18b/0x190
> [ 1616.240798]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
> [ 1616.244401] RIP: 0033:0x7f78fc53e45d
> [ 1616.246690] RSP: 002b:00007ffd40330d20 EFLAGS: 00000246 ORIG_RAX: 00000000000000ca
> [ 1616.251199] RAX: fffffffffffffe00 RBX: 00007f78f7806700 RCX: 00007f78fc53e45d
> [ 1616.254817] RDX: 00000000000004cd RSI: 0000000000000000 RDI: 00007f78f78069d0
> [ 1616.258410] RBP: 00007ffd40330d20 R08: 00000000000000ca R09: 00007f78f78069d0
> [ 1616.261813] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
> [ 1616.265065] R13: 0000000000000000 R14: 00007f78fc95e8c0 R15: 00007f78f7806d28
>
> [ 1616.272861] journal-offline D    0  1229      1 0x00000104
> [ 1616.275856] Call Trace:
> [ 1616.277396]  ? __schedule+0x336/0xf40
> [ 1616.279258]  ? release_pages+0x192/0x3d0
> [ 1616.282871]  schedule+0x32/0xc0
> [ 1616.285218]  io_schedule+0x12/0x40
> [ 1616.287267]  wait_on_page_bit+0xea/0x130
> [ 1616.291084]  ? add_to_page_cache_lru+0xe0/0xe0
> [ 1616.293898]  __filemap_fdatawait_range+0xbb/0x110
> [ 1616.297391]  ? xen_swiotlb_init+0x85/0x4d0
> [ 1616.303285]  file_write_and_wait_range+0x76/0xa0
> [ 1616.306313]  xfs_file_fsync+0x5d/0x240 [xfs]
> [ 1616.309196]  ? syscall_trace_enter+0xd8/0x2d0
> [ 1616.312193]  do_fsync+0x38/0x60
> [ 1616.314654]  SyS_fsync+0xc/0x10
> [ 1616.318686]  do_syscall_64+0x74/0x190
> [ 1616.321519]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
> [ 1616.324045] RIP: 0033:0x7f78fc5470ec
> [ 1616.326257] RSP: 002b:00007f78f7805d30 EFLAGS: 00000293 ORIG_RAX: 000000000000004a
> [ 1616.333535] RAX: ffffffffffffffda RBX: 00005597340357b0 RCX: 00007f78fc5470ec
> [ 1616.337057] RDX: 0000000000000000 RSI: 00007f78fbea3811 RDI: 0000000000000013
> [ 1616.341176] RBP: 00007f78fbea4c60 R08: 00007f78f7806700 R09: 00007f78f7806700
> [ 1616.345029] R10: 0000000000000811 R11: 0000000000000293 R12: 0000000000000002
> [ 1616.349279] R13: 00007ffd40330e8f R14: 00007ffd40330e90 R15: 0000000000000016
>
> [ 1876.568670] systemd-journal D    0 14892      1 0x00000100
> [ 1876.573395] Call Trace:
> [ 1876.575559]  ? __schedule+0x336/0xf40
> [ 1876.578005]  ? memcg_kmem_charge+0xad/0xf0
> [ 1876.580797]  ? lock_page_memcg+0x11/0x80
> [ 1876.583674]  schedule+0x32/0xc0
> [ 1876.585516]  io_schedule+0x12/0x40
> [ 1876.590223]  wait_on_page_bit+0xea/0x130
> [ 1876.591840]  ? add_to_page_cache_lru+0xe0/0xe0
> [ 1876.593554]  __filemap_fdatawait_range+0xbb/0x110
> [ 1876.595340]  ? store_online+0x34/0xb0
> [ 1876.596913]  ? __filemap_fdatawrite_range+0xc1/0x100
> [ 1876.599338]  ? __filemap_fdatawrite_range+0xcf/0x100
> [ 1876.601447]  file_write_and_wait_range+0x76/0xa0
> [ 1876.604356]  xfs_file_fsync+0x5d/0x240 [xfs]
> [ 1876.606599]  ? syscall_trace_enter+0xd8/0x2d0
> [ 1876.608753]  do_fsync+0x38/0x60
> [ 1876.610952]  SyS_fsync+0xc/0x10
> [ 1876.612442]  do_syscall_64+0x74/0x190
> [ 1876.615383]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
> [ 1876.622030] RIP: 0033:0x7fe056a840c4
> [ 1876.624698] RSP: 002b:00007ffe7908ce88 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
> [ 1876.628290] RAX: ffffffffffffffda RBX: 000055ad65d1f9c0 RCX: 00007fe056a840c4
> [ 1876.630922] RDX: 00007fe0563e1c7c RSI: 0000000000000003 RDI: 0000000000000017
> [ 1876.634244] RBP: 00007fe0563e1c60 R08: 0000000000000005 R09: 0000000000000002
> [ 1876.637153] R10: 000055ad65d1a010 R11: 0000000000000246 R12: 0000000000000002
> [ 1876.640099] R13: 00000000fffffff0 R14: 0000000000000002 R15: 00007ffe7908d2e0
> ===
>
> And what's more important, I can make smartctl hang too!
>
> ===
> [ 1876.466385] smartctl        D    0 14891    495 0x00000000
> [ 1876.469100] Call Trace:
> [ 1876.471267]  ? __schedule+0x336/0xf40
> [ 1876.473541]  ? blk_mq_sched_dispatch_requests+0x117/0x190
> [ 1876.476331]  ? __sbitmap_get_word+0x2a/0x80
> [ 1876.478784]  ? sbitmap_get_shallow+0x5c/0xa0
> [ 1876.481353]  schedule+0x32/0xc0
> [ 1876.484412]  io_schedule+0x12/0x40
> [ 1876.486892]  blk_mq_get_tag+0x181/0x2a0
> [ 1876.489448]  ? wait_woken+0x80/0x80
> [ 1876.492018]  blk_mq_get_request+0xf9/0x400
> [ 1876.497734]  ? lookup_fast+0xc8/0x2d0
> [ 1876.501050]  blk_mq_alloc_request+0x7e/0xe0
> [ 1876.503705]  blk_get_request_flags+0x40/0x160
> [ 1876.506306]  sg_io+0x9d/0x3f0
> [ 1876.507920]  ? path_lookupat+0xaa/0x1f0
> [ 1876.509750]  ? current_time+0x18/0x70
> [ 1876.511496]  scsi_cmd_ioctl+0x257/0x410
> [ 1876.513151]  ? xfs_bmapi_read+0x1c3/0x340 [xfs]
> [ 1876.515355]  sd_ioctl+0xbf/0x1a0 [sd_mod]
> [ 1876.517638]  blkdev_ioctl+0x8ca/0x990
> [ 1876.519219]  ? read_null+0x10/0x10
> [ 1876.520849]  block_ioctl+0x39/0x40
> [ 1876.522368]  do_vfs_ioctl+0xa4/0x630
> [ 1876.524490]  ? vfs_write+0x164/0x1a0
> [ 1876.526841]  SyS_ioctl+0x74/0x80
> [ 1876.528328]  do_syscall_64+0x74/0x190
> [ 1876.529886]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
> [ 1876.537471] RIP: 0033:0x7f4f232c8d87
> [ 1876.540388] RSP: 002b:00007ffd0fe530a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> [ 1876.545738] RAX: ffffffffffffffda RBX: 00007ffd0fe53350 RCX: 00007f4f232c8d87
> [ 1876.548950] RDX: 00007ffd0fe530c0 RSI: 0000000000002285 RDI: 0000000000000003
> [ 1876.552912] RBP: 00007ffd0fe533a0 R08: 0000000000000010 R09: 00007ffd0fe53980
> [ 1876.559750] R10: 0000000000000200 R11: 0000000000000246 R12: 000055e98902dce0
> [ 1876.563829] R13: 0000000000000000 R14: 000055e989027550 R15: 00000000000000d0
> ===
>
> Workqueues, also from alt+sysrq+t dump:
>
> ===
> [ 1876.676508] Showing busy workqueues and worker pools:
> [ 1876.681916] workqueue events_power_efficient: flags=0x82
> [ 1876.685388]   pwq 8: cpus=0-3 flags=0x4 nice=0 active=2/256
> [ 1876.688962]     pending: fb_flashcursor, neigh_periodic_work
> [ 1876.694414] workqueue events_freezable_power_: flags=0x86
> [ 1876.699262]   pwq 8: cpus=0-3 flags=0x4 nice=0 active=1/256
> [ 1876.703777]     pending: disk_events_workfn
> [ 1876.707279] workqueue dm-thin: flags=0xa000a
> [ 1876.709053]   pwq 8: cpus=0-3 flags=0x4 nice=0 active=1/1
> [ 1876.715598]     pending: do_waker [dm_thin_pool]
> ===
>
> So far, I can reproduce it only with blk-mq *and* BFQ enabled. I've switched another machine (my server) to Kyber, and I do not observe the issue (so far, at least).

Two other questions, since you can reproduce this easily:

- does it reproduce _without_ hardened usercopy? (I would assume yes,
but you'd just not get any warning until the hangs started.) If it
does reproduce without hardened usercopy, then a new bisect run could
narrow the search even more.

- does it reproduce with Linus's current tree?

> Paolo, Jens? I don't know whom to address, actually :(. Can someone give me an idea on this please?
>
>> The thing I can't figure out is how req->sense is slipping forward in
>> (and even beyond!) the allocation.
>
> *cough* race condition *cough*

What would imply missing locking, yes? Yikes. But I'd expect
use-after-free or something, or bad data, not having the pointer slip
forward?

-Kees

-- 
Kees Cook
Pixel Security