Re: [syzbot] INFO: task hung in port100_probe

[Krzysztof Kozlowski <krzysztof.kozlowski@canonical.com>]

On 22/06/2021 17:43, syzbot wrote:
> Hello,
> 
> syzbot found the following issue on:
> 
> HEAD commit:    fd0aa1a4 Merge tag 'for-linus' of git://git.kernel.org/pub..
> git tree:       upstream
> console output: https://syzkaller.appspot.com/x/log.txt?x=13e1500c300000
> kernel config:  https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
> dashboard link: https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869
> syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=1792e284300000
> C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=13ad9d48300000
> 
> IMPORTANT: if you fix the issue, please add the following tag to the commit:
> Reported-by: syzbot+abd2e0dafb481b621869@syzkaller.appspotmail.com
> 
> INFO: task kworker/0:1:7 blocked for more than 143 seconds.
>       Not tainted 5.13.0-rc6-syzkaller #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:kworker/0:1     state:D stack:25584 pid:    7 ppid:     2 flags:0x00004000
> Workqueue: usb_hub_wq hub_event
> Call Trace:
>  context_switch kernel/sched/core.c:4339 [inline]
>  __schedule+0x916/0x23e0 kernel/sched/core.c:5147
>  schedule+0xcf/0x270 kernel/sched/core.c:5226
>  schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
>  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+0x168/0x270 kernel/sched/completion.c:138
>  port100_send_cmd_sync drivers/nfc/port100.c:923 [inline]
>  port100_get_command_type_mask drivers/nfc/port100.c:1008 [inline]
>  port100_probe+0x9e4/0x1340 drivers/nfc/port100.c:1554
>  usb_probe_interface+0x315/0x7f0 drivers/usb/core/driver.c:396
>  really_probe+0x291/0xf60 drivers/base/dd.c:576
>  driver_probe_device+0x298/0x410 drivers/base/dd.c:763
>  __device_attach_driver+0x203/0x2c0 drivers/base/dd.c:870
>  bus_for_each_drv+0x15f/0x1e0 drivers/base/bus.c:431
>  __device_attach+0x228/0x4b0 drivers/base/dd.c:938
>  bus_probe_device+0x1e4/0x290 drivers/base/bus.c:491
>  device_add+0xbe0/0x2100 drivers/base/core.c:3324
>  usb_set_configuration+0x113f/0x1910 drivers/usb/core/message.c:2164
>  usb_generic_driver_probe+0xba/0x100 drivers/usb/core/generic.c:238
>  usb_probe_device+0xd9/0x2c0 drivers/usb/core/driver.c:293
>  really_probe+0x291/0xf60 drivers/base/dd.c:576
>  driver_probe_device+0x298/0x410 drivers/base/dd.c:763
>  __device_attach_driver+0x203/0x2c0 drivers/base/dd.c:870
>  bus_for_each_drv+0x15f/0x1e0 drivers/base/bus.c:431
>  __device_attach+0x228/0x4b0 drivers/base/dd.c:938
>  bus_probe_device+0x1e4/0x290 drivers/base/bus.c:491
>  device_add+0xbe0/0x2100 drivers/base/core.c:3324
>  usb_new_device.cold+0x721/0x1058 drivers/usb/core/hub.c:2556
>  hub_port_connect drivers/usb/core/hub.c:5276 [inline]
>  hub_port_connect_change drivers/usb/core/hub.c:5416 [inline]
>  port_event drivers/usb/core/hub.c:5562 [inline]
>  hub_event+0x2357/0x4330 drivers/usb/core/hub.c:5644
>  process_one_work+0x98d/0x1600 kernel/workqueue.c:2276
>  process_scheduled_works kernel/workqueue.c:2338 [inline]
>  worker_thread+0x82b/0x1120 kernel/workqueue.c:2424
>  kthread+0x3b1/0x4a0 kernel/kthread.c:313
>  ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
> INFO: task kworker/1:2:3367 blocked for more than 143 seconds.
>       Not tainted 5.13.0-rc6-syzkaller #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:kworker/1:2     state:D stack:25552 pid: 3367 ppid:     2 flags:0x00004000
> Workqueue: usb_hub_wq hub_event
> Call Trace:
>  context_switch kernel/sched/core.c:4339 [inline]
>  __schedule+0x916/0x23e0 kernel/sched/core.c:5147
>  schedule+0xcf/0x270 kernel/sched/core.c:5226
>  schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
>  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+0x168/0x270 kernel/sched/completion.c:138
>  port100_send_cmd_sync drivers/nfc/port100.c:923 [inline]
>  port100_get_command_type_mask drivers/nfc/port100.c:1008 [inline]
>  port100_probe+0x9e4/0x1340 drivers/nfc/port100.c:1554
>  usb_probe_interface+0x315/0x7f0 drivers/usb/core/driver.c:396
>  really_probe+0x291/0xf60 drivers/base/dd.c:576
>  driver_probe_device+0x298/0x410 drivers/base/dd.c:763
>  __device_attach_driver+0x203/0x2c0 drivers/base/dd.c:870
>  bus_for_each_drv+0x15f/0x1e0 drivers/base/bus.c:431
>  __device_attach+0x228/0x4b0 drivers/base/dd.c:938
>  bus_probe_device+0x1e4/0x290 drivers/base/bus.c:491
>  device_add+0xbe0/0x2100 drivers/base/core.c:3324
>  usb_set_configuration+0x113f/0x1910 drivers/usb/core/message.c:2164
>  usb_generic_driver_probe+0xba/0x100 drivers/usb/core/generic.c:238
>  usb_probe_device+0xd9/0x2c0 drivers/usb/core/driver.c:293
>  really_probe+0x291/0xf60 drivers/base/dd.c:576
>  driver_probe_device+0x298/0x410 drivers/base/dd.c:763
>  __device_attach_driver+0x203/0x2c0 drivers/base/dd.c:870
>  bus_for_each_drv+0x15f/0x1e0 drivers/base/bus.c:431
>  __device_attach+0x228/0x4b0 drivers/base/dd.c:938
>  bus_probe_device+0x1e4/0x290 drivers/base/bus.c:491
>  device_add+0xbe0/0x2100 drivers/base/core.c:3324
>  usb_new_device.cold+0x721/0x1058 drivers/usb/core/hub.c:2556
>  hub_port_connect drivers/usb/core/hub.c:5276 [inline]
>  hub_port_connect_change drivers/usb/core/hub.c:5416 [inline]
>  port_event drivers/usb/core/hub.c:5562 [inline]
>  hub_event+0x2357/0x4330 drivers/usb/core/hub.c:5644
>  process_one_work+0x98d/0x1600 kernel/workqueue.c:2276
>  process_scheduled_works kernel/workqueue.c:2338 [inline]
>  worker_thread+0x82b/0x1120 kernel/workqueue.c:2424
>  kthread+0x3b1/0x4a0 kernel/kthread.c:313
>  ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
> INFO: task kworker/1:3:4871 blocked for more than 144 seconds.
>       Not tainted 5.13.0-rc6-syzkaller #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:kworker/1:3     state:D stack:25584 pid: 4871 ppid:     2 flags:0x00004000
> Workqueue: usb_hub_wq hub_event
> Call Trace:
>  context_switch kernel/sched/core.c:4339 [inline]
>  __schedule+0x916/0x23e0 kernel/sched/core.c:5147
>  schedule+0xcf/0x270 kernel/sched/core.c:5226
>  schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
>  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+0x168/0x270 kernel/sched/completion.c:138
>  port100_send_cmd_sync drivers/nfc/port100.c:923 [inline]
>  port100_get_command_type_mask drivers/nfc/port100.c:1008 [inline]
>  port100_probe+0x9e4/0x1340 drivers/nfc/port100.c:1554
>  usb_probe_interface+0x315/0x7f0 drivers/usb/core/driver.c:396
>  really_probe+0x291/0xf60 drivers/base/dd.c:576
>  driver_probe_device+0x298/0x410 drivers/base/dd.c:763
>  __device_attach_driver+0x203/0x2c0 drivers/base/dd.c:870
>  bus_for_each_drv+0x15f/0x1e0 drivers/base/bus.c:431
>  __device_attach+0x228/0x4b0 drivers/base/dd.c:938
>  bus_probe_device+0x1e4/0x290 drivers/base/bus.c:491
>  device_add+0xbe0/0x2100 drivers/base/core.c:3324
>  usb_set_configuration+0x113f/0x1910 drivers/usb/core/message.c:2164
>  usb_generic_driver_probe+0xba/0x100 drivers/usb/core/generic.c:238
>  usb_probe_device+0xd9/0x2c0 drivers/usb/core/driver.c:293
>  really_probe+0x291/0xf60 drivers/base/dd.c:576
>  driver_probe_device+0x298/0x410 drivers/base/dd.c:763
>  __device_attach_driver+0x203/0x2c0 drivers/base/dd.c:870
>  bus_for_each_drv+0x15f/0x1e0 drivers/base/bus.c:431
>  __device_attach+0x228/0x4b0 drivers/base/dd.c:938
>  bus_probe_device+0x1e4/0x290 drivers/base/bus.c:491
>  device_add+0xbe0/0x2100 drivers/base/core.c:3324
>  usb_new_device.cold+0x721/0x1058 drivers/usb/core/hub.c:2556
>  hub_port_connect drivers/usb/core/hub.c:5276 [inline]
>  hub_port_connect_change drivers/usb/core/hub.c:5416 [inline]
>  port_event drivers/usb/core/hub.c:5562 [inline]
>  hub_event+0x2357/0x4330 drivers/usb/core/hub.c:5644
>  process_one_work+0x98d/0x1600 kernel/workqueue.c:2276
>  process_scheduled_works kernel/workqueue.c:2338 [inline]
>  worker_thread+0x82b/0x1120 kernel/workqueue.c:2424
>  kthread+0x3b1/0x4a0 kernel/kthread.c:313
>  ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
> INFO: task kworker/1:0:8456 blocked for more than 144 seconds.
>       Not tainted 5.13.0-rc6-syzkaller #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:kworker/1:0     state:D stack:25936 pid: 8456 ppid:     2 flags:0x00004000
> Workqueue: usb_hub_wq hub_event
> Call Trace:
>  context_switch kernel/sched/core.c:4339 [inline]
>  __schedule+0x916/0x23e0 kernel/sched/core.c:5147
>  schedule+0xcf/0x270 kernel/sched/core.c:5226
>  schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
>  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+0x168/0x270 kernel/sched/completion.c:138
>  port100_send_cmd_sync drivers/nfc/port100.c:923 [inline]
>  port100_get_command_type_mask drivers/nfc/port100.c:1008 [inline]
>  port100_probe+0x9e4/0x1340 drivers/nfc/port100.c:1554
>  usb_probe_interface+0x315/0x7f0 drivers/usb/core/driver.c:396
>  really_probe+0x291/0xf60 drivers/base/dd.c:576
>  driver_probe_device+0x298/0x410 drivers/base/dd.c:763
>  __device_attach_driver+0x203/0x2c0 drivers/base/dd.c:870
>  bus_for_each_drv+0x15f/0x1e0 drivers/base/bus.c:431
>  __device_attach+0x228/0x4b0 drivers/base/dd.c:938
>  bus_probe_device+0x1e4/0x290 drivers/base/bus.c:491
>  device_add+0xbe0/0x2100 drivers/base/core.c:3324
>  usb_set_configuration+0x113f/0x1910 drivers/usb/core/message.c:2164
>  usb_generic_driver_probe+0xba/0x100 drivers/usb/core/generic.c:238
>  usb_probe_device+0xd9/0x2c0 drivers/usb/core/driver.c:293
>  really_probe+0x291/0xf60 drivers/base/dd.c:576
>  driver_probe_device+0x298/0x410 drivers/base/dd.c:763
>  __device_attach_driver+0x203/0x2c0 drivers/base/dd.c:870
>  bus_for_each_drv+0x15f/0x1e0 drivers/base/bus.c:431
>  __device_attach+0x228/0x4b0 drivers/base/dd.c:938
>  bus_probe_device+0x1e4/0x290 drivers/base/bus.c:491
>  device_add+0xbe0/0x2100 drivers/base/core.c:3324
>  usb_new_device.cold+0x721/0x1058 drivers/usb/core/hub.c:2556
>  hub_port_connect drivers/usb/core/hub.c:5276 [inline]
>  hub_port_connect_change drivers/usb/core/hub.c:5416 [inline]
>  port_event drivers/usb/core/hub.c:5562 [inline]
>  hub_event+0x2357/0x4330 drivers/usb/core/hub.c:5644
>  process_one_work+0x98d/0x1600 kernel/workqueue.c:2276
>  process_scheduled_works kernel/workqueue.c:2338 [inline]
>  worker_thread+0x82b/0x1120 kernel/workqueue.c:2424
>  kthread+0x3b1/0x4a0 kernel/kthread.c:313
>  ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
> INFO: task kworker/1:1:8462 blocked for more than 145 seconds.
>       Not tainted 5.13.0-rc6-syzkaller #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:kworker/1:1     state:D stack:25960 pid: 8462 ppid:     2 flags:0x00004000
> Workqueue: usb_hub_wq hub_event
> Call Trace:
>  context_switch kernel/sched/core.c:4339 [inline]
>  __schedule+0x916/0x23e0 kernel/sched/core.c:5147
>  schedule+0xcf/0x270 kernel/sched/core.c:5226
>  schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
>  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+0x168/0x270 kernel/sched/completion.c:138
>  port100_send_cmd_sync drivers/nfc/port100.c:923 [inline]
>  port100_get_command_type_mask drivers/nfc/port100.c:1008 [inline]
>  port100_probe+0x9e4/0x1340 drivers/nfc/port100.c:1554
>  usb_probe_interface+0x315/0x7f0 drivers/usb/core/driver.c:396
>  really_probe+0x291/0xf60 drivers/base/dd.c:576
>  driver_probe_device+0x298/0x410 drivers/base/dd.c:763
>  __device_attach_driver+0x203/0x2c0 drivers/base/dd.c:870
>  bus_for_each_drv+0x15f/0x1e0 drivers/base/bus.c:431
>  __device_attach+0x228/0x4b0 drivers/base/dd.c:938
>  bus_probe_device+0x1e4/0x290 drivers/base/bus.c:491
>  device_add+0xbe0/0x2100 drivers/base/core.c:3324
>  usb_set_configuration+0x113f/0x1910 drivers/usb/core/message.c:2164
>  usb_generic_driver_probe+0xba/0x100 drivers/usb/core/generic.c:238
>  usb_probe_device+0xd9/0x2c0 drivers/usb/core/driver.c:293
>  really_probe+0x291/0xf60 drivers/base/dd.c:576
>  driver_probe_device+0x298/0x410 drivers/base/dd.c:763
>  __device_attach_driver+0x203/0x2c0 drivers/base/dd.c:870
>  bus_for_each_drv+0x15f/0x1e0 drivers/base/bus.c:431
>  __device_attach+0x228/0x4b0 drivers/base/dd.c:938
>  bus_probe_device+0x1e4/0x290 drivers/base/bus.c:491
>  device_add+0xbe0/0x2100 drivers/base/core.c:3324
>  usb_new_device.cold+0x721/0x1058 drivers/usb/core/hub.c:2556
>  hub_port_connect drivers/usb/core/hub.c:5276 [inline]
>  hub_port_connect_change drivers/usb/core/hub.c:5416 [inline]
>  port_event drivers/usb/core/hub.c:5562 [inline]
>  hub_event+0x2357/0x4330 drivers/usb/core/hub.c:5644
>  process_one_work+0x98d/0x1600 kernel/workqueue.c:2276
>  process_scheduled_works kernel/workqueue.c:2338 [inline]
>  worker_thread+0x82b/0x1120 kernel/workqueue.c:2424
>  kthread+0x3b1/0x4a0 kernel/kthread.c:313
>  ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
> INFO: task syz-executor195:8751 blocked for more than 145 seconds.
>       Not tainted 5.13.0-rc6-syzkaller #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:syz-executor195 state:D stack:28016 pid: 8751 ppid:  8448 flags:0x00000004
> Call Trace:
>  context_switch kernel/sched/core.c:4339 [inline]
>  __schedule+0x916/0x23e0 kernel/sched/core.c:5147
>  schedule+0xcf/0x270 kernel/sched/core.c:5226
>  schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:5285
>  __mutex_lock_common kernel/locking/mutex.c:1036 [inline]
>  __mutex_lock+0x7d4/0x10c0 kernel/locking/mutex.c:1104
>  misc_open+0x55/0x4a0 drivers/char/misc.c:107
>  chrdev_open+0x266/0x770 fs/char_dev.c:414
>  do_dentry_open+0x4b9/0x11b0 fs/open.c:826
>  do_open fs/namei.c:3361 [inline]
>  path_openat+0x1c0e/0x27e0 fs/namei.c:3494
>  do_filp_open+0x190/0x3d0 fs/namei.c:3521
>  do_sys_openat2+0x16d/0x420 fs/open.c:1187
>  do_sys_open fs/open.c:1203 [inline]
>  __do_sys_openat fs/open.c:1219 [inline]
>  __se_sys_openat fs/open.c:1214 [inline]
>  __x64_sys_openat+0x13f/0x1f0 fs/open.c:1214
>  do_syscall_64+0x3a/0xb0 arch/x86/entry/common.c:47
>  entry_SYSCALL_64_after_hwframe+0x44/0xae
> RIP: 0033:0x402af7
> RSP: 002b:00007ffc0cb8ab80 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
> RAX: ffffffffffffffda RBX: 00000000200000c0 RCX: 0000000000402af7
> RDX: 0000000000000002 RSI: 000000000048803b RDI: 00000000ffffff9c
> RBP: 000000000048803b R08: 00007ffc0cb8ac68 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000002
> R13: 00007ffc0cb8ccdc R14: 0000000000000036 R15: 00007ffc0cb8cce0
> INFO: task syz-executor195:8758 blocked for more than 145 seconds.
>       Not tainted 5.13.0-rc6-syzkaller #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:syz-executor195 state:D stack:28144 pid: 8758 ppid:  8447 flags:0x00000004
> Call Trace:
>  context_switch kernel/sched/core.c:4339 [inline]
>  __schedule+0x916/0x23e0 kernel/sched/core.c:5147
>  schedule+0xcf/0x270 kernel/sched/core.c:5226
>  schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:5285
>  __mutex_lock_common kernel/locking/mutex.c:1036 [inline]
>  __mutex_lock+0x7d4/0x10c0 kernel/locking/mutex.c:1104
>  misc_open+0x55/0x4a0 drivers/char/misc.c:107
>  chrdev_open+0x266/0x770 fs/char_dev.c:414
>  do_dentry_open+0x4b9/0x11b0 fs/open.c:826
>  do_open fs/namei.c:3361 [inline]
>  path_openat+0x1c0e/0x27e0 fs/namei.c:3494
>  do_filp_open+0x190/0x3d0 fs/namei.c:3521
>  do_sys_openat2+0x16d/0x420 fs/open.c:1187
>  do_sys_open fs/open.c:1203 [inline]
>  __do_sys_openat fs/open.c:1219 [inline]
>  __se_sys_openat fs/open.c:1214 [inline]
>  __x64_sys_openat+0x13f/0x1f0 fs/open.c:1214
>  do_syscall_64+0x3a/0xb0 arch/x86/entry/common.c:47
>  entry_SYSCALL_64_after_hwframe+0x44/0xae
> RIP: 0033:0x402af7
> RSP: 002b:00007ffc0cb8ab80 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
> RAX: ffffffffffffffda RBX: 00000000200000c0 RCX: 0000000000402af7
> RDX: 0000000000000002 RSI: 000000000048803b RDI: 00000000ffffff9c
> RBP: 000000000048803b R08: 00007ffc0cb8ac68 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000002
> R13: 00007ffc0cb8ccdc R14: 0000000000000036 R15: 00007ffc0cb8cce0
> INFO: task syz-executor195:8778 blocked for more than 146 seconds.
>       Not tainted 5.13.0-rc6-syzkaller #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:syz-executor195 state:D stack:28144 pid: 8778 ppid:  8445 flags:0x00000004
> Call Trace:
>  context_switch kernel/sched/core.c:4339 [inline]
>  __schedule+0x916/0x23e0 kernel/sched/core.c:5147
>  schedule+0xcf/0x270 kernel/sched/core.c:5226
>  schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:5285
>  __mutex_lock_common kernel/locking/mutex.c:1036 [inline]
>  __mutex_lock+0x7d4/0x10c0 kernel/locking/mutex.c:1104
>  misc_open+0x55/0x4a0 drivers/char/misc.c:107
>  chrdev_open+0x266/0x770 fs/char_dev.c:414
>  do_dentry_open+0x4b9/0x11b0 fs/open.c:826
>  do_open fs/namei.c:3361 [inline]
>  path_openat+0x1c0e/0x27e0 fs/namei.c:3494
>  do_filp_open+0x190/0x3d0 fs/namei.c:3521
>  do_sys_openat2+0x16d/0x420 fs/open.c:1187
>  do_sys_open fs/open.c:1203 [inline]
>  __do_sys_openat fs/open.c:1219 [inline]
>  __se_sys_openat fs/open.c:1214 [inline]
>  __x64_sys_openat+0x13f/0x1f0 fs/open.c:1214
>  do_syscall_64+0x3a/0xb0 arch/x86/entry/common.c:47
>  entry_SYSCALL_64_after_hwframe+0x44/0xae
> RIP: 0033:0x402af7
> RSP: 002b:00007ffc0cb8ab80 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
> RAX: ffffffffffffffda RBX: 00000000200000c0 RCX: 0000000000402af7
> RDX: 0000000000000002 RSI: 000000000048803b RDI: 00000000ffffff9c
> RBP: 000000000048803b R08: 00007ffc0cb8ac68 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000002
> R13: 00007ffc0cb8ccdc R14: 0000000000000036 R15: 00007ffc0cb8cce0
> INFO: task syz-executor195:8784 blocked for more than 146 seconds.
>       Not tainted 5.13.0-rc6-syzkaller #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:syz-executor195 state:D stack:28144 pid: 8784 ppid:  8446 flags:0x00000004
> Call Trace:
>  context_switch kernel/sched/core.c:4339 [inline]
>  __schedule+0x916/0x23e0 kernel/sched/core.c:5147
>  schedule+0xcf/0x270 kernel/sched/core.c:5226
>  schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:5285
>  __mutex_lock_common kernel/locking/mutex.c:1036 [inline]
>  __mutex_lock+0x7d4/0x10c0 kernel/locking/mutex.c:1104
>  misc_open+0x55/0x4a0 drivers/char/misc.c:107
>  chrdev_open+0x266/0x770 fs/char_dev.c:414
>  do_dentry_open+0x4b9/0x11b0 fs/open.c:826
>  do_open fs/namei.c:3361 [inline]
>  path_openat+0x1c0e/0x27e0 fs/namei.c:3494
>  do_filp_open+0x190/0x3d0 fs/namei.c:3521
>  do_sys_openat2+0x16d/0x420 fs/open.c:1187
>  do_sys_open fs/open.c:1203 [inline]
>  __do_sys_openat fs/open.c:1219 [inline]
>  __se_sys_openat fs/open.c:1214 [inline]
>  __x64_sys_openat+0x13f/0x1f0 fs/open.c:1214
>  do_syscall_64+0x3a/0xb0 arch/x86/entry/common.c:47
>  entry_SYSCALL_64_after_hwframe+0x44/0xae
> RIP: 0033:0x402af7
> RSP: 002b:00007ffc0cb8ab80 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
> RAX: ffffffffffffffda RBX: 00000000200000c0 RCX: 0000000000402af7
> RDX: 0000000000000002 RSI: 000000000048803b RDI: 00000000ffffff9c
> RBP: 000000000048803b R08: 00007ffc0cb8ac68 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000002
> R13: 00007ffc0cb8ccdc R14: 0000000000000036 R15: 00007ffc0cb8cce0
> INFO: task syz-executor195:8792 blocked for more than 146 seconds.
>       Not tainted 5.13.0-rc6-syzkaller #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:syz-executor195 state:D stack:28144 pid: 8792 ppid:  8442 flags:0x00004004
> Call Trace:
>  context_switch kernel/sched/core.c:4339 [inline]
>  __schedule+0x916/0x23e0 kernel/sched/core.c:5147
>  schedule+0xcf/0x270 kernel/sched/core.c:5226
>  schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:5285
>  __mutex_lock_common kernel/locking/mutex.c:1036 [inline]
>  __mutex_lock+0x7d4/0x10c0 kernel/locking/mutex.c:1104
>  misc_open+0x55/0x4a0 drivers/char/misc.c:107
>  chrdev_open+0x266/0x770 fs/char_dev.c:414
>  do_dentry_open+0x4b9/0x11b0 fs/open.c:826
>  do_open fs/namei.c:3361 [inline]
>  path_openat+0x1c0e/0x27e0 fs/namei.c:3494
>  do_filp_open+0x190/0x3d0 fs/namei.c:3521
>  do_sys_openat2+0x16d/0x420 fs/open.c:1187
>  do_sys_open fs/open.c:1203 [inline]
>  __do_sys_openat fs/open.c:1219 [inline]
>  __se_sys_openat fs/open.c:1214 [inline]
>  __x64_sys_openat+0x13f/0x1f0 fs/open.c:1214
>  do_syscall_64+0x3a/0xb0 arch/x86/entry/common.c:47
>  entry_SYSCALL_64_after_hwframe+0x44/0xae
> RIP: 0033:0x402af7
> RSP: 002b:00007ffc0cb8ab80 EFLAGS: 00000246 ORIG_RAX: 0000000000000101
> RAX: ffffffffffffffda RBX: 00000000200000c0 RCX: 0000000000402af7
> RDX: 0000000000000002 RSI: 000000000048803b RDI: 00000000ffffff9c
> RBP: 000000000048803b R08: 00007ffc0cb8ac68 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000002
> R13: 00007ffc0cb8ccdc R14: 0000000000000036 R15: 00007ffc0cb8cce0
> 
> Showing all locks held in the system:
> 3 locks held by kworker/0:0/5:
> 5 locks held by kworker/0:1/7:
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:617 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x871/0x1600 kernel/workqueue.c:2247
>  #1: ffffc90000cc7da8 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x8a5/0x1600 kernel/workqueue.c:2251
>  #2: ffff8880215bc220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #2: ffff8880215bc220 (&dev->mutex){....}-{3:3}, at: hub_event+0x1c1/0x4330 drivers/usb/core/hub.c:5590
>  #3: ffff8880143f6220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #3: ffff8880143f6220 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7a/0x4b0 drivers/base/dd.c:913
>  #4: ffff88802d51b1a8 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #4: ffff88802d51b1a8 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7a/0x4b0 drivers/base/dd.c:913
> 1 lock held by khungtaskd/1643:
>  #0: ffffffff8bf79620 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x53/0x260 kernel/locking/lockdep.c:6333
> 5 locks held by kworker/1:2/3367:
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:617 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x871/0x1600 kernel/workqueue.c:2247
>  #1: ffffc90003027da8 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x8a5/0x1600 kernel/workqueue.c:2251
>  #2: ffff8880214df220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #2: ffff8880214df220 (&dev->mutex){....}-{3:3}, at: hub_event+0x1c1/0x4330 drivers/usb/core/hub.c:5590
>  #3: ffff888019014220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #3: ffff888019014220 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7a/0x4b0 drivers/base/dd.c:913
>  #4: ffff8880190171a8 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #4: ffff8880190171a8 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7a/0x4b0 drivers/base/dd.c:913
> 5 locks held by kworker/1:3/4871:
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:617 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x871/0x1600 kernel/workqueue.c:2247
>  #1: ffffc9000b01fda8 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x8a5/0x1600 kernel/workqueue.c:2251
>  #2: ffff88802168b220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #2: ffff88802168b220 (&dev->mutex){....}-{3:3}, at: hub_event+0x1c1/0x4330 drivers/usb/core/hub.c:5590
>  #3: ffff88802d05d220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #3: ffff88802d05d220 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7a/0x4b0 drivers/base/dd.c:913
>  #4: ffff8880190131a8 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #4: ffff8880190131a8 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7a/0x4b0 drivers/base/dd.c:913
> 1 lock held by in:imklog/8343:
>  #0: ffff8880147e6870 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xe9/0x100 fs/file.c:974
> 5 locks held by kworker/1:0/8456:
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:617 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x871/0x1600 kernel/workqueue.c:2247
>  #1: ffffc900016cfda8 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x8a5/0x1600 kernel/workqueue.c:2251
>  #2: ffff8880216c3220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #2: ffff8880216c3220 (&dev->mutex){....}-{3:3}, at: hub_event+0x1c1/0x4330 drivers/usb/core/hub.c:5590
>  #3: ffff88802d059220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #3: ffff88802d059220 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7a/0x4b0 drivers/base/dd.c:913
>  #4: ffff888030fe51a8 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #4: ffff888030fe51a8 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7a/0x4b0 drivers/base/dd.c:913
> 5 locks held by kworker/1:1/8462:
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic64_set include/asm-generic/atomic-instrumented.h:856 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic_long_set include/asm-generic/atomic-long.h:41 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:617 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
>  #0: ffff8880198c2d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x871/0x1600 kernel/workqueue.c:2247
>  #1: ffffc900016dfda8 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x8a5/0x1600 kernel/workqueue.c:2251
>  #2: ffff88823bc62a20 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #2: ffff88823bc62a20 (&dev->mutex){....}-{3:3}, at: hub_event+0x1c1/0x4330 drivers/usb/core/hub.c:5590
>  #3: ffff888030fe7220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #3: ffff888030fe7220 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7a/0x4b0 drivers/base/dd.c:913
>  #4: ffff8880190151a8 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:742 [inline]
>  #4: ffff8880190151a8 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7a/0x4b0 drivers/base/dd.c:913
> 1 lock held by syz-executor195/8751:
>  #0: ffffffff8c99e6e8 (misc_mtx){+.+.}-{3:3}, at: misc_open+0x55/0x4a0 drivers/char/misc.c:107
> 1 lock held by syz-executor195/8758:
>  #0: ffffffff8c99e6e8 (misc_mtx){+.+.}-{3:3}, at: misc_open+0x55/0x4a0 drivers/char/misc.c:107
> 1 lock held by syz-executor195/8778:
>  #0: ffffffff8c99e6e8 (misc_mtx){+.+.}-{3:3}, at: misc_open+0x55/0x4a0 drivers/char/misc.c:107
> 1 lock held by syz-executor195/8784:
>  #0: ffffffff8c99e6e8 (misc_mtx){+.+.}-{3:3}, at: misc_open+0x55/0x4a0 drivers/char/misc.c:107
> 1 lock held by syz-executor195/8792:
>  #0: ffffffff8c99e6e8 (misc_mtx){+.+.}-{3:3}, at: misc_open+0x55/0x4a0 drivers/char/misc.c:107
> 2 locks held by syz-executor195/8814:
>  #0: ffffffff8c99e6e8 (misc_mtx){+.+.}-{3:3}, at: misc_open+0x55/0x4a0 drivers/char/misc.c:107
>  #1: ffffffff8be49fe8 (system_transition_mutex){+.+.}-{3:3}, at: snapshot_open+0x3b/0x2a0 kernel/power/user.c:54
> 
> =============================================
> 
> NMI backtrace for cpu 1
> CPU: 1 PID: 1643 Comm: khungtaskd Not tainted 5.13.0-rc6-syzkaller #0
> Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
> Call Trace:
>  __dump_stack lib/dump_stack.c:79 [inline]
>  dump_stack+0x141/0x1d7 lib/dump_stack.c:120
>  nmi_cpu_backtrace.cold+0x44/0xd7 lib/nmi_backtrace.c:105
>  nmi_trigger_cpumask_backtrace+0x1b3/0x230 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+0xd48/0xfb0 kernel/hung_task.c:294
>  kthread+0x3b1/0x4a0 kernel/kthread.c:313
>  ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
> Sending NMI from CPU 1 to CPUs 0:
> NMI backtrace for cpu 0
> CPU: 0 PID: 4850 Comm: systemd-journal Not tainted 5.13.0-rc6-syzkaller #0
> Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
> RIP: 0033:0x7fbb9961e46c
> Code: d1 49 89 e1 31 d2 41 b8 10 00 00 00 41 89 f6 49 89 e7 e8 57 fc ff ff 85 c0 41 89 c4 0f 88 5f ff ff ff 48 8b 04 24 4c 8b 40 08 <4d> 85 c0 0f 84 bb 00 00 00 49 83 f8 0f 0f 87 e1 00 00 00 e8 6c 7b
> RSP: 002b:00007ffc2e6bdca0 EFLAGS: 00000202
> RAX: 00007fbb96c1b798 RBX: 000000000016c798 RCX: 000000000016c798
> RDX: 0000000000000000 RSI: 0000000000000010 RDI: 00005570395fa120
> RBP: 00005570395f9e80 R08: 0000000000001608 R09: 00005570395fa120
> R10: 00007ffc2e6cf090 R11: 00007fbb96da6658 R12: 0000000000000001
> R13: 00007ffc2e6bdd18 R14: 0000000000000006 R15: 00007ffc2e6bdca0
> FS:  00007fbb999308c0 GS:  0000000000000000
> 
> 
> ---
> This report 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 issue. See:
> https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
> syzbot can test patches for this issue, for details see:
> https://goo.gl/tpsmEJ#testing-patches

