* [syzbot] INFO: task hung in port100_probe @ 2021-06-22 15:43 syzbot 2021-06-22 16:07 ` Pavel Skripkin ` (2 more replies) 0 siblings, 3 replies; 23+ messages in thread From: syzbot @ 2021-06-22 15:43 UTC (permalink / raw) To: krzysztof.kozlowski, linux-kernel, netdev, syzkaller-bugs 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 ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-06-22 15:43 [syzbot] INFO: task hung in port100_probe syzbot @ 2021-06-22 16:07 ` Pavel Skripkin 2021-06-22 16:21 ` syzbot 2021-07-22 14:20 ` Krzysztof Kozlowski 2022-03-09 19:33 ` Pavel Skripkin 2 siblings, 1 reply; 23+ messages in thread From: Pavel Skripkin @ 2021-06-22 16:07 UTC (permalink / raw) To: syzbot; +Cc: krzysztof.kozlowski, linux-kernel, netdev, syzkaller-bugs [-- Attachment #1: Type: text/plain, Size: 1245 bytes --] On Tue, 22 Jun 2021 08:43:29 -0700 syzbot <syzbot+abd2e0dafb481b621869@syzkaller.appspotmail.com> 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 Hmmm, maybe this will work #syz test git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master With regards, Pavel Skripkin [-- Attachment #2: 0001-nfc-add-missing-complete-to-avoid-hung.patch --] [-- Type: text/x-patch, Size: 1525 bytes --] From 450d464332a8dbf5a915c1447af554ca84a163bb Mon Sep 17 00:00:00 2001 From: Pavel Skripkin <paskripkin@gmail.com> Date: Tue, 22 Jun 2021 19:00:03 +0300 Subject: [PATCH] nfc: add missing complete() to avoid hung /* .... */ Signed-off-by: Pavel Skripkin <paskripkin@gmail.com> --- drivers/nfc/port100.c | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/drivers/nfc/port100.c b/drivers/nfc/port100.c index 8e4d355dc3ae..c8c421af49b7 100644 --- a/drivers/nfc/port100.c +++ b/drivers/nfc/port100.c @@ -805,9 +805,15 @@ static void port100_build_cmd_frame(struct port100 *dev, u8 cmd_code, port100_tx_frame_finish(skb->data); } +struct port100_sync_cmd_response { + struct sk_buff *resp; + struct completion done; +}; + static void port100_send_async_complete(struct port100 *dev) { struct port100_cmd *cmd = dev->cmd; + struct port100_sync_cmd_response *cmd_resp = cmd->complete_cb_context; int status = cmd->status; struct sk_buff *req = cmd->req; @@ -831,6 +837,7 @@ static void port100_send_async_complete(struct port100 *dev) cmd->complete_cb(dev, cmd->complete_cb_context, resp); done: + complete(&cmd_resp->done); kfree(cmd); } @@ -883,11 +890,6 @@ static int port100_send_cmd_async(struct port100 *dev, u8 cmd_code, return rc; } -struct port100_sync_cmd_response { - struct sk_buff *resp; - struct completion done; -}; - static void port100_wq_cmd_complete(struct work_struct *work) { struct port100 *dev = container_of(work, struct port100, -- 2.32.0 ^ permalink raw reply related [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-06-22 16:07 ` Pavel Skripkin @ 2021-06-22 16:21 ` syzbot 0 siblings, 0 replies; 23+ messages in thread From: syzbot @ 2021-06-22 16:21 UTC (permalink / raw) To: krzysztof.kozlowski, linux-kernel, netdev, paskripkin, syzkaller-bugs Hello, syzbot has tested the proposed patch but the reproducer is still triggering an issue: WARNING: ODEBUG bug in release_nodes ------------[ cut here ]------------ ODEBUG: free active (active state 0) object type: work_struct hint: port100_wq_cmd_complete+0x0/0x3b0 drivers/nfc/port100.c:1174 WARNING: CPU: 1 PID: 10270 at lib/debugobjects.c:505 debug_print_object+0x16e/0x250 lib/debugobjects.c:505 Modules linked in: CPU: 1 PID: 10270 Comm: kworker/1:8 Not tainted 5.13.0-rc7-syzkaller #0 Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011 Workqueue: usb_hub_wq hub_event RIP: 0010:debug_print_object+0x16e/0x250 lib/debugobjects.c:505 Code: ff df 48 89 fa 48 c1 ea 03 80 3c 02 00 0f 85 af 00 00 00 48 8b 14 dd a0 f6 c2 89 4c 89 ee 48 c7 c7 a0 ea c2 89 e8 2d ee 01 05 <0f> 0b 83 05 25 2d 76 09 01 48 83 c4 18 5b 5d 41 5c 41 5d 41 5e c3 RSP: 0018:ffffc9000af76fc8 EFLAGS: 00010282 RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 RDX: ffff888017f11c40 RSI: ffffffff815ce3a5 RDI: fffff520015eedeb RBP: 0000000000000001 R08: 0000000000000000 R09: 0000000000000000 R10: ffffffff815c820e R11: 0000000000000000 R12: ffffffff896ae040 R13: ffffffff89c2f0e0 R14: ffffffff814a7730 R15: dffffc0000000000 FS: 0000000000000000(0000) GS:ffff8880b9d00000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 CR2: 00007fb6ceabf000 CR3: 000000001cbec000 CR4: 00000000001506e0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 Call Trace: __debug_check_no_obj_freed lib/debugobjects.c:987 [inline] debug_check_no_obj_freed+0x301/0x420 lib/debugobjects.c:1018 slab_free_hook mm/slub.c:1558 [inline] slab_free_freelist_hook+0x174/0x240 mm/slub.c:1608 slab_free mm/slub.c:3168 [inline] kfree+0xe5/0x7f0 mm/slub.c:4212 release_nodes+0x4a3/0x8f0 drivers/base/devres.c:524 devres_release_all+0x74/0xd0 drivers/base/devres.c:545 really_probe+0x557/0xf60 drivers/base/dd.c:644 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:2558 hub_port_connect drivers/usb/core/hub.c:5278 [inline] hub_port_connect_change drivers/usb/core/hub.c:5418 [inline] port_event drivers/usb/core/hub.c:5564 [inline] hub_event+0x2357/0x4330 drivers/usb/core/hub.c:5646 process_one_work+0x98d/0x1600 kernel/workqueue.c:2276 worker_thread+0x64c/0x1120 kernel/workqueue.c:2422 kthread+0x3b1/0x4a0 kernel/kthread.c:313 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294 Tested on: commit: a96bfed6 Merge tag 'for-linus' of git://git.armlinux.org.u.. git tree: upstream console output: https://syzkaller.appspot.com/x/log.txt?x=12448400300000 kernel config: https://syzkaller.appspot.com/x/.config?x=3932cedd2c2d4a69 dashboard link: https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869 compiler: patch: https://syzkaller.appspot.com/x/patch.diff?x=15683230300000 ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-06-22 15:43 [syzbot] INFO: task hung in port100_probe syzbot 2021-06-22 16:07 ` Pavel Skripkin @ 2021-07-22 14:20 ` Krzysztof Kozlowski 2021-07-22 14:23 ` Krzysztof Kozlowski 2021-07-22 14:47 ` Alan Stern 2022-03-09 19:33 ` Pavel Skripkin 2 siblings, 2 replies; 23+ messages in thread From: Krzysztof Kozlowski @ 2021-07-22 14:20 UTC (permalink / raw) To: syzbot, linux-kernel, netdev, syzkaller-bugs, Pavel Skripkin Cc: Thierry Escande, Alan Stern, Andrey Konovalov 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 ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-07-22 14:20 ` Krzysztof Kozlowski @ 2021-07-22 14:23 ` Krzysztof Kozlowski 2021-07-22 14:47 ` Alan Stern 1 sibling, 0 replies; 23+ messages in thread From: Krzysztof Kozlowski @ 2021-07-22 14:23 UTC (permalink / raw) To: syzbot, linux-kernel, netdev, syzkaller-bugs, Pavel Skripkin Cc: Thierry Escande, Alan Stern, Andrey Konovalov 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 ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-07-22 14:20 ` Krzysztof Kozlowski 2021-07-22 14:23 ` Krzysztof Kozlowski @ 2021-07-22 14:47 ` Alan Stern 2021-07-23 9:05 ` Krzysztof Kozlowski 2021-10-20 20:56 ` Krzysztof Kozlowski 1 sibling, 2 replies; 23+ messages in thread From: Alan Stern @ 2021-07-22 14:47 UTC (permalink / raw) To: Krzysztof Kozlowski Cc: syzbot, linux-kernel, netdev, syzkaller-bugs, Pavel Skripkin, Thierry Escande, Andrey Konovalov On Thu, Jul 22, 2021 at 04:20:10PM +0200, 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 ... > 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? Here's what I wrote earlier: "It looks like the problem stems from the fact that port100_send_frame_async() submits two URBs, but port100_send_cmd_sync() only waits for one of them to complete. The other URB may then still be active when the driver tries to reuse it." Of course, there may be more than one problem, so we may not be talking about the same thing. Does that help at all? Alan Stern ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-07-22 14:47 ` Alan Stern @ 2021-07-23 9:05 ` Krzysztof Kozlowski 2021-07-23 13:07 ` Alan Stern 2021-10-20 20:56 ` Krzysztof Kozlowski 1 sibling, 1 reply; 23+ messages in thread From: Krzysztof Kozlowski @ 2021-07-23 9:05 UTC (permalink / raw) To: Alan Stern Cc: syzbot, linux-kernel, netdev, syzkaller-bugs, Pavel Skripkin, Thierry Escande, Andrey Konovalov On 22/07/2021 16:47, Alan Stern wrote: > On Thu, Jul 22, 2021 at 04:20:10PM +0200, 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 > ... > >> 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? > > Here's what I wrote earlier: "It looks like the problem stems from the fact > that port100_send_frame_async() submits two URBs, but > port100_send_cmd_sync() only waits for one of them to complete. The other > URB may then still be active when the driver tries to reuse it." I see now you replied this to earlier syzbot report about "URB submitted while active". Here is a slightly different issue - hung task on waiting for completion coming from device ack. However maybe these are both similar or at least come from similar root cause in the driver. > > Of course, there may be more than one problem, so we may not be talking > about the same thing. > > Does that help at all? Thanks, it gives me some ideas to look into although I spent already too much time on this old driver. I doubt it has any users so maybe better to mark it as BROKEN... Best regards, Krzysztof ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-07-23 9:05 ` Krzysztof Kozlowski @ 2021-07-23 13:07 ` Alan Stern 0 siblings, 0 replies; 23+ messages in thread From: Alan Stern @ 2021-07-23 13:07 UTC (permalink / raw) To: Krzysztof Kozlowski Cc: syzbot, linux-kernel, netdev, syzkaller-bugs, Pavel Skripkin, Thierry Escande, Andrey Konovalov On Fri, Jul 23, 2021 at 11:05:09AM +0200, Krzysztof Kozlowski wrote: > On 22/07/2021 16:47, Alan Stern wrote: > > On Thu, Jul 22, 2021 at 04:20:10PM +0200, Krzysztof Kozlowski wrote: > >> Anyone hints where the issue could be? > > > > Here's what I wrote earlier: "It looks like the problem stems from the fact > > that port100_send_frame_async() submits two URBs, but > > port100_send_cmd_sync() only waits for one of them to complete. The other > > URB may then still be active when the driver tries to reuse it." > > I see now you replied this to earlier syzbot report about "URB submitted > while active". Here is a slightly different issue - hung task on waiting > for completion coming from device ack. > > However maybe these are both similar or at least come from similar root > cause in the driver. Exactly what I was thinking. :-) > > Of course, there may be more than one problem, so we may not be talking > > about the same thing. > > > > Does that help at all? > > Thanks, it gives me some ideas to look into although I spent already too > much time on this old driver. I doubt it has any users so maybe better > to mark it as BROKEN... Whatever you think is best. I know nothing about port100. Alan Stern ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-07-22 14:47 ` Alan Stern 2021-07-23 9:05 ` Krzysztof Kozlowski @ 2021-10-20 20:56 ` Krzysztof Kozlowski 2021-10-20 22:05 ` Alan Stern 1 sibling, 1 reply; 23+ messages in thread From: Krzysztof Kozlowski @ 2021-10-20 20:56 UTC (permalink / raw) To: Alan Stern, Felipe Balbi, Greg Kroah-Hartman Cc: syzbot, linux-kernel, netdev, syzkaller-bugs, Pavel Skripkin, Thierry Escande, Andrey Konovalov On 22/07/2021 16:47, Alan Stern wrote: > On Thu, Jul 22, 2021 at 04:20:10PM +0200, 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 > ... > >> 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? > > Here's what I wrote earlier: "It looks like the problem stems from the fact > that port100_send_frame_async() submits two URBs, but > port100_send_cmd_sync() only waits for one of them to complete. The other > URB may then still be active when the driver tries to reuse it." > > Of course, there may be more than one problem, so we may not be talking > about the same thing. Hi Alan, Felipe, Greg and others, This is an old issue reported by syzkaller for NFC port100 driver [1]. There is something similar for pn533 [2]. I was looking at it some time ago, took a break and now I am trying to fix it again. Without success. The issue is reproducible via USB gadget on QEMU, not on real HW. I looked and debugged the code and I think previously mentioned double-URB-submit is not the reason here. Or I miss how the USB works (which is quite probable...). 1. The port100 driver calls port100_send_cmd_sync() which eventually goes to port100_send_frame_async(). After it, it waits for "sync" completion. 2. In port100_send_frame_async(), driver indeed first submits "out_urb" which quite fast is being processed by dummy_hcd with "no ep configured" and -EPROTO. 3. Then (or sometimes before -EPROTO response from (2) above) the port100_send_frame_async() submits "in_urb" via port100_submit_urb_for_ack() and waits for its completion. Completion of "in_urb" (or the "ack") in port100_recv_ack() would schedule work to complete the (1) above - the sync completion. 4. Usually, when reproducer works fine (does not trigger issue), the dummy_timer() from gadget responds with the same "no ep configured for urb" for this "in_urb" (3). This completes "in_urb", which eventually completes (1) and probe finishes with error. Error is expected, because it's random junk-gadget... The syzkaller reproducer fails if >1 of threads are running these usb gadgets. When this happens, no "in_urb" completion happens. No this "ack" port100_recv_ack(). I added some debugs and simply dummy_hcd dummy_timer() is woken up on enqueuing in_urb and then is looping crazy on a previous URB (some older URB, coming from before port100 driver probe started). The dummy_timer() loop never reaches the second "in_urb" to process it, I think. The pn533 NFC driver has similar design, but I have now really doubts it is a NFC driver issue. Instead an issue in dummy gadget HCD is somehow triggered by the reproducer. Reproduction - just follow [1] or [2]. Eventually I slightly tweaked the code and put here: https://github.com/krzk/tools/tree/master/tests-var/nfc/port100_probe $ make $ sudo ./port100_probe [1] https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869 [2] https://syzkaller.appspot.com/bug?extid=1dc8b460d6d48d7ef9ca Best regards, Krzysztof ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-10-20 20:56 ` Krzysztof Kozlowski @ 2021-10-20 22:05 ` Alan Stern 2021-10-25 14:57 ` Krzysztof Kozlowski 0 siblings, 1 reply; 23+ messages in thread From: Alan Stern @ 2021-10-20 22:05 UTC (permalink / raw) To: Krzysztof Kozlowski Cc: Felipe Balbi, Greg Kroah-Hartman, syzbot, linux-kernel, netdev, syzkaller-bugs, Pavel Skripkin, Thierry Escande, Andrey Konovalov On Wed, Oct 20, 2021 at 10:56:42PM +0200, Krzysztof Kozlowski wrote: > Hi Alan, Felipe, Greg and others, > > This is an old issue reported by syzkaller for NFC port100 driver [1]. > There is something similar for pn533 [2]. > > I was looking at it some time ago, took a break and now I am trying to > fix it again. Without success. > > The issue is reproducible via USB gadget on QEMU, not on real HW. I > looked and debugged the code and I think previously mentioned > double-URB-submit is not the reason here. Or I miss how the USB works > (which is quite probable...). > > 1. The port100 driver calls port100_send_cmd_sync() which eventually > goes to port100_send_frame_async(). After it, it waits for "sync" > completion. > > 2. In port100_send_frame_async(), driver indeed first submits "out_urb" > which quite fast is being processed by dummy_hcd with "no ep configured" > and -EPROTO. > > 3. Then (or sometimes before -EPROTO response from (2) above) the > port100_send_frame_async() submits "in_urb" via > port100_submit_urb_for_ack() and waits for its completion. Completion of > "in_urb" (or the "ack") in port100_recv_ack() would schedule work to > complete the (1) above - the sync completion. > > 4. Usually, when reproducer works fine (does not trigger issue), the > dummy_timer() from gadget responds with the same "no ep configured for > urb" for this "in_urb" (3). This completes "in_urb", which eventually > completes (1) and probe finishes with error. Error is expected, because > it's random junk-gadget... > > The syzkaller reproducer fails if >1 of threads are running these usb > gadgets. When this happens, no "in_urb" completion happens. No this > "ack" port100_recv_ack(). > > I added some debugs and simply dummy_hcd dummy_timer() is woken up on > enqueuing in_urb and then is looping crazy on a previous URB (some older > URB, coming from before port100 driver probe started). The dummy_timer() > loop never reaches the second "in_urb" to process it, I think. Is there any way you can track down what's happening in that crazy loop? That is, what driver was responsible for the previous URB? We have seen this sort of thing before, where a driver submits an URB for a gadget which has disconnected. The URB fails with -EPROTO status but the URB's completion handler does an automatic resubmit. That can lead to a very tight loop with dummy-hcd, and it could easily prevent some other important processing from occurring. The simple solution is to prevent the driver from resubmitting when the completion status is -EPROTO. Alan Stern > The pn533 NFC driver has similar design, but I have now really doubts it > is a NFC driver issue. Instead an issue in dummy gadget HCD is somehow > triggered by the reproducer. > > Reproduction - just follow [1] or [2]. Eventually I slightly tweaked the > code and put here: > https://github.com/krzk/tools/tree/master/tests-var/nfc/port100_probe > $ make > $ sudo ./port100_probe > > > [1] https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869 > [2] https://syzkaller.appspot.com/bug?extid=1dc8b460d6d48d7ef9ca > > > Best regards, > Krzysztof ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-10-20 22:05 ` Alan Stern @ 2021-10-25 14:57 ` Krzysztof Kozlowski 2021-10-25 16:22 ` Alan Stern 0 siblings, 1 reply; 23+ messages in thread From: Krzysztof Kozlowski @ 2021-10-25 14:57 UTC (permalink / raw) To: Alan Stern Cc: Felipe Balbi, Greg Kroah-Hartman, syzbot, linux-kernel, netdev, syzkaller-bugs, Pavel Skripkin, Thierry Escande, Andrey Konovalov On 21/10/2021 00:05, Alan Stern wrote: >> >> The syzkaller reproducer fails if >1 of threads are running these usb >> gadgets. When this happens, no "in_urb" completion happens. No this >> "ack" port100_recv_ack(). >> >> I added some debugs and simply dummy_hcd dummy_timer() is woken up on >> enqueuing in_urb and then is looping crazy on a previous URB (some older >> URB, coming from before port100 driver probe started). The dummy_timer() >> loop never reaches the second "in_urb" to process it, I think. > > Is there any way you can track down what's happening in that crazy loop? > That is, what driver was responsible for the previous URB? > > We have seen this sort of thing before, where a driver submits an URB > for a gadget which has disconnected. The URB fails with -EPROTO status > but the URB's completion handler does an automatic resubmit. That can > lead to a very tight loop with dummy-hcd, and it could easily prevent > some other important processing from occurring. The simple solution is > to prevent the driver from resubmitting when the completion status is > -EPROTO. Hi Alan, Thanks for the reply. The URB which causes crazy loop is the port100 driver second URB, the one called ack or in_urb. The flow is: 1. probe() 2. port100_get_command_type_mask() 3. port100_send_cmd_async() 4. port100_send_frame_async() 5. usb_submit_urb(dev->out_urb) The call succeeds, the dummy_hcd picks it up and immediately ends the timer-loop with -EPROTO The completion here does not resubmit another/same URB. I checked this carefully and I hope I did not miss anything. 6. port100_submit_urb_for_ack() which sends the in_urb: usb_submit_urb(dev->in_urb) ... wait for completion ... dummy_hcd loops on this URB around line 2000: if (status == -EINPROGRESS) continue Best regards, Krzysztof ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-10-25 14:57 ` Krzysztof Kozlowski @ 2021-10-25 16:22 ` Alan Stern 2021-10-25 17:13 ` Krzysztof Kozlowski 0 siblings, 1 reply; 23+ messages in thread From: Alan Stern @ 2021-10-25 16:22 UTC (permalink / raw) To: Krzysztof Kozlowski Cc: Felipe Balbi, Greg Kroah-Hartman, syzbot, linux-kernel, netdev, syzkaller-bugs, Pavel Skripkin, Thierry Escande, Andrey Konovalov On Mon, Oct 25, 2021 at 04:57:23PM +0200, Krzysztof Kozlowski wrote: > On 21/10/2021 00:05, Alan Stern wrote: > >> > >> The syzkaller reproducer fails if >1 of threads are running these usb > >> gadgets. When this happens, no "in_urb" completion happens. No this > >> "ack" port100_recv_ack(). > >> > >> I added some debugs and simply dummy_hcd dummy_timer() is woken up on > >> enqueuing in_urb and then is looping crazy on a previous URB (some older > >> URB, coming from before port100 driver probe started). The dummy_timer() > >> loop never reaches the second "in_urb" to process it, I think. > > > > Is there any way you can track down what's happening in that crazy loop? > > That is, what driver was responsible for the previous URB? > > > > We have seen this sort of thing before, where a driver submits an URB > > for a gadget which has disconnected. The URB fails with -EPROTO status > > but the URB's completion handler does an automatic resubmit. That can > > lead to a very tight loop with dummy-hcd, and it could easily prevent > > some other important processing from occurring. The simple solution is > > to prevent the driver from resubmitting when the completion status is > > -EPROTO. > > Hi Alan, > > Thanks for the reply. > > The URB which causes crazy loop is the port100 driver second URB, the > one called ack or in_urb. > > The flow is: > 1. probe() > 2. port100_get_command_type_mask() > 3. port100_send_cmd_async() > 4. port100_send_frame_async() > 5. usb_submit_urb(dev->out_urb) > The call succeeds, the dummy_hcd picks it up and immediately ends the > timer-loop with -EPROTO So that URB completes immediately. > The completion here does not resubmit another/same URB. I checked this > carefully and I hope I did not miss anything. Yeah, I see the same thing. > 6. port100_submit_urb_for_ack() which sends the in_urb: > usb_submit_urb(dev->in_urb) > ... wait for completion > ... dummy_hcd loops on this URB around line 2000: > if (status == -EINPROGRESS) > continue Do I understand this correctly? You're saying that dummy-hcd executes the following jump at line 1975: /* incomplete transfer? */ if (status == -EINPROGRESS) continue; which goes back up to the loop head on line 1831: list_for_each_entry_safe(urbp, tmp, &dum_hcd->urbp_list, urbp_list) { Is that right? I don't see why this should cause any problem. It won't loop back to the same URB; it will make its way through the list. (Unless the list has somehow gotten corrupted...) dum_hcd->urbp_list should be short (perhaps 32 entries at most), so the loop should reach the end of the list fairly quickly. Now, doing all this 1000 times per second could use up a significant portion of the available time. Do you think that's the reason for the problem? It seems pretty unlikely. Alan Stern ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-10-25 16:22 ` Alan Stern @ 2021-10-25 17:13 ` Krzysztof Kozlowski 2021-10-25 18:54 ` Alan Stern 0 siblings, 1 reply; 23+ messages in thread From: Krzysztof Kozlowski @ 2021-10-25 17:13 UTC (permalink / raw) To: Alan Stern Cc: Felipe Balbi, Greg Kroah-Hartman, syzbot, linux-kernel, netdev, syzkaller-bugs, Pavel Skripkin, Thierry Escande, Andrey Konovalov On 25/10/2021 18:22, Alan Stern wrote: > On Mon, Oct 25, 2021 at 04:57:23PM +0200, Krzysztof Kozlowski wrote: >> On 21/10/2021 00:05, Alan Stern wrote: >>>> >>>> The syzkaller reproducer fails if >1 of threads are running these usb >>>> gadgets. When this happens, no "in_urb" completion happens. No this >>>> "ack" port100_recv_ack(). >>>> >>>> I added some debugs and simply dummy_hcd dummy_timer() is woken up on >>>> enqueuing in_urb and then is looping crazy on a previous URB (some older >>>> URB, coming from before port100 driver probe started). The dummy_timer() >>>> loop never reaches the second "in_urb" to process it, I think. >>> >>> Is there any way you can track down what's happening in that crazy loop? >>> That is, what driver was responsible for the previous URB? >>> >>> We have seen this sort of thing before, where a driver submits an URB >>> for a gadget which has disconnected. The URB fails with -EPROTO status >>> but the URB's completion handler does an automatic resubmit. That can >>> lead to a very tight loop with dummy-hcd, and it could easily prevent >>> some other important processing from occurring. The simple solution is >>> to prevent the driver from resubmitting when the completion status is >>> -EPROTO. >> >> Hi Alan, >> >> Thanks for the reply. >> >> The URB which causes crazy loop is the port100 driver second URB, the >> one called ack or in_urb. >> >> The flow is: >> 1. probe() >> 2. port100_get_command_type_mask() >> 3. port100_send_cmd_async() >> 4. port100_send_frame_async() >> 5. usb_submit_urb(dev->out_urb) >> The call succeeds, the dummy_hcd picks it up and immediately ends the >> timer-loop with -EPROTO > > So that URB completes immediately. > >> The completion here does not resubmit another/same URB. I checked this >> carefully and I hope I did not miss anything. > > Yeah, I see the same thing. > >> 6. port100_submit_urb_for_ack() which sends the in_urb: >> usb_submit_urb(dev->in_urb) >> ... wait for completion >> ... dummy_hcd loops on this URB around line 2000: >> if (status == -EINPROGRESS) >> continue > > Do I understand this correctly? You're saying that dummy-hcd executes > the following jump at line 1975: > > /* incomplete transfer? */ > if (status == -EINPROGRESS) > continue; > > which goes back up to the loop head on line 1831: > > list_for_each_entry_safe(urbp, tmp, &dum_hcd->urbp_list, urbp_list) { > > Is that right? Yes, exactly. The loop continues, iterating over list finishes thus the loops and dummy timer function exits. Then immediately it is being rescheduled by something (I don't know by what yet). To remind - the syzbot reproducer must run at least two threads (spawning USB gadgets so creating separate dummy devices) at the same time. However only one of dummy HCD devices seems to timer-loop endlessly... but this might not be important, e.g. maybe it's how syzbot reproducer works. > I don't see why this should cause any problem. It won't > loop back to the same URB; it will make its way through the list. > (Unless the list has somehow gotten corrupted...) dum_hcd->urbp_list > should be short (perhaps 32 entries at most), so the loop should reach > the end of the list fairly quickly. The list has actually only one element - only this one URB coming from port100 device (which I was always calling second URB/ack, in_urb). > Now, doing all this 1000 times per second could use up a significant > portion of the available time. Do you think that's the reason for the > problem? It seems pretty unlikely. No, this timer-looping itself is not a problem. Problem is that this URB never reaches some final state, e.g. -EPROTO. In normal operation, e.g. when reproducer did not hit the issue, both URBs from port100 (the first out_urb and second in_urb) complete with -EPROTO. In the case leading to hang ("task kworker/0:0:5 blocked for more than 143 seconds"), the in_urb does not complete therefore the port100 driver waits. Whether this intensive timer-loop is important (processing the same URB and continuing), I don't know. Best regards, Krzysztof ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-10-25 17:13 ` Krzysztof Kozlowski @ 2021-10-25 18:54 ` Alan Stern 0 siblings, 0 replies; 23+ messages in thread From: Alan Stern @ 2021-10-25 18:54 UTC (permalink / raw) To: Krzysztof Kozlowski Cc: Felipe Balbi, Greg Kroah-Hartman, syzbot, linux-kernel, netdev, syzkaller-bugs, Pavel Skripkin, Thierry Escande, Andrey Konovalov On Mon, Oct 25, 2021 at 07:13:59PM +0200, Krzysztof Kozlowski wrote: > On 25/10/2021 18:22, Alan Stern wrote: > > On Mon, Oct 25, 2021 at 04:57:23PM +0200, Krzysztof Kozlowski wrote: > >> The URB which causes crazy loop is the port100 driver second URB, the > >> one called ack or in_urb. > >> > >> The flow is: > >> 1. probe() > >> 2. port100_get_command_type_mask() > >> 3. port100_send_cmd_async() > >> 4. port100_send_frame_async() > >> 5. usb_submit_urb(dev->out_urb) > >> The call succeeds, the dummy_hcd picks it up and immediately ends the > >> timer-loop with -EPROTO > > > > So that URB completes immediately. > > > >> The completion here does not resubmit another/same URB. I checked this > >> carefully and I hope I did not miss anything. > > > > Yeah, I see the same thing. > > > >> 6. port100_submit_urb_for_ack() which sends the in_urb: > >> usb_submit_urb(dev->in_urb) > >> ... wait for completion > >> ... dummy_hcd loops on this URB around line 2000: > >> if (status == -EINPROGRESS) > >> continue > > > > Do I understand this correctly? You're saying that dummy-hcd executes > > the following jump at line 1975: > > > > /* incomplete transfer? */ > > if (status == -EINPROGRESS) > > continue; > > > > which goes back up to the loop head on line 1831: > > > > list_for_each_entry_safe(urbp, tmp, &dum_hcd->urbp_list, urbp_list) { > > > > Is that right? > > Yes, exactly. The loop continues, iterating over list finishes thus the > loops and dummy timer function exits. Then immediately it is being > rescheduled by something (I don't know by what yet). There's a timer (dum_hcd->timer) which fires every millisecond. If syzbot creates a lot of dummy-hcd instances then each instance will have its own timer, which could use up a large part of the available CPU time. But you say this isn't the real problem... > To remind - the syzbot reproducer must run at least two threads > (spawning USB gadgets so creating separate dummy devices) at the same > time. However only one of dummy HCD devices seems to timer-loop > endlessly... but this might not be important, e.g. maybe it's how syzbot > reproducer works. > > > I don't see why this should cause any problem. It won't > > loop back to the same URB; it will make its way through the list. > > (Unless the list has somehow gotten corrupted...) dum_hcd->urbp_list > > should be short (perhaps 32 entries at most), so the loop should reach > > the end of the list fairly quickly. > > The list has actually only one element - only this one URB coming from > port100 device (which I was always calling second URB/ack, in_urb). Okay, good. > > Now, doing all this 1000 times per second could use up a significant > > portion of the available time. Do you think that's the reason for the > > problem? It seems pretty unlikely. > > No, this timer-looping itself is not a problem. Problem is that this URB > never reaches some final state, e.g. -EPROTO. The -EPROTO completion should happen very quickly once the gadget driver unregisters or disconnects itself. This is because the call to find_endpoint at line 1856 should return NULL: ep = find_endpoint(dum, address); if (!ep) { /* set_configuration() disagreement */ dev_dbg(dummy_dev(dum_hcd), "no ep configured for urb %p\n", urb); status = -EPROTO; goto return_urb; } The NULL return should be caused by the !is_active test at the beginning of find_endpoint: static struct dummy_ep *find_endpoint(struct dummy *dum, u8 address) { int i; if (!is_active((dum->gadget.speed == USB_SPEED_SUPER ? dum->ss_hcd : dum->hs_hcd))) return NULL; is_active is defined as a macro: #define is_active(dum_hcd) ((dum_hcd->port_status & \ (USB_PORT_STAT_CONNECTION | USB_PORT_STAT_ENABLE | \ USB_PORT_STAT_SUSPEND)) \ == (USB_PORT_STAT_CONNECTION | USB_PORT_STAT_ENABLE)) and a disconnection should turn off the USB_PORT_STAT_CONNECTION bit, as follows: usb_gadget_unregister_driver calls usb_gadget_remove_driver (in drivers/usb/gadget/udc/core.c), which calls usb_gadget_disconnect, which calls dummy_pullup with value = 0, which sets dum->pullup to 0 and calls set_link_state, which calls set_link_state_by_speed, which turns off the USB_PORT_STATE_CONNECTION bit in dum_hcd->port_status because dum->pullup is 0. You can try tracing through this sequence of events to see if they're not taking place as intended. > In normal operation, e.g. when reproducer did not hit the issue, both > URBs from port100 (the first out_urb and second in_urb) complete with > -EPROTO. In the case leading to hang ("task kworker/0:0:5 blocked for > more than 143 seconds"), the in_urb does not complete therefore the > port100 driver waits. Those "... blocked for more than 143 seconds" errors occur when some task or interrupt loop is using up all the CPU time, preventing normal processes from running. In this case the culprit has got to be the timer routine and loop in dummy_hcd. However, the loop should terminate once the gadget driver unregisters itself, as described above. > Whether this intensive timer-loop is important (processing the same URB > and continuing), I don't know. Yes, that's how dummy_hcd gets its work done. Alan Stern ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2021-06-22 15:43 [syzbot] INFO: task hung in port100_probe syzbot 2021-06-22 16:07 ` Pavel Skripkin 2021-07-22 14:20 ` Krzysztof Kozlowski @ 2022-03-09 19:33 ` Pavel Skripkin 2022-03-09 19:56 ` syzbot 2 siblings, 1 reply; 23+ messages in thread From: Pavel Skripkin @ 2022-03-09 19:33 UTC (permalink / raw) To: syzbot, krzysztof.kozlowski, linux-kernel, netdev, syzkaller-bugs [-- Attachment #1: Type: text/plain, Size: 783 bytes --] On 6/22/21 18: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 > Hm, I can't reproduce this issue on top of my tree. Let's test my latest port100 patch #syz test git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master With regards, Pavel Skripkin [-- Attachment #2: ph --] [-- Type: text/plain, Size: 3056 bytes --] commit 131f7ebb9a3d8d271e3b384eefd69b94c0cfc784 Author: Pavel Skripkin <paskripkin@gmail.com> Date: Tue Mar 8 21:42:00 2022 +0300 NFC: port100: fix use-after-free in port100_send_complete Syzbot reported UAF in port100_send_complete(). The root case is in missing usb_kill_urb() calls on error handling path of ->probe function. port100_send_complete() accesses devm allocated memory which will be freed on probe failure. We should kill this urbs before returning an error from probe function to prevent reported use-after-free Fail log: BUG: KASAN: use-after-free in port100_send_complete+0x16e/0x1a0 drivers/nfc/port100.c:935 Read of size 1 at addr ffff88801bb59540 by task ksoftirqd/2/26 ... Call Trace: <TASK> __dump_stack lib/dump_stack.c:88 [inline] dump_stack_lvl+0xcd/0x134 lib/dump_stack.c:106 print_address_description.constprop.0.cold+0x8d/0x303 mm/kasan/report.c:255 __kasan_report mm/kasan/report.c:442 [inline] kasan_report.cold+0x83/0xdf mm/kasan/report.c:459 port100_send_complete+0x16e/0x1a0 drivers/nfc/port100.c:935 __usb_hcd_giveback_urb+0x2b0/0x5c0 drivers/usb/core/hcd.c:1670 ... Allocated by task 1255: kasan_save_stack+0x1e/0x40 mm/kasan/common.c:38 kasan_set_track mm/kasan/common.c:45 [inline] set_alloc_info mm/kasan/common.c:436 [inline] ____kasan_kmalloc mm/kasan/common.c:515 [inline] ____kasan_kmalloc mm/kasan/common.c:474 [inline] __kasan_kmalloc+0xa6/0xd0 mm/kasan/common.c:524 alloc_dr drivers/base/devres.c:116 [inline] devm_kmalloc+0x96/0x1d0 drivers/base/devres.c:823 devm_kzalloc include/linux/device.h:209 [inline] port100_probe+0x8a/0x1320 drivers/nfc/port100.c:1502 Freed by task 1255: kasan_save_stack+0x1e/0x40 mm/kasan/common.c:38 kasan_set_track+0x21/0x30 mm/kasan/common.c:45 kasan_set_free_info+0x20/0x30 mm/kasan/generic.c:370 ____kasan_slab_free mm/kasan/common.c:366 [inline] ____kasan_slab_free+0xff/0x140 mm/kasan/common.c:328 kasan_slab_free include/linux/kasan.h:236 [inline] __cache_free mm/slab.c:3437 [inline] kfree+0xf8/0x2b0 mm/slab.c:3794 release_nodes+0x112/0x1a0 drivers/base/devres.c:501 devres_release_all+0x114/0x190 drivers/base/devres.c:530 really_probe+0x626/0xcc0 drivers/base/dd.c:670 Reported-and-tested-by: syzbot+16bcb127fb73baeecb14@syzkaller.appspotmail.com Fixes: 0347a6ab300a ("NFC: port100: Commands mechanism implementation") Signed-off-by: Pavel Skripkin <paskripkin@gmail.com> diff --git a/drivers/nfc/port100.c b/drivers/nfc/port100.c index d7db1a0e6be1..00d8ea6dcb5d 100644 --- a/drivers/nfc/port100.c +++ b/drivers/nfc/port100.c @@ -1612,7 +1612,9 @@ static int port100_probe(struct usb_interface *interface, nfc_digital_free_device(dev->nfc_digital_dev); error: + usb_kill_urb(dev->in_urb); usb_free_urb(dev->in_urb); + usb_kill_urb(dev->out_urb); usb_free_urb(dev->out_urb); usb_put_dev(dev->udev); ^ permalink raw reply related [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2022-03-09 19:33 ` Pavel Skripkin @ 2022-03-09 19:56 ` syzbot 0 siblings, 0 replies; 23+ messages in thread From: syzbot @ 2022-03-09 19:56 UTC (permalink / raw) To: krzysztof.kozlowski, linux-kernel, netdev, paskripkin, syzkaller-bugs Hello, syzbot has tested the proposed patch and the reproducer did not trigger any issue: Reported-and-tested-by: syzbot+abd2e0dafb481b621869@syzkaller.appspotmail.com Tested on: commit: 330f4c53 ARM: fix build error when BPF_SYSCALL is disa.. git tree: upstream kernel config: https://syzkaller.appspot.com/x/.config?x=16438642a37fea1 dashboard link: https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869 compiler: Debian clang version 11.0.1-2, GNU ld (GNU Binutils for Debian) 2.35.2 patch: https://syzkaller.appspot.com/x/patch.diff?x=117d9781700000 Note: testing is done by a robot and is best-effort only. ^ permalink raw reply [flat|nested] 23+ messages in thread
[parent not found: <20220310084247.1148-1-hdanton@sina.com>]
* Re: [syzbot] INFO: task hung in port100_probe [not found] <20220310084247.1148-1-hdanton@sina.com> @ 2022-03-10 14:22 ` syzbot [not found] ` <20220311053751.1226-1-hdanton@sina.com> 1 sibling, 0 replies; 23+ messages in thread From: syzbot @ 2022-03-10 14:22 UTC (permalink / raw) To: hdanton, linux-kernel, netdev, syzkaller-bugs Hello, syzbot has tested the proposed patch and the reproducer did not trigger any issue: Reported-and-tested-by: syzbot+abd2e0dafb481b621869@syzkaller.appspotmail.com Tested on: commit: 1db333d9 Merge tag 'spi-fix-v5.17-rc7' of git://git.ke.. git tree: upstream kernel config: https://syzkaller.appspot.com/x/.config?x=16438642a37fea1 dashboard link: https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869 compiler: Debian clang version 11.0.1-2, GNU ld (GNU Binutils for Debian) 2.35.2 Note: no patches were applied. Note: testing is done by a robot and is best-effort only. ^ permalink raw reply [flat|nested] 23+ messages in thread
[parent not found: <20220311053751.1226-1-hdanton@sina.com>]
* Re: [syzbot] INFO: task hung in port100_probe [not found] ` <20220311053751.1226-1-hdanton@sina.com> @ 2022-03-11 19:17 ` Pavel Skripkin 2022-03-11 19:18 ` syzbot [not found] ` <20220312005624.1310-1-hdanton@sina.com> 1 sibling, 1 reply; 23+ messages in thread From: Pavel Skripkin @ 2022-03-11 19:17 UTC (permalink / raw) To: Hillf Danton, syzbot Cc: Krzysztof Kozlowski, Alan Stern, linux-kernel, netdev, syzkaller-bugs Hi Hillf, On 3/11/22 08:37, Hillf Danton wrote: > On Thu, 10 Mar 2022 06:22:10 -0800 >> Hello, >> >> syzbot has tested the proposed patch and the reproducer did not trigger any issue: >> >> Reported-and-tested-by: syzbot+abd2e0dafb481b621869@syzkaller.appspotmail.com >> >> Tested on: >> >> commit: 1db333d9 Merge tag 'spi-fix-v5.17-rc7' of git://git.ke.. >> git tree: upstream >> kernel config: https://syzkaller.appspot.com/x/.config?x=16438642a37fea1 >> dashboard link: https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869 >> compiler: Debian clang version 11.0.1-2, GNU ld (GNU Binutils for Debian) 2.35.2 >> >> Note: no patches were applied. >> Note: testing is done by a robot and is best-effort only. > > Given the failure of reproducing it upstream, wait for syzbot to bisect the > fix commit in spare cycles. > upstream branch already has my patch: see commit f80cfe2f26581f188429c12bd937eb905ad3ac7b. let's test previous commit to see if my really fixes this issue #syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git 3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b With regards, Pavel Skripkin ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2022-03-11 19:17 ` Pavel Skripkin @ 2022-03-11 19:18 ` syzbot 2022-03-11 19:19 ` Pavel Skripkin 0 siblings, 1 reply; 23+ messages in thread From: syzbot @ 2022-03-11 19:18 UTC (permalink / raw) To: hdanton, krzysztof.kozlowski, linux-kernel, netdev, paskripkin, stern, syzkaller-bugs Hello, syzbot tried to test the proposed patch but the build/boot failed: failed to checkout kernel repo git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b: failed to run ["git" "fetch" "--force" "f569e972c8e9057ee9c286220c83a480ebf30cc5" "3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b"]: exit status 128 fatal: couldn't find remote ref 3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b Tested on: commit: [unknown git tree: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git 3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b dashboard link: https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869 compiler: Note: no patches were applied. ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2022-03-11 19:18 ` syzbot @ 2022-03-11 19:19 ` Pavel Skripkin 2022-03-11 19:32 ` syzbot 0 siblings, 1 reply; 23+ messages in thread From: Pavel Skripkin @ 2022-03-11 19:19 UTC (permalink / raw) To: syzbot, hdanton, krzysztof.kozlowski, linux-kernel, netdev, stern, syzkaller-bugs On 3/11/22 22:18, syzbot wrote: > Hello, > > syzbot tried to test the proposed patch but the build/boot failed: > > failed to checkout kernel repo git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b: failed to run ["git" "fetch" "--force" "f569e972c8e9057ee9c286220c83a480ebf30cc5" "3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b"]: exit status 128 > fatal: couldn't find remote ref 3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b > Em, looks like wrong format #syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git 3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b With regards, Pavel Skripkin ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [syzbot] INFO: task hung in port100_probe 2022-03-11 19:19 ` Pavel Skripkin @ 2022-03-11 19:32 ` syzbot 0 siblings, 0 replies; 23+ messages in thread From: syzbot @ 2022-03-11 19:32 UTC (permalink / raw) To: hdanton, krzysztof.kozlowski, linux-kernel, netdev, paskripkin, stern, syzkaller-bugs Hello, syzbot has tested the proposed patch and the reproducer did not trigger any issue: Reported-and-tested-by: syzbot+abd2e0dafb481b621869@syzkaller.appspotmail.com Tested on: commit: 3bf7edc8 Merge tag 'arm64-fixes' of git://git.kernel.o.. git tree: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git kernel config: https://syzkaller.appspot.com/x/.config?x=16438642a37fea1 dashboard link: https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869 compiler: Debian clang version 11.0.1-2, GNU ld (GNU Binutils for Debian) 2.35.2 Note: no patches were applied. Note: testing is done by a robot and is best-effort only. ^ permalink raw reply [flat|nested] 23+ messages in thread
[parent not found: <20220312005624.1310-1-hdanton@sina.com>]
* Re: [syzbot] INFO: task hung in port100_probe [not found] ` <20220312005624.1310-1-hdanton@sina.com> @ 2022-03-12 10:36 ` Pavel Skripkin [not found] ` <20220312115854.1399-1-hdanton@sina.com> 1 sibling, 0 replies; 23+ messages in thread From: Pavel Skripkin @ 2022-03-12 10:36 UTC (permalink / raw) To: Hillf Danton Cc: Krzysztof Kozlowski, Alan Stern, syzbot, linux-kernel, netdev, syzkaller-bugs Hi Hillf, On 3/12/22 03:56, Hillf Danton wrote: >> upstream branch already has my patch: see commit >> f80cfe2f26581f188429c12bd937eb905ad3ac7b. >> > Thanks for your fix. > >> let's test previous commit to see if my really fixes this issue >> >> #syz test: >> git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git >> 3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b > > Given the Reported-and-tested-by tag in syzbot's echo [1], can you try and > bisect the curing commit in your spare cycles? > > Hillf > > [1] https://lore.kernel.org/lkml/00000000000002e20d05d9f663c6@google.com/ > Hm, that's odd. Last hit was 4d09h ago and I don't see related patches went it expect for mine. Will try to bisect... Also there is a chance, that reproducer is just unstable. With regards, Pavel Skripkin ^ permalink raw reply [flat|nested] 23+ messages in thread
[parent not found: <20220312115854.1399-1-hdanton@sina.com>]
* Re: [syzbot] INFO: task hung in port100_probe [not found] ` <20220312115854.1399-1-hdanton@sina.com> @ 2022-03-12 12:44 ` Pavel Skripkin 0 siblings, 0 replies; 23+ messages in thread From: Pavel Skripkin @ 2022-03-12 12:44 UTC (permalink / raw) To: Hillf Danton Cc: Krzysztof Kozlowski, Alan Stern, syzbot, linux-kernel, netdev, syzkaller-bugs Hi Hillf, On 3/12/22 14:58, Hillf Danton wrote: > On Sat, 12 Mar 2022 13:36:15 +0300 Pavel Skripkin wrote: >> On 3/12/22 03:56, Hillf Danton wrote: >> >> upstream branch already has my patch: see commit >> >> f80cfe2f26581f188429c12bd937eb905ad3ac7b. >> >> >> > Thanks for your fix. >> > >> >> let's test previous commit to see if my really fixes this issue >> >> >> >> #syz test: >> >> git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git >> >> 3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b3bf7edc84a9eb4007dd9a0cb8878a7e1d5ec6a3b >> > >> > Given the Reported-and-tested-by tag in syzbot's echo [1], can you try and >> > bisect the curing commit in your spare cycles? >> > >> > Hillf >> > >> > [1] https://lore.kernel.org/lkml/00000000000002e20d05d9f663c6@google.com/ >> > >> >> Hm, that's odd. Last hit was 4d09h ago and I don't see related patches > > Wonder if you mean it was reproduced four days ago by "Last hit was 4d09h ago". Yes, exactly. > If it was then can you share the splat? Anything different from the > syzbot report [2] on Tue, 22 Jun 2021? > IIRC syzbot tests on top of newest updates. I.e. last time syzbot reproduced this issue on top of v5.17-rc7 at least. So fix commit should somewhere between v5.17-rc7..HEAD With regards, Pavel Skripkin ^ permalink raw reply [flat|nested] 23+ messages in thread
end of thread, other threads:[~2022-03-12 12:45 UTC | newest] Thread overview: 23+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2021-06-22 15:43 [syzbot] INFO: task hung in port100_probe syzbot 2021-06-22 16:07 ` Pavel Skripkin 2021-06-22 16:21 ` syzbot 2021-07-22 14:20 ` Krzysztof Kozlowski 2021-07-22 14:23 ` Krzysztof Kozlowski 2021-07-22 14:47 ` Alan Stern 2021-07-23 9:05 ` Krzysztof Kozlowski 2021-07-23 13:07 ` Alan Stern 2021-10-20 20:56 ` Krzysztof Kozlowski 2021-10-20 22:05 ` Alan Stern 2021-10-25 14:57 ` Krzysztof Kozlowski 2021-10-25 16:22 ` Alan Stern 2021-10-25 17:13 ` Krzysztof Kozlowski 2021-10-25 18:54 ` Alan Stern 2022-03-09 19:33 ` Pavel Skripkin 2022-03-09 19:56 ` syzbot [not found] <20220310084247.1148-1-hdanton@sina.com> 2022-03-10 14:22 ` syzbot [not found] ` <20220311053751.1226-1-hdanton@sina.com> 2022-03-11 19:17 ` Pavel Skripkin 2022-03-11 19:18 ` syzbot 2022-03-11 19:19 ` Pavel Skripkin 2022-03-11 19:32 ` syzbot [not found] ` <20220312005624.1310-1-hdanton@sina.com> 2022-03-12 10:36 ` Pavel Skripkin [not found] ` <20220312115854.1399-1-hdanton@sina.com> 2022-03-12 12:44 ` Pavel Skripkin
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).