Re: [syzbot] INFO: task hung in port100_probe

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

On 22/07/2021 16:20, Krzysztof Kozlowski wrote:
> 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?

Also syzbot report for pn533 NFC (and its code) looks very similar:
https://lore.kernel.org/lkml/00000000000053e5bb05c7983666@google.com/

Best regards,
Best regards,
Krzysztof