Cc: Thierry, Alan, Andrey,

The issue is reproducible immediately on QEMU instance with
USB_DUMMY_HCD and USB_RAW_GADGET. I don't know about real port100 NFC
device.

I spent some time looking into this and have no clue, except that it
looks like an effect of a race condition.

1. When using syskaller reproducer against one USB device (In the C
reproducer change the loop in main() to use procid=0) - issue does not
happen.

2. With two threads or more talking to separate Dummy USB devices, the
issue appears. The more of them, the better...

3. The reported problem is in missing complete. The correct flow is like:
port100_probe()
port100_get_command_type_mask()
port100_send_cmd_sync()
port100_send_cmd_async()
port100_submit_urb_for_ack()
port100_send_complete()
[   63.363863] port100 2-1:0.0: NFC: Urb failure (status -71)
port100_recv_ack()
[   63.369942] port100 2-1:0.0: NFC: Urb failure (status -71)

and schedule_work() which completes and unblocks port100_send_cmd_sync

However in the failing case (hung task) the port100_recv_ack() is never
called. It looks like USB core / HCD / gadget does not send the Ack/URB
complete.

I don't know why. The port100 NFC driver code looks OK, except it is not
prepared for missing ack/urb so it waits indefinitely. I could try to
convert it to wait_for_completion_timeout() but it won't be trivial and
more important - I am not sure if this is the problem. Somehow the ACK
with Urb failure is not sent back to the port100 device. Therefore I am
guessing that the race condition is somwhere in USB stack, not in
port100 driver.

The lockdep and other testing tools did not find anything here.

Anyone hints where the issue could be?

Best regards,
Krzysztof