INFO: task hung in usb_bulk_msg

INFO: task hung in usb_bulk_msg

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit:    b36fdc6853a3 Merge tag 'gpio-v4.19-2' of git://git.kernel...
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=143a64d1400000
kernel config:  https://syzkaller.appspot.com/x/.config?x=6c9564cd177daf0c
dashboard link: https://syzkaller.appspot.com/bug?extid=7a7613e5ba9ae7bd15f9
compiler:       gcc (GCC) 8.0.1 20180413 (experimental)

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

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+7a7613e5ba9ae7bd15f9@syzkaller.appspotmail.com

INFO: task syz-executor3:10234 blocked for more than 140 seconds.
       Not tainted 4.19.0-rc2+ #3
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor3   D23224 10234   7516 0x00000004
Call Trace:
  context_switch kernel/sched/core.c:2825 [inline]
  __schedule+0x87c/0x1df0 kernel/sched/core.c:3473
  schedule+0xfb/0x450 kernel/sched/core.c:3517
  schedule_timeout+0x1cc/0x260 kernel/time/timer.c:1780
  do_wait_for_common kernel/sched/completion.c:83 [inline]
  __wait_for_common kernel/sched/completion.c:104 [inline]
  wait_for_common kernel/sched/completion.c:115 [inline]
  wait_for_completion_timeout+0x45f/0x960 kernel/sched/completion.c:155
  usb_start_wait_urb+0x18b/0x360 drivers/usb/core/message.c:62
  usb_bulk_msg+0x22e/0x550 drivers/usb/core/message.c:253
  proc_bulk+0x590/0xaa0 drivers/usb/core/devio.c:1193
  usbdev_do_ioctl+0x19fc/0x3b30 drivers/usb/core/devio.c:2401
  usbdev_ioctl+0x25/0x30 drivers/usb/core/devio.c:2551
  vfs_ioctl fs/ioctl.c:46 [inline]
  file_ioctl fs/ioctl.c:501 [inline]
  do_vfs_ioctl+0x1de/0x1720 fs/ioctl.c:685
  ksys_ioctl+0xa9/0xd0 fs/ioctl.c:702
  __do_sys_ioctl fs/ioctl.c:709 [inline]
  __se_sys_ioctl fs/ioctl.c:707 [inline]
  __x64_sys_ioctl+0x73/0xb0 fs/ioctl.c:707
  do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
  entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x457099
Code: Bad RIP value.
RSP: 002b:00007f408a01ec78 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f408a01f6d4 RCX: 0000000000457099
RDX: 0000000020000240 RSI: 00000000c0185502 RDI: 0000000000000003
RBP: 00000000009300a0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 00000000004cebc0 R14: 00000000004c503e R15: 0000000000000000

Showing all locks held in the system:
1 lock held by khungtaskd/792:
  #0: 00000000935370f1 (rcu_read_lock){....}, at:  
debug_show_all_locks+0xd0/0x428 kernel/locking/lockdep.c:4436
1 lock held by rsyslogd/4545:
2 locks held by getty/4666:
  #0: 000000001c78bb1f (&tty->ldisc_sem){++++}, at:  
ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:353
  #1: 00000000fd476690 (&ldata->atomic_read_lock){+.+.}, at:  
n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4667:
  #0: 000000003636bd05 (&tty->ldisc_sem){++++}, at:  
ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:353
  #1: 0000000080b0e131 (&ldata->atomic_read_lock){+.+.}, at:  
n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4668:
  #0: 00000000784da20e (&tty->ldisc_sem){++++}, at:  
ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:353
  #1: 00000000f35d11ec (&ldata->atomic_read_lock){+.+.}, at:  
n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4669:
  #0: 0000000050e62864 (&tty->ldisc_sem){++++}, at:  
ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:353
  #1: 0000000013be2de2 (&ldata->atomic_read_lock){+.+.}, at:  
n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4670:
  #0: 0000000076405ad8 (&tty->ldisc_sem){++++}, at:  
ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:353
  #1: 000000006c5d932d (&ldata->atomic_read_lock){+.+.}, at:  
n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4671:
  #0: 00000000a94de6ea (&tty->ldisc_sem){++++}, at:  
ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:353
  #1: 000000004906f867 (&ldata->atomic_read_lock){+.+.}, at:  
n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140
2 locks held by getty/4672:
  #0: 00000000664d51ab (&tty->ldisc_sem){++++}, at:  
ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:353
  #1: 00000000cdc5bd8f (&ldata->atomic_read_lock){+.+.}, at:  
n_tty_read+0x335/0x1ce0 drivers/tty/n_tty.c:2140

=============================================

NMI backtrace for cpu 0
CPU: 0 PID: 792 Comm: khungtaskd Not tainted 4.19.0-rc2+ #3
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS  
Google 01/01/2011
Call Trace:
  __dump_stack lib/dump_stack.c:77 [inline]
  dump_stack+0x1c9/0x2b4 lib/dump_stack.c:113
  nmi_cpu_backtrace.cold.3+0x48/0x88 lib/nmi_backtrace.c:101
  nmi_trigger_cpumask_backtrace+0x151/0x192 lib/nmi_backtrace.c:62
  arch_trigger_cpumask_backtrace+0x14/0x20 arch/x86/kernel/apic/hw_nmi.c:38
  trigger_all_cpu_backtrace include/linux/nmi.h:144 [inline]
  check_hung_uninterruptible_tasks kernel/hung_task.c:204 [inline]
  watchdog+0xb39/0x1040 kernel/hung_task.c:265
  kthread+0x35a/0x420 kernel/kthread.c:246
  ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:413
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.19.0-rc2+ #3
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS  
Google 01/01/2011
RIP: 0010:__wrmsr arch/x86/include/asm/msr.h:105 [inline]
RIP: 0010:native_apic_msr_eoi_write+0xf/0x20 arch/x86/include/asm/apic.h:214
Code: ff ff e9 13 ff ff ff e8 9f 8f 87 00 e9 de fe ff ff e8 35 58 13 00 90  
90 90 90 90 55 31 c0 b9 0b 08 00 00 89 c2 48 89 e5 0f 30 <5d> c3 0f 1f 44  
00 00 66 2e 0f 1f 84 00 00 00 00 00 c3 0f 1f 44 00
RSP: 0018:ffff8801db107e90 EFLAGS: 00000046
RAX: 0000000000000000 RBX: 1ffff1003b620fd4 RCX: 000000000000080b
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 00000000000000b0
RBP: ffff8801db107e90 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff87f2d300
R13: ffff8801db107fc0 R14: 0000000000000000 R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffff8801db100000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: ffffffffff600400 CR3: 00000001b7c96000 CR4: 00000000001406e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
  <IRQ>
  apic_eoi arch/x86/include/asm/apic.h:402 [inline]
  ack_APIC_irq arch/x86/include/asm/apic.h:448 [inline]
  smp_reschedule_interrupt+0xe4/0x5e0 arch/x86/kernel/smp.c:262
  reschedule_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:888
  </IRQ>
RIP: 0010:native_safe_halt+0x6/0x10 arch/x86/include/asm/irqflags.h:57
Code: c7 48 89 45 d8 e8 fa fc e4 fa 48 8b 45 d8 e9 d2 fe ff ff 48 89 df e8  
e9 fc e4 fa eb 8a 90 90 90 90 90 90 90 55 48 89 e5 fb f4 <5d> c3 0f 1f 84  
00 00 00 00 00 55 48 89 e5 f4 5d c3 90 90 90 90 90
RSP: 0018:ffff8801d9f27c30 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff02
RAX: dffffc0000000000 RBX: 1ffff1003b3e4f8a RCX: 0000000000000000
RDX: 1ffffffff10237c8 RSI: 0000000000000001 RDI: ffffffff8811be40
RBP: ffff8801d9f27c30 R08: ffff8801d9f1a380 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000001
R13: ffff8801d9f27cf0 R14: 0000000000000001 R15: 0000000000000000
  arch_safe_halt arch/x86/include/asm/paravirt.h:94 [inline]
  default_idle+0xc2/0x410 arch/x86/kernel/process.c:498
  arch_cpu_idle+0x10/0x20 arch/x86/kernel/process.c:489
  default_idle_call+0x6d/0x90 kernel/sched/idle.c:93
  cpuidle_idle_call kernel/sched/idle.c:153 [inline]
  do_idle+0x3aa/0x580 kernel/sched/idle.c:262
  cpu_startup_entry+0x10c/0x120 kernel/sched/idle.c:368
  start_secondary+0x433/0x5d0 arch/x86/kernel/smpboot.c:271
  secondary_startup_64+0xa4/0xb0 arch/x86/kernel/head_64.S:242


---
This bug 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 syzkaller@googlegroups.com.

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

Re: INFO: task hung in usb_bulk_msg

[syzbot]

syzbot has found a reproducer for the following issue on:

HEAD commit:    15bc20c6 Merge tag 'tty-5.9-rc3' of git://git.kernel.org/p..
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=1052a669900000
kernel config:  https://syzkaller.appspot.com/x/.config?x=978db74cb30aa994
dashboard link: https://syzkaller.appspot.com/bug?extid=7a7613e5ba9ae7bd15f9
compiler:       gcc (GCC) 10.1.0-syz 20200507
syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=101c328e900000
C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=155eff41900000

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

INFO: task syz-executor790:9958 blocked for more than 143 seconds.
      Not tainted 5.9.0-rc2-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor790 state:D stack:28240 pid: 9958 ppid:  6854 flags:0x00004004
Call Trace:
 context_switch kernel/sched/core.c:3778 [inline]
 __schedule+0x8e5/0x21e0 kernel/sched/core.c:4527
 schedule+0xd0/0x2a0 kernel/sched/core.c:4602
 schedule_timeout+0x1d8/0x250 kernel/time/timer.c:1855
 do_wait_for_common kernel/sched/completion.c:85 [inline]
 __wait_for_common kernel/sched/completion.c:106 [inline]
 wait_for_common kernel/sched/completion.c:117 [inline]
 wait_for_completion_timeout+0x15e/0x270 kernel/sched/completion.c:157
 usb_start_wait_urb+0x144/0x2b0 drivers/usb/core/message.c:63
 usb_bulk_msg+0x226/0x550 drivers/usb/core/message.c:254
 do_proc_bulk+0x39b/0x710 drivers/usb/core/devio.c:1231
 proc_bulk drivers/usb/core/devio.c:1268 [inline]
 usbdev_do_ioctl drivers/usb/core/devio.c:2542 [inline]
 usbdev_ioctl+0x586/0x3360 drivers/usb/core/devio.c:2708
 vfs_ioctl fs/ioctl.c:48 [inline]
 __do_sys_ioctl fs/ioctl.c:753 [inline]
 __se_sys_ioctl fs/ioctl.c:739 [inline]
 __x64_sys_ioctl+0x193/0x200 fs/ioctl.c:739
 do_syscall_64+0x2d/0x70 arch/x86/entry/common.c:46
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x44d089
Code: Bad RIP value.
RSP: 002b:00007f70887dadb8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00000000006dec48 RCX: 000000000044d089
RDX: 0000000020000000 RSI: 00000000c0185502 RDI: 0000000000000003
RBP: 00000000006dec40 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000006dec4c
R13: 00007ffebdfc131f R14: 00007f70887db9c0 R15: 0000000000000064

Showing all locks held in the system:
1 lock held by ksoftirqd/1/16:
 #0: ffff8880ae735e18 (&rq->lock){-.-.}-{2:2}, at: rq_lock kernel/sched/sched.h:1292 [inline]
 #0: ffff8880ae735e18 (&rq->lock){-.-.}-{2:2}, at: __schedule+0x232/0x21e0 kernel/sched/core.c:4445
1 lock held by khungtaskd/1169:
 #0: ffffffff89bd6900 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x53/0x260 kernel/locking/lockdep.c:5825
1 lock held by in:imklog/6531:
 #0: ffff8880a83bab70 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xe9/0x100 fs/file.c:930
3 locks held by kworker/u4:0/6882:
1 lock held by syz-executor790/24330:
 #0: ffff8880ae635e18 (&rq->lock){-.-.}-{2:2}, at: rq_lock kernel/sched/sched.h:1292 [inline]
 #0: ffff8880ae635e18 (&rq->lock){-.-.}-{2:2}, at: __schedule+0x232/0x21e0 kernel/sched/core.c:4445

=============================================

NMI backtrace for cpu 0
CPU: 0 PID: 1169 Comm: khungtaskd Not tainted 5.9.0-rc2-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x18f/0x20d lib/dump_stack.c:118
 nmi_cpu_backtrace.cold+0x70/0xb1 lib/nmi_backtrace.c:101
 nmi_trigger_cpumask_backtrace+0x1b3/0x223 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:209 [inline]
 watchdog+0xd7d/0x1000 kernel/hung_task.c:295
 kthread+0x3b5/0x4a0 kernel/kthread.c:292
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 6851 Comm: syz-executor790 Not tainted 5.9.0-rc2-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
RIP: 0010:get_timespec64+0x1b3/0x220 kernel/time/time.c:801
Code: 89 73 08 e8 8f f6 10 00 48 b8 00 00 00 00 00 fc ff df 49 c7 04 04 00 00 00 00 48 8b 44 24 58 65 48 2b 04 25 28 00 00 00 75 45 <48> 83 c4 60 44 89 e8 5b 5d 41 5c 41 5d 41 5e c3 e8 58 f6 10 00 45
RSP: 0018:ffffc90001667e20 EFLAGS: 00000246
RAX: 0000000000000000 RBX: ffffc90001667ed0 RCX: ffffffff81634853
RDX: ffff8880a77381c0 RSI: ffffffff81634881 RDI: ffffc90001667ed8
RBP: 0000000000000000 R08: 00000000000f4240 R09: ffffc90001667e4f
R10: 0000000000000000 R11: 0000000000000000 R12: 1ffff920002ccfc4
R13: 0000000000000000 R14: 00000000000f4240 R15: 0000000000000000
FS:  000000000153e880(0000) GS:ffff8880ae700000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000004c6238 CR3: 00000000a93cd000 CR4: 00000000001506e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 __do_sys_nanosleep kernel/time/hrtimer.c:1962 [inline]
 __se_sys_nanosleep kernel/time/hrtimer.c:1957 [inline]
 __x64_sys_nanosleep+0xaa/0x260 kernel/time/hrtimer.c:1957
 do_syscall_64+0x2d/0x70 arch/x86/entry/common.c:46
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x44b800
Code: c0 5b 5d c3 66 0f 1f 44 00 00 8b 04 24 48 83 c4 18 5b 5d c3 66 0f 1f 44 00 00 83 3d b1 a0 29 00 00 75 14 b8 23 00 00 00 0f 05 <48> 3d 01 f0 ff ff 0f 83 24 e4 fb ff c3 48 83 ec 08 e8 7a 43 00 00
RSP: 002b:00007ffebdfc1378 EFLAGS: 00000246 ORIG_RAX: 0000000000000023
RAX: ffffffffffffffda RBX: 00000000000025c4 RCX: 000000000044b800
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 00007ffebdfc1380
RBP: 000000000009bbed R08: 0000000000000001 R09: 000000000153e880
R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffebdfc13e0
R13: 000000000040a140 R14: 0000000000000000 R15: 0000000000000000

Re: INFO: task hung in usb_bulk_msg

[Andy Shevchenko]

On Fri, Aug 28, 2020 at 05:52:16AM -0700, syzbot wrote:
> syzbot has found a reproducer for the following issue on:
> 
> HEAD commit:    15bc20c6 Merge tag 'tty-5.9-rc3' of git://git.kernel.org/p..
> git tree:       upstream
> console output: https://syzkaller.appspot.com/x/log.txt?x=1052a669900000
> kernel config:  https://syzkaller.appspot.com/x/.config?x=978db74cb30aa994
> dashboard link: https://syzkaller.appspot.com/bug?extid=7a7613e5ba9ae7bd15f9
> compiler:       gcc (GCC) 10.1.0-syz 20200507
> syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=101c328e900000
> C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=155eff41900000
> 
> IMPORTANT: if you fix the issue, please add the following tag to the commit:
> Reported-by: syzbot+7a7613e5ba9ae7bd15f9@syzkaller.appspotmail.com

I have had hard times to understand the link between tty subsystem and this
report. Also I'm wondering how 'Maintainers' column is formed in the dashboard
view. And how the Cc list of this message in particular.

-- 
With Best Regards,
Andy Shevchenko

Re: INFO: task hung in usb_bulk_msg

[Alan Stern]

On Fri, Aug 28, 2020 at 05:52:16AM -0700, syzbot wrote:
> syzbot has found a reproducer for the following issue on:
> 
> HEAD commit:    15bc20c6 Merge tag 'tty-5.9-rc3' of git://git.kernel.org/p..
> git tree:       upstream
> console output: https://syzkaller.appspot.com/x/log.txt?x=1052a669900000
> kernel config:  https://syzkaller.appspot.com/x/.config?x=978db74cb30aa994
> dashboard link: https://syzkaller.appspot.com/bug?extid=7a7613e5ba9ae7bd15f9
> compiler:       gcc (GCC) 10.1.0-syz 20200507
> syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=101c328e900000
> C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=155eff41900000
> 
> IMPORTANT: if you fix the issue, please add the following tag to the commit:
> Reported-by: syzbot+7a7613e5ba9ae7bd15f9@syzkaller.appspotmail.com
> 
> INFO: task syz-executor790:9958 blocked for more than 143 seconds.
>       Not tainted 5.9.0-rc2-syzkaller #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:syz-executor790 state:D stack:28240 pid: 9958 ppid:  6854 flags:0x00004004
> Call Trace:
>  context_switch kernel/sched/core.c:3778 [inline]
>  __schedule+0x8e5/0x21e0 kernel/sched/core.c:4527
>  schedule+0xd0/0x2a0 kernel/sched/core.c:4602
>  schedule_timeout+0x1d8/0x250 kernel/time/timer.c:1855
>  do_wait_for_common kernel/sched/completion.c:85 [inline]
>  __wait_for_common kernel/sched/completion.c:106 [inline]
>  wait_for_common kernel/sched/completion.c:117 [inline]
>  wait_for_completion_timeout+0x15e/0x270 kernel/sched/completion.c:157
>  usb_start_wait_urb+0x144/0x2b0 drivers/usb/core/message.c:63
>  usb_bulk_msg+0x226/0x550 drivers/usb/core/message.c:254
>  do_proc_bulk+0x39b/0x710 drivers/usb/core/devio.c:1231
>  proc_bulk drivers/usb/core/devio.c:1268 [inline]
>  usbdev_do_ioctl drivers/usb/core/devio.c:2542 [inline]
>  usbdev_ioctl+0x586/0x3360 drivers/usb/core/devio.c:2708

I'm confused about this bug report.

Here's the syz reproducer from the link listed above:

# 
https://syzkaller.appspot.com/bug?id=bf172344c5f1d3487a4feff67c3dd30e08d5b635
# See https://goo.gl/kgGztJ for information about syzkaller reproducers.
#{"threaded":true,"repeat":true,"procs":6,"sandbox":"none","fault_call":-1,"netdev":true,"close_fds":true}
r0 = syz_open_dev$usbfs(&(0x7f0000000040)='/dev/bus/usb/00#/00#\x00', 
0x4000000000000071, 0x28081)
r1 = socket$inet6(0xa, 0x2, 0x0)
r2 = dup(r1)
ioctl$PERF_EVENT_IOC_ENABLE(r2, 0x8912, 0x400200)
socketpair$unix(0x1, 0x0, 0x0, &(0x7f0000000000))
ioctl$USBDEVFS_CONTROL(r0, 0x8108551b, &(0x7f0000001140)={0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0})
ioctl$USBDEVFS_CLEAR_HALT(r0, 0xc0185502, &(0x7f0000000000)={0x1, 0x1})

As far as I can see, the only USB ioctls used in this test are 
USBDEVFS_CONTROL and USBDEVFS_CLEAR_HALT.  Neither of those calls 
do_proc_bulk() or usb_bulk_msg(), so how did those routines end up in 
the stack trace?

In fact, do_proc_bulk() is called only for USBDEVFS_BULK.  But the test 
doesn't use that ioctl!

What's going on?  Am I missing part of the test?

Alan Stern

Re: INFO: task hung in usb_bulk_msg

[Andrey Konovalov]

On Sat, Aug 29, 2020 at 3:24 AM Alan Stern <stern@rowland.harvard.edu> wrote:
>
> On Fri, Aug 28, 2020 at 05:52:16AM -0700, syzbot wrote:
> > syzbot has found a reproducer for the following issue on:
> >
> > HEAD commit:    15bc20c6 Merge tag 'tty-5.9-rc3' of git://git.kernel.org/p..
> > git tree:       upstream
> > console output: https://syzkaller.appspot.com/x/log.txt?x=1052a669900000
> > kernel config:  https://syzkaller.appspot.com/x/.config?x=978db74cb30aa994
> > dashboard link: https://syzkaller.appspot.com/bug?extid=7a7613e5ba9ae7bd15f9
> > compiler:       gcc (GCC) 10.1.0-syz 20200507
> > syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=101c328e900000
> > C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=155eff41900000
> >
> > IMPORTANT: if you fix the issue, please add the following tag to the commit:
> > Reported-by: syzbot+7a7613e5ba9ae7bd15f9@syzkaller.appspotmail.com
> >
> > INFO: task syz-executor790:9958 blocked for more than 143 seconds.
> >       Not tainted 5.9.0-rc2-syzkaller #0
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > task:syz-executor790 state:D stack:28240 pid: 9958 ppid:  6854 flags:0x00004004
> > Call Trace:
> >  context_switch kernel/sched/core.c:3778 [inline]
> >  __schedule+0x8e5/0x21e0 kernel/sched/core.c:4527
> >  schedule+0xd0/0x2a0 kernel/sched/core.c:4602
> >  schedule_timeout+0x1d8/0x250 kernel/time/timer.c:1855
> >  do_wait_for_common kernel/sched/completion.c:85 [inline]
> >  __wait_for_common kernel/sched/completion.c:106 [inline]
> >  wait_for_common kernel/sched/completion.c:117 [inline]
> >  wait_for_completion_timeout+0x15e/0x270 kernel/sched/completion.c:157
> >  usb_start_wait_urb+0x144/0x2b0 drivers/usb/core/message.c:63
> >  usb_bulk_msg+0x226/0x550 drivers/usb/core/message.c:254
> >  do_proc_bulk+0x39b/0x710 drivers/usb/core/devio.c:1231
> >  proc_bulk drivers/usb/core/devio.c:1268 [inline]
> >  usbdev_do_ioctl drivers/usb/core/devio.c:2542 [inline]
> >  usbdev_ioctl+0x586/0x3360 drivers/usb/core/devio.c:2708
>
> I'm confused about this bug report.
>
> Here's the syz reproducer from the link listed above:
>
> #
> https://syzkaller.appspot.com/bug?id=bf172344c5f1d3487a4feff67c3dd30e08d5b635
> # See https://goo.gl/kgGztJ for information about syzkaller reproducers.
> #{"threaded":true,"repeat":true,"procs":6,"sandbox":"none","fault_call":-1,"netdev":true,"close_fds":true}
> r0 = syz_open_dev$usbfs(&(0x7f0000000040)='/dev/bus/usb/00#/00#\x00',
> 0x4000000000000071, 0x28081)
> r1 = socket$inet6(0xa, 0x2, 0x0)
> r2 = dup(r1)
> ioctl$PERF_EVENT_IOC_ENABLE(r2, 0x8912, 0x400200)
> socketpair$unix(0x1, 0x0, 0x0, &(0x7f0000000000))
> ioctl$USBDEVFS_CONTROL(r0, 0x8108551b, &(0x7f0000001140)={0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0})
> ioctl$USBDEVFS_CLEAR_HALT(r0, 0xc0185502, &(0x7f0000000000)={0x1, 0x1})
>
> As far as I can see, the only USB ioctls used in this test are
> USBDEVFS_CONTROL and USBDEVFS_CLEAR_HALT.  Neither of those calls
> do_proc_bulk() or usb_bulk_msg(), so how did those routines end up in
> the stack trace?
>
> In fact, do_proc_bulk() is called only for USBDEVFS_BULK.  But the test
> doesn't use that ioctl!
>
> What's going on?  Am I missing part of the test?

Hi Alan,

Yeah, it's a bit confusing, sorry for that. Since syzkaller mutates
the values that are passed into syscalls, it might mutate the cmd
value of an ioctl. This results in a mismatch between the name of a
syscall in syzkaller's notation, and the actual cmd value. In this
case we have:

ioctl$USBDEVFS_CONTROL(r0, 0x8108551b, ...)

where 0x8108551b == 2164806939, which is the value for
USBDEVFS_DISCONNECT_CLAIM [1], and

ioctl$USBDEVFS_CLEAR_HALT(r0, 0xc0185502, ...)

where 0xc0185502 == 3222820098, which is the value for USBDEVFS_BULK [2].

I remember Dmitry did some changes to this part, but I think syzkaller
only avoids getting disabled ioctls during mutations. Dmitry, maybe it
would make sense to avoid getting other known ioctls during mutations?

Thanks!

[1] https://github.com/google/syzkaller/blob/master/sys/linux/dev_bus_usb.txt.const#L13
[2] https://github.com/google/syzkaller/blob/master/sys/linux/dev_bus_usb.txt.const#L4

Re: INFO: task hung in usb_bulk_msg

[Dmitry Vyukov]

On Mon, Aug 31, 2020 at 3:08 PM 'Andrey Konovalov' via syzkaller-bugs
<syzkaller-bugs@googlegroups.com> wrote:
>
> On Sat, Aug 29, 2020 at 3:24 AM Alan Stern <stern@rowland.harvard.edu> wrote:
> >
> > On Fri, Aug 28, 2020 at 05:52:16AM -0700, syzbot wrote:
> > > syzbot has found a reproducer for the following issue on:
> > >
> > > HEAD commit:    15bc20c6 Merge tag 'tty-5.9-rc3' of git://git.kernel.org/p..
> > > git tree:       upstream
> > > console output: https://syzkaller.appspot.com/x/log.txt?x=1052a669900000
> > > kernel config:  https://syzkaller.appspot.com/x/.config?x=978db74cb30aa994
> > > dashboard link: https://syzkaller.appspot.com/bug?extid=7a7613e5ba9ae7bd15f9
> > > compiler:       gcc (GCC) 10.1.0-syz 20200507
> > > syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=101c328e900000
> > > C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=155eff41900000
> > >
> > > IMPORTANT: if you fix the issue, please add the following tag to the commit:
> > > Reported-by: syzbot+7a7613e5ba9ae7bd15f9@syzkaller.appspotmail.com
> > >
> > > INFO: task syz-executor790:9958 blocked for more than 143 seconds.
> > >       Not tainted 5.9.0-rc2-syzkaller #0
> > > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > > task:syz-executor790 state:D stack:28240 pid: 9958 ppid:  6854 flags:0x00004004
> > > Call Trace:
> > >  context_switch kernel/sched/core.c:3778 [inline]
> > >  __schedule+0x8e5/0x21e0 kernel/sched/core.c:4527
> > >  schedule+0xd0/0x2a0 kernel/sched/core.c:4602
> > >  schedule_timeout+0x1d8/0x250 kernel/time/timer.c:1855
> > >  do_wait_for_common kernel/sched/completion.c:85 [inline]
> > >  __wait_for_common kernel/sched/completion.c:106 [inline]
> > >  wait_for_common kernel/sched/completion.c:117 [inline]
> > >  wait_for_completion_timeout+0x15e/0x270 kernel/sched/completion.c:157
> > >  usb_start_wait_urb+0x144/0x2b0 drivers/usb/core/message.c:63
> > >  usb_bulk_msg+0x226/0x550 drivers/usb/core/message.c:254
> > >  do_proc_bulk+0x39b/0x710 drivers/usb/core/devio.c:1231
> > >  proc_bulk drivers/usb/core/devio.c:1268 [inline]
> > >  usbdev_do_ioctl drivers/usb/core/devio.c:2542 [inline]
> > >  usbdev_ioctl+0x586/0x3360 drivers/usb/core/devio.c:2708
> >
> > I'm confused about this bug report.
> >
> > Here's the syz reproducer from the link listed above:
> >
> > #
> > https://syzkaller.appspot.com/bug?id=bf172344c5f1d3487a4feff67c3dd30e08d5b635
> > # See https://goo.gl/kgGztJ for information about syzkaller reproducers.
> > #{"threaded":true,"repeat":true,"procs":6,"sandbox":"none","fault_call":-1,"netdev":true,"close_fds":true}
> > r0 = syz_open_dev$usbfs(&(0x7f0000000040)='/dev/bus/usb/00#/00#\x00',
> > 0x4000000000000071, 0x28081)
> > r1 = socket$inet6(0xa, 0x2, 0x0)
> > r2 = dup(r1)
> > ioctl$PERF_EVENT_IOC_ENABLE(r2, 0x8912, 0x400200)
> > socketpair$unix(0x1, 0x0, 0x0, &(0x7f0000000000))
> > ioctl$USBDEVFS_CONTROL(r0, 0x8108551b, &(0x7f0000001140)={0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0})
> > ioctl$USBDEVFS_CLEAR_HALT(r0, 0xc0185502, &(0x7f0000000000)={0x1, 0x1})
> >
> > As far as I can see, the only USB ioctls used in this test are
> > USBDEVFS_CONTROL and USBDEVFS_CLEAR_HALT.  Neither of those calls
> > do_proc_bulk() or usb_bulk_msg(), so how did those routines end up in
> > the stack trace?
> >
> > In fact, do_proc_bulk() is called only for USBDEVFS_BULK.  But the test
> > doesn't use that ioctl!
> >
> > What's going on?  Am I missing part of the test?
>
> Hi Alan,
>
> Yeah, it's a bit confusing, sorry for that. Since syzkaller mutates
> the values that are passed into syscalls, it might mutate the cmd
> value of an ioctl. This results in a mismatch between the name of a
> syscall in syzkaller's notation, and the actual cmd value. In this
> case we have:
>
> ioctl$USBDEVFS_CONTROL(r0, 0x8108551b, ...)
>
> where 0x8108551b == 2164806939, which is the value for
> USBDEVFS_DISCONNECT_CLAIM [1], and
>
> ioctl$USBDEVFS_CLEAR_HALT(r0, 0xc0185502, ...)
>
> where 0xc0185502 == 3222820098, which is the value for USBDEVFS_BULK [2].
>
> I remember Dmitry did some changes to this part, but I think syzkaller
> only avoids getting disabled ioctls during mutations. Dmitry, maybe it
> would make sense to avoid getting other known ioctls during mutations?

Agree, it would make sense. I've started working on it but wasn't able
to finish. It also affects get/setsockopt, fcntl, prctl, bpf and
others. In this more general context it turns out to be an interesting
problem figuring out what is that exactly we don't want to mutate and
to what values.