Re: INFO: task hung in hub_port_init

2020-10-06 Thread Andrey Konovalov 
On Tue, Oct 6, 2020 at 10:56 AM Oliver Neukum  wrote:
>
> > bisection log:  https://syzkaller.appspot.com/x/bisect.txt?x=152bb76050
> > final oops: https://syzkaller.appspot.com/x/report.txt?x=172bb76050
> > console output: https://syzkaller.appspot.com/x/log.txt?x=132bb76050
> >
> > IMPORTANT: if you fix the issue, please add the following tag to the commit:
> > Reported-by: syzbot+74d6ef051d3d2eacf...@syzkaller.appspotmail.com
> > 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:0x4000
> > 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?

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.

Re: INFO: task hung in hub_port_init

2020-10-06 Thread Oliver Neukum 
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=14c3b3db90
> 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=153bf5bd90
> C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=124c92af90
> 
> The issue was bisected to:
> 
> commit 6dcf45e514974a1ff10755015b5e06746a033e5f
> Author: Niklas Söderlund 
> Date:   Mon Jan 9 15:34:04 2017 +
> 
> 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=152bb76050
> final oops: https://syzkaller.appspot.com/x/report.txt?x=172bb76050
> console output: https://syzkaller.appspot.com/x/log.txt?x=132bb76050
> 
> IMPORTANT: if you fix the issue, please add the following tag to the commit:
> Reported-by: syzbot+74d6ef051d3d2eacf...@syzkaller.appspotmail.com
> 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:0x4000
> 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

INFO: task hung in hub_port_init

2020-10-06 Thread syzbot 
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=14c3b3db90
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=153bf5bd90
C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=124c92af90

The issue was bisected to:

commit 6dcf45e514974a1ff10755015b5e06746a033e5f
Author: Niklas Söderlund 
Date:   Mon Jan 9 15:34:04 2017 +

sh_eth: use correct name for ECMR_MPDE bit

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

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+74d6ef051d3d2eacf...@syzkaller.appspotmail.com
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:0x4000
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
 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]
 hub_event+0x1e64/0x3e60 drivers/usb/core/hub.c:5576
 process_one_work+0x94c/0x1670 kernel/workqueue.c:2269
 process_scheduled_works kernel/workqueue.c:2331 [inline]
 worker_thread+0x82b/0x1120 kernel/workqueue.c:2417
 kthread+0x3b5/0x4a0 kernel/kthread.c:292
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
INFO: task kworker/1:2:2641 blocked for more than 144 seconds.
  Not tainted 5.9.0-rc7-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:2 state:D stack:26992 pid: 2641 ppid: 2 flags:0x4000
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
 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
 usb_get_descriptor+0xc5/0x1b0 drivers/usb/core/message.c:655
 usb_get_device_descriptor+0x81/0xf0 drivers/usb/core/message.c:927
 hub_port_init+0x78f/0x2d80 drivers/usb/core/hub.c:4784
 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]
 hub_event+0x1e64/0x3e60 drivers/usb/core/hub.c:5576
 process_one_work+0x94c/0x1670 kernel/workqueue.c:2269
 worker_thread+0x64c/0x1120 kernel/workqueue.c:2415
 kthread+0x3b5/0x4a0 kernel/kthread.c:292
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:294
INFO: task kworker/1:1:6862 blocked for more than 146 seconds.
  Not tainted 5.9.0-rc7-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:1 state:D stack:26864 pid: 6862 ppid: 2 flags:0x4000
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
 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]
 hub_event+0x1e64/0x3e60 drivers/usb/core/hub.c:5576
 process_one_work+0x94c/0x1670 kernel/workqueue.c:2269
 worker_thread+0x64c/0x1120 kernel/workqueue.c:2415
 kthread+0x3b5/0x4a0 kernel/kthread.