INFO: task hung in hub_port_init

Hello,

syzbot found the following issue on:

HEAD commit:    d3d45f82 Merge tag 'pinctrl-v5.9-2' of git://git.kernel.or..
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=14c3b3db900000
kernel config:  https://syzkaller.appspot.com/x/.config?x=89ab6a0c48f30b49
dashboard link: https://syzkaller.appspot.com/bug?extid=74d6ef051d3d2eacf428
compiler:       gcc (GCC) 10.1.0-syz 20200507
syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=153bf5bd900000
C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=124c92af900000

The issue was bisected to:

commit 6dcf45e514974a1ff10755015b5e06746a033e5f
Author: Niklas Söderlund [off-list ref]
Date:   Mon Jan 9 15:34:04 2017 +0000

    sh_eth: use correct name for ECMR_MPDE bit

bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=152bb760500000
final oops:     https://syzkaller.appspot.com/x/report.txt?x=172bb760500000
console output: https://syzkaller.appspot.com/x/log.txt?x=132bb760500000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: <redacted>
Fixes: 6dcf45e51497 ("sh_eth: use correct name for ECMR_MPDE bit")

INFO: task kworker/0:0:5 blocked for more than 143 seconds.
      Not tainted 5.9.0-rc7-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/0:0     state:D stack:27664 pid:    5 ppid:     2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
 context_switch kernel/sched/core.c:3778 [inline]
 __schedule+0xec9/0x2280 kernel/sched/core.c:4527
 schedule+0xd0/0x2a0 kernel/sched/core.c:4602
 usb_kill_urb.part.0+0x197/0x220 drivers/usb/core/urb.c:696
 usb_kill_urb+0x7c/0x90 drivers/usb/core/urb.c:691

179 more lines

Am Dienstag, den 06.10.2020, 01:19 -0700 schrieb syzbot:

Hi,

HEAD commit:    d3d45f82 Merge tag 'pinctrl-v5.9-2' of git://git.kernel.or..
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=14c3b3db900000
kernel config:  https://syzkaller.appspot.com/x/.config?x=89ab6a0c48f30b49
dashboard link: https://syzkaller.appspot.com/bug?extid=74d6ef051d3d2eacf428
compiler:       gcc (GCC) 10.1.0-syz 20200507
syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=153bf5bd900000
C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=124c92af900000

The issue was bisected to:

commit 6dcf45e514974a1ff10755015b5e06746a033e5f
Author: Niklas Söderlund [off-list ref]
Date:   Mon Jan 9 15:34:04 2017 +0000

    sh_eth: use correct name for ECMR_MPDE bit

I am afraid this has bisected a race condition into neverland.

bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=152bb760500000
final oops:     https://syzkaller.appspot.com/x/report.txt?x=172bb760500000
console output: https://syzkaller.appspot.com/x/log.txt?x=132bb760500000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: <redacted>
Fixes: 6dcf45e51497 ("sh_eth: use correct name for ECMR_MPDE bit")

INFO: task kworker/0:0:5 blocked for more than 143 seconds.
      Not tainted 5.9.0-rc7-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/0:0     state:D stack:27664 pid:    5 ppid:     2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
 context_switch kernel/sched/core.c:3778 [inline]
 __schedule+0xec9/0x2280 kernel/sched/core.c:4527
 schedule+0xd0/0x2a0 kernel/sched/core.c:4602

By this time urb_dequeue() has been killed and has returned.

 usb_kill_urb.part.0+0x197/0x220 drivers/usb/core/urb.c:696
 usb_kill_urb+0x7c/0x90 drivers/usb/core/urb.c:691
 usb_start_wait_urb+0x24a/0x2b0 drivers/usb/core/message.c:64
 usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
 usb_control_msg+0x31c/0x4a0 drivers/usb/core/message.c:153
 hub_port_init+0x11ae/0x2d80 drivers/usb/core/hub.c:4689
 hub_port_connect drivers/usb/core/hub.c:5140 [inline]
 hub_port_connect_change drivers/usb/core/hub.c:5348 [inline]
 port_event drivers/usb/core/hub.c:5494 [inline]

This looks like it should.

Which HC driver are you using for these tests? It looks like
the HCD is not acting on urb_dequeue(), rather than a locking
issue.

	Regards
		Oliver

On Tue, Oct 6, 2020 at 10:56 AM Oliver Neukum [off-list ref] wrote:

quoted

bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=152bb760500000
final oops:     https://syzkaller.appspot.com/x/report.txt?x=172bb760500000
console output: https://syzkaller.appspot.com/x/log.txt?x=132bb760500000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: <redacted>
Fixes: 6dcf45e51497 ("sh_eth: use correct name for ECMR_MPDE bit")

INFO: task kworker/0:0:5 blocked for more than 143 seconds.
      Not tainted 5.9.0-rc7-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/0:0     state:D stack:27664 pid:    5 ppid:     2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
 context_switch kernel/sched/core.c:3778 [inline]
 __schedule+0xec9/0x2280 kernel/sched/core.c:4527
 schedule+0xd0/0x2a0 kernel/sched/core.c:4602

By this time urb_dequeue() has been killed and has returned.

quoted

 usb_kill_urb.part.0+0x197/0x220 drivers/usb/core/urb.c:696
 usb_kill_urb+0x7c/0x90 drivers/usb/core/urb.c:691
 usb_start_wait_urb+0x24a/0x2b0 drivers/usb/core/message.c:64
 usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
 usb_control_msg+0x31c/0x4a0 drivers/usb/core/message.c:153
 hub_port_init+0x11ae/0x2d80 drivers/usb/core/hub.c:4689
 hub_port_connect drivers/usb/core/hub.c:5140 [inline]
 hub_port_connect_change drivers/usb/core/hub.c:5348 [inline]
 port_event drivers/usb/core/hub.c:5494 [inline]

This looks like it should.

Which HC driver are you using for these tests?

Hi Oliver,

This is the USB/IP one, based on what I see in the reproducer.

Thanks!

It looks like
the HCD is not acting on urb_dequeue(), rather than a locking
issue.