Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Date:   Mon, 15 Apr 2019 14:06:58 -0400 (EDT)
From:   Alan Stern <stern@rowland.harvard.edu>
To:     Andrey Konovalov <andreyknvl@google.com>
cc:     Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
        <gustavo@embeddedor.com>,
        Kernel development list <linux-kernel@vger.kernel.org>,
        USB list <linux-usb@vger.kernel.org>,
        syzkaller-bugs <syzkaller-bugs@googlegroups.com>
Subject: Re: INFO: task hung in usb_kill_urb
In-Reply-To: <CAAeHK+wrF8Oh7ur+BcuyARvm2sx6KNVGFxqKHoyajApN+tOA_g@mail.gmail.com>
Message-ID: <Pine.LNX.4.44L0.1904151357540.1575-100000@iolanthe.rowland.org>
MIME-Version: 1.0
Content-Type: TEXT/PLAIN; charset=US-ASCII
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

On Mon, 15 Apr 2019, Andrey Konovalov wrote:

> On Fri, Apr 12, 2019 at 9:46 PM Alan Stern <stern@rowland.harvard.edu> wrote:
> >
> > Andrey:
> >
> > It's really hard to tell just what's going on here.
> >
> > On Fri, 12 Apr 2019, syzbot wrote:
> >
> > > Hello,
> > >
> > > syzbot found the following crash on:
> > >
> > > HEAD commit:    9a33b369 usb-fuzzer: main usb gadget fuzzer driver
> > > git tree:       https://github.com/google/kasan/tree/usb-fuzzer
> > > console output: https://syzkaller.appspot.com/x/log.txt?x=14c4c1af200000
> > > kernel config:  https://syzkaller.appspot.com/x/.config?x=23e37f59d94ddd15
> > > dashboard link: https://syzkaller.appspot.com/bug?extid=d919b0f29d7b5a4994b9
> > > compiler:       gcc (GCC) 9.0.0 20181231 (experimental)
> > > syz repro:      https://syzkaller.appspot.com/x/repro.syz?x=14410dbb200000
> > > C reproducer:   https://syzkaller.appspot.com/x/repro.c?x=12f0acd3200000
> > >
> > > IMPORTANT: if you fix the bug, please add the following tag to the commit:
> > > Reported-by: syzbot+d919b0f29d7b5a4994b9@syzkaller.appspotmail.com
> > >
> > > usb-fuzzer-gadget dummy_udc.0: failed to start USB fuzzer: -22
> > > usb-fuzzer-gadget dummy_udc.0: failed to start USB fuzzer: -22
> > > usb-fuzzer-gadget dummy_udc.0: failed to start USB fuzzer: -22
> > > usb-fuzzer-gadget dummy_udc.0: failed to start USB fuzzer: -22
> > > usb-fuzzer-gadget dummy_udc.0: failed to start USB fuzzer: -22
> > > INFO: task kworker/0:2:532 blocked for more than 143 seconds.
> > >        Not tainted 5.1.0-rc4-319354-g9a33b36 #3
> > > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > > kworker/0:2     D26656   532      2 0x80000000
> > > Workqueue: usb_hub_wq hub_event
> > > Call Trace:
> > >   schedule+0x8f/0x180 kernel/sched/core.c:3562
> > >   usb_kill_urb drivers/usb/core/urb.c:695 [inline]
> > >   usb_kill_urb+0x22a/0x2c0 drivers/usb/core/urb.c:687
> > >   usb_start_wait_urb+0x257/0x4d0 drivers/usb/core/message.c:63
> > >   usb_internal_control_msg drivers/usb/core/message.c:101 [inline]
> > >   usb_control_msg+0x321/0x4a0 drivers/usb/core/message.c:152
> >
> > It looks like something is stuck waiting for usb_kill_urb() to finish.
> > But what happened before that?
> 
> This crash is somewhat special. It happens quite often during USB
> fuzzing, but at the same time it's a hang, which makes it a bit harder
> debug. I initially thought that is somehow related to my custom USB
> fuzzing kernel patches, but then I saw that someone else hit this
> issue while doing USB fuzzing in a completely different way that
> doesn't require kernel modifications. So it might be an actual issue
> in the kernel.
> 
> The full console output is provided by the syzbot, but I guess it's
> not very useful in this case. I've just made sure that this issue is
> manually reproducible, so we can easily retest it with debug patches
> (syzbot should be also able to do that via the syz test command). Or
> is there a way to turn on some verbose mode to see some USB debug
> messages?

If I were doing this manually, I would run the following commands after
loading the dummy-hcd driver but before starting the main test
(requires CONFIG_USB_MON; you can skip the modprobe if
CONFIG_USB_MON=y):

	modprobe usbmon
	cat /sys/kernel/debug/usb/usbmon/Nu >/tmp/mon.out &

where N is the USB bus number corresponding to the dummy-hcd bus.  
Then after the test hangs, on another VT kill the "cat" process and
examine the contents of /tmp/mon.out.

Maybe you can do the equivalent with syzkaller?  If necessary, you can 
start the "cat" before loading dummy-hcd and specify a bus number of 0.
That will capture data for all the USB buses, including the dummy-hcd 
bus when it gets added (I think -- I haven't actually tried it).

Alan

> > I can't tell from the reproducer source, because it uses a bunch of
> > special stuff you added in your usb-fuzzer tree.
> >
> > Alan Stern
> >
> 
> I understand, for now I guess the simpler way to debug this is to run
> the reproducer. I'll write you and Greg a separate email regarding all
> that special stuff that I added.
> 
> Thanks!