WARNING in usb_submit_urb (4)

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit: 163c8d54a997 compiler: remove __no_sanitize_address_or_inl..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=11af34b9400000
kernel config: https://syzkaller.appspot.com/x/.config?x=8f559fee2fc3375a
dashboard link: https://syzkaller.appspot.com/bug?extid=7634edaea4d0b341c625
compiler: gcc (GCC) 8.0.1 20180413 (experimental)

Unfortunately, I don't have any reproducer for this crash yet.

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+7634ed...@syzkaller.appspotmail.com

------------[ cut here ]------------
URB 000000004ff98a65 submitted while active
WARNING: CPU: 1 PID: 17 at drivers/usb/core/urb.c:363
usb_submit_urb+0x11cf/0x14e0 drivers/usb/core/urb.c:363
Kernel panic - not syncing: panic_on_warn set ...
CPU: 1 PID: 17 Comm: kworker/1:0 Not tainted 4.20.0-rc1+ #322
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Workqueue: events_power_efficient hub_init_func2
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x244/0x39d lib/dump_stack.c:113
panic+0x2ad/0x55c kernel/panic.c:188
__warn.cold.8+0x20/0x45 kernel/panic.c:540
report_bug+0x254/0x2d0 lib/bug.c:186
fixup_bug arch/x86/kernel/traps.c:178 [inline]
do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:271
do_invalid_op+0x36/0x40 arch/x86/kernel/traps.c:290
invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:969
RIP: 0010:usb_submit_urb+0x11cf/0x14e0 drivers/usb/core/urb.c:363
Code: ee e8 c5 f1 7b fc 45 84 ed 0f 85 e2 f6 ff ff e8 e7 f0 7b fc 48 89 de
48 c7 c7 a0 21 92 88 c6 05 a6 bd 0d 05 01 e8 a1 52 45 fc <0f> 0b e9 c0 f6
ff ff c7 45 a0 01 00 00 00 e9 65 f7 ff ff 41 bc ed
RSP: 0018:ffff8801d9b5f4f0 EFLAGS: 00010282
RAX: 0000000000000000 RBX: ffff8801cdf30000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff8165e9b5 RDI: 0000000000000005
RBP: ffff8801d9b5f560 R08: ffff8801d9b4c480 R09: ffffed003b5e5020
R10: ffffed003b5e5020 R11: ffff8801daf28107 R12: 00000000fffffff0
R13: 0000000000000000 R14: 0000000000000009 R15: ffff8801d9b5f6f8
hub_activate+0xcab/0x1940 drivers/usb/core/hub.c:1215
hub_init_func2+0x1e/0x30 drivers/usb/core/hub.c:1240
process_one_work+0xc90/0x1c40 kernel/workqueue.c:2153
worker_thread+0x17f/0x1390 kernel/workqueue.c:2296
kthread+0x35a/0x440 kernel/kthread.c:246
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:352
Kernel Offset: disabled
Rebooting in 86400 seconds..


---
This bug 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 syzk...@googlegroups.com.

syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#bug-status-tracking for how to communicate with
syzbot.

[syzbot]

syzbot has found a reproducer for the following crash on:

HEAD commit: e12e00e388de Merge tag 'kbuild-fixes-v4.20' of git://git.k..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=100e4ef5400000
kernel config: https://syzkaller.appspot.com/x/.config?x=8f215f21f041a0d7

dashboard link: https://syzkaller.appspot.com/bug?extid=7634edaea4d0b341c625
compiler: gcc (GCC) 8.0.1 20180413 (experimental)

syz repro: https://syzkaller.appspot.com/x/repro.syz?x=11ce6fbd400000

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+7634ed...@syzkaller.appspotmail.com

hub 3-0:1.0: 8 ports detected
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 8 ports detected
------------[ cut here ]------------
URB 000000005e43faa5 submitted while active
WARNING: CPU: 0 PID: 6240 at drivers/usb/core/urb.c:363

usb_submit_urb+0x11cf/0x14e0 drivers/usb/core/urb.c:363
Kernel panic - not syncing: panic_on_warn set ...

CPU: 0 PID: 6240 Comm: kworker/0:1 Not tainted 4.20.0-rc1+ #332

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Workqueue: events_power_efficient hub_init_func2
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x244/0x39d lib/dump_stack.c:113
panic+0x2ad/0x55c kernel/panic.c:188
__warn.cold.8+0x20/0x45 kernel/panic.c:540
report_bug+0x254/0x2d0 lib/bug.c:186
fixup_bug arch/x86/kernel/traps.c:178 [inline]
do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:271
do_invalid_op+0x36/0x40 arch/x86/kernel/traps.c:290
invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:969
RIP: 0010:usb_submit_urb+0x11cf/0x14e0 drivers/usb/core/urb.c:363

Code: ee e8 95 62 7b fc 45 84 ed 0f 85 e2 f6 ff ff e8 b7 61 7b fc 48 89 de
48 c7 c7 a0 32 92 88 c6 05 d4 45 0d 05 01 e8 11 c5 44 fc <0f> 0b e9 c0 f6

ff ff c7 45 a0 01 00 00 00 e9 65 f7 ff ff 41 bc ed

RSP: 0018:ffff8881c1f974f0 EFLAGS: 00010282
RAX: 0000000000000000 RBX: ffff8881c83bb800 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff8165e7e5 RDI: 0000000000000005
RBP: ffff8881c1f97560 R08: ffff8881bc062040 R09: ffffed103b5c3ef8
R10: ffffed103b5c3ef8 R11: ffff8881dae1f7c7 R12: 00000000fffffff0
R13: 0000000000000000 R14: 0000000000000009 R15: ffff8881c1f976f8

[Alan Stern]

On Mon, 12 Nov 2018, syzbot wrote:

> syzbot has found a reproducer for the following crash on:
>
> HEAD commit: e12e00e388de Merge tag 'kbuild-fixes-v4.20' of git://git.k..
> git tree: upstream
> console output: https://syzkaller.appspot.com/x/log.txt?x=100e4ef5400000
> kernel config: https://syzkaller.appspot.com/x/.config?x=8f215f21f041a0d7
> dashboard link: https://syzkaller.appspot.com/bug?extid=7634edaea4d0b341c625
> compiler: gcc (GCC) 8.0.1 20180413 (experimental)
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=11ce6fbd400000
>
> IMPORTANT: if you fix the bug, please add the following tag to the commit:
> Reported-by: syzbot+7634ed...@syzkaller.appspotmail.com

I tried reproducing this bug on my own system, following the
instructions at

https://github.com/google/syzkaller/blob/master/docs/executing_syzkaller_programs.md

The reproducer failed to run properly. It produced the following
output:


$ ./syz-execprog -cover=0 -threaded=1 -repeat=1 -procs=4 /tmp/repro.syz
2018/11/13 15:29:32 parsed 1 programs
2018/11/13 15:29:32 executed programs: 0
2018/11/13 15:29:32 result: failed=false hanged=false err=executor 3: failed: tun: ioctl(TUNSETIFF) failed (errno 1)
loop failed (errno 0)


tun: ioctl(TUNSETIFF) failed (errno 1)
loop failed (errno 0)


The system is Fedora 28 running the 4.18.16-200.fc28.x86_64 kernel.
What should I do to investigate further?

Alan Stern

[Andrey Konovalov]

Hi Alan,

Looking at "errno 1", it seems that syz-execprog doesn't have enough
privileges to execute this ioctl, so you might need to run it as root.

However the absence of a C reproducer points to the fact that this is
some kind of a race condition. Those are quite sensitive to timing,
and any difference in the used setup might affect their
reproducibility. I would recommend building the exact kernel revision
with the provided config. For me it took around 3 minutes to
syz-execprog before I saw the WARNING.

Thanks!

[syzbot]

syzbot has bisected this bug to:

commit c470abd4fde40ea6a0846a2beab642a578c0b8cd
Author: Linus Torvalds <torv...@linux-foundation.org>
Date: Sun Feb 19 22:34:00 2017 +0000

Linux 4.10

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=11b415ed200000
start commit: e12e00e3 Merge tag 'kbuild-fixes-v4.20' of git://git.kerne..
git tree: upstream

kernel config: https://syzkaller.appspot.com/x/.config?x=8f215f21f041a0d7
dashboard link: https://syzkaller.appspot.com/bug?extid=7634edaea4d0b341c625

syz repro: https://syzkaller.appspot.com/x/repro.syz?x=11ce6fbd400000

Reported-by: syzbot+7634ed...@syzkaller.appspotmail.com
Fixes: c470abd4fde4 ("Linux 4.10")

For information about bisection process see: https://goo.gl/tpsmEJ#bisection

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer still triggered
crash:
WARNING in usb_submit_urb

hub 3-0:1.0: 8 ports detected
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 8 ports detected
------------[ cut here ]------------

URB 000000001f4e2e8e submitted while active
WARNING: CPU: 1 PID: 17 at drivers/usb/core/urb.c:362
usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:362

Kernel panic - not syncing: panic_on_warn set ...

CPU: 1 PID: 17 Comm: kworker/1:0 Not tainted 5.1.0-rc4+ #1

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Workqueue: events_power_efficient hub_init_func2
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]

dump_stack+0x172/0x1f0 lib/dump_stack.c:113
panic+0x2cb/0x65c kernel/panic.c:214
__warn.cold+0x20/0x45 kernel/panic.c:571
report_bug+0x263/0x2b0 lib/bug.c:186
fixup_bug arch/x86/kernel/traps.c:179 [inline]
fixup_bug arch/x86/kernel/traps.c:174 [inline]
do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:272
do_invalid_op+0x37/0x50 arch/x86/kernel/traps.c:291
invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:973
RIP: 0010:usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:362
Code: 89 de e8 33 89 f5 fc 84 db 0f 85 fe f5 ff ff e8 e6 87 f5 fc 4c 89 fe
48 c7 c7 c0 ea b1 87 c6 05 a8 cc ba 04 01 e8 8e 36 c8 fc <0f> 0b e9 dc f5
ff ff c7 45 c8 01 00 00 00 e9 94 f6 ff ff 41 be ed
RSP: 0018:ffff8881d9b47b90 EFLAGS: 00010282
RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff815afd86 RDI: ffffed103b368f64
RBP: ffff8881d9b47bf0 R08: ffff8881d9b32480 R09: ffffed103b5e5011
R10: ffffed103b5e5010 R11: ffff8881daf28087 R12: ffff8881ccd7edd0
R13: ffff8881d9b47cf0 R14: 00000000fffffff0 R15: ffff8881cd77e800
hub_activate+0xc77/0x16d0 drivers/usb/core/hub.c:1257
hub_init_func2+0x1e/0x30 drivers/usb/core/hub.c:1282
process_one_work+0x98e/0x1790 kernel/workqueue.c:2269
worker_thread+0x98/0xe40 kernel/workqueue.c:2415
kthread+0x357/0x430 kernel/kthread.c:253

ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:352
Kernel Offset: disabled
Rebooting in 86400 seconds..

Tested on:

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=11ddf187200000
kernel config: https://syzkaller.appspot.com/x/.config?x=84a3f526da898ded
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

[Andrey Konovalov]

Hi Alan,

This bug was originally triggered on the upstream kernel tree, no need
to run syz test on the usb-fuzzer tree (no harm either though :),
sorry for the confusion.

Thanks!


>
> --
> You received this message because you are subscribed to the Google Groups "syzkaller-bugs" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to syzkaller-bug...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/syzkaller-bugs/0000000000009086e10586495e19%40google.com.
> For more options, visit https://groups.google.com/d/optout.

[Alan Stern]

Oh, okay, I'll note that for the future.

It looks like this run was made without the patch I included in the
requesting email. That patch added some dev_info calls, to provide
additional debugging information, but none of them appear in the
console output.

What went wrong? Was this a result of using the wrong source tree?

Alan

[Andrey Konovalov]

Apparently syzbot failed to detect a patch in your syz test request,
but I didn't see your request email (I think you've sent it directly
to the bot), so I'm not sure what went wrong. Could you retry that
while keeping syzkall...@googlegroups.com in CC?

>
> Alan
>

[Alan Stern]

If I don't specify a repo and branch on the "#syz test:" line, will the
current upstream kernel tree be used? I'll try doing that...

Alan

[Alan Stern]

#sys test:


Index: usb-devel/drivers/usb/core/driver.c
===================================================================
--- usb-devel.orig/drivers/usb/core/driver.c
+++ usb-devel/drivers/usb/core/driver.c
@@ -34,6 +34,9 @@

#include "usb.h"

+#undef dev_vdbg
+#define dev_vdbg dev_info
+

/*
* Adds a new dynamic USBdevice ID to this driver,
Index: usb-devel/drivers/usb/core/hub.c
===================================================================
--- usb-devel.orig/drivers/usb/core/hub.c
+++ usb-devel/drivers/usb/core/hub.c
@@ -36,6 +36,10 @@
#include "hub.h"
#include "otg_whitelist.h"

+#undef dev_dbg
+#define dev_dbg dev_info
+
+
#define USB_VENDOR_GENESYS_LOGIC 0x05e3
#define HUB_QUIRK_CHECK_PORT_AUTOSUSPEND 0x01

@@ -1016,6 +1020,8 @@ static void hub_activate(struct usb_hub
bool need_debounce_delay = false;
unsigned delay;

+ dev_info(hub->intfdev, "%s type %d\n", __func__, type);
+
/* Continue a partial initialization */
if (type == HUB_INIT2 || type == HUB_INIT3) {
device_lock(&hdev->dev);
@@ -1254,6 +1260,7 @@ static void hub_activate(struct usb_hub
init3:
hub->quiescing = 0;

+ dev_info(hub->intfdev, "Submitting status URB\n");
status = usb_submit_urb(hub->urb, GFP_NOIO);
if (status < 0)
dev_err(hub->intfdev, "activate --> %d\n", status);

[Dmitry Vyukov]

On Fri, Apr 12, 2019 at 6:05 PM Alan Stern <st...@rowland.harvard.edu> wrote:
>
> #sys test:


There is no default tree/branch. And it's spelled sy_z_ with z.

[Andrey Konovalov]

You need to provide a link to the tree and the branch name like this:

#syz test: git://repo/address.git branch

[syzbot]

"git://repo/address.git" does not look like a valid git repo address.

[Alan Stern]

#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git v5.1-rc3

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer still triggered
crash:
WARNING in usb_submit_urb

hub 3-0:1.0: 8 ports detected
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 8 ports detected
------------[ cut here ]------------

URB 00000000b7243ab0 submitted while active
WARNING: CPU: 0 PID: 5 at drivers/usb/core/urb.c:362

usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:362
Kernel panic - not syncing: panic_on_warn set ...

CPU: 0 PID: 5 Comm: kworker/0:0 Not tainted 5.1.0-rc3 #1

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Workqueue: events_power_efficient hub_init_func2
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x172/0x1f0 lib/dump_stack.c:113
panic+0x2cb/0x65c kernel/panic.c:214
__warn.cold+0x20/0x45 kernel/panic.c:571
report_bug+0x263/0x2b0 lib/bug.c:186
fixup_bug arch/x86/kernel/traps.c:179 [inline]
fixup_bug arch/x86/kernel/traps.c:174 [inline]
do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:272
do_invalid_op+0x37/0x50 arch/x86/kernel/traps.c:291

kobject: 'loop0' (000000001fceac74): kobject_uevent_env

invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:973
RIP: 0010:usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:362

Code: 89 de e8 73 d7 f5 fc 84 db 0f 85 fe f5 ff ff e8 26 d6 f5 fc 4c 89 fe
48 c7 c7 e0 e9 b1 87 c6 05 29 17 bb 04 01 e8 0e 82 c8 fc <0f> 0b e9 dc f5

ff ff c7 45 c8 01 00 00 00 e9 94 f6 ff ff 41 be ed

RSP: 0018:ffff8881d9aafb90 EFLAGS: 00010282

RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000

RDX: 0000000000000000 RSI: ffffffff815b0046 RDI: ffffed103b355f64
RBP: ffff8881d9aafbf0 R08: ffff8881d9a96140 R09: ffffed103b5c5011
R10: ffffed103b5c5010 R11: ffff8881dae28087 R12: ffff8881cebdb690
R13: ffff8881d9aafcf0 R14: 00000000fffffff0 R15: ffff8881cd952800
kobject: 'loop0' (000000001fceac74): fill_kobj_path: path
= '/devices/virtual/block/loop0'

hub_activate+0xc77/0x16d0 drivers/usb/core/hub.c:1257
hub_init_func2+0x1e/0x30 drivers/usb/core/hub.c:1282
process_one_work+0x98e/0x1790 kernel/workqueue.c:2269
worker_thread+0x98/0xe40 kernel/workqueue.c:2415
kthread+0x357/0x430 kernel/kthread.c:253
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:352
Kernel Offset: disabled
Rebooting in 86400 seconds..


Tested on:

commit: 79a3aaa7 Linux 5.1-rc3
git tree:
git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git v5.1-rc3
console output: https://syzkaller.appspot.com/x/log.txt?x=10d8b397200000
kernel config: https://syzkaller.appspot.com/x/.config?x=3893d7552f01d316

[Andrey Konovalov]

Let's retry that with a different patch format:

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger
crash:

Reported-and-tested-by:
syzbot+7634ed...@syzkaller.appspotmail.com

Tested on:

commit: 79a3aaa7 Linux 5.1-rc3
git tree:
git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git v5.1-rc3

kernel config: https://syzkaller.appspot.com/x/.config?x=3893d7552f01d316
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

patch: https://syzkaller.appspot.com/x/patch.diff?x=13c9c07b200000

Note: testing is done by a robot and is best-effort only.

[Andrey Konovalov]

On Mon, Apr 15, 2019 at 2:34 PM syzbot
<syzbot+7634ed...@syzkaller.appspotmail.com> wrote:
>
> Hello,
>
> syzbot has tested the proposed patch and the reproducer did not trigger
> crash:
>
> Reported-and-tested-by:
> syzbot+7634ed...@syzkaller.appspotmail.com

Hm, I think this is some kind of race and the patch affects the
timings, so this can't be reproduced that easily. I'll try to do it
manually.

[Alan Stern]

Hmmm. That's not a very useful result, considering that the patch
merely added some debugging output. Perhaps the extra debugging caused
a change in timing which prevented some race, but it doesn't get us any
closer to figuring out where the race is.

Any suggestions?

Alan

[Andrey Konovalov]

On Mon, Apr 15, 2019 at 5:16 PM Andrey Konovalov <andre...@google.com> wrote:
>
> On Mon, Apr 15, 2019 at 2:34 PM syzbot
> <syzbot+7634ed...@syzkaller.appspotmail.com> wrote:
> >
> > Hello,
> >
> > syzbot has tested the proposed patch and the reproducer did not trigger
> > crash:
> >
> > Reported-and-tested-by:
> > syzbot+7634ed...@syzkaller.appspotmail.com
>
> Hm, I think this is some kind of race and the patch affects the
> timings, so this can't be reproduced that easily. I'll try to do it
> manually.

Hm, now I'm having troubles to reproduce it manually. Let's try your
debug patch once more on the exact commit this was reported. If it
doesn't trigger, I think the best thing would be to close this report
as invalid, and wait for syzbot to (hopefully) generate a fresh
reproducer.

#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
e12e00e388de

[Alan Stern]

On Mon, 15 Apr 2019, Andrey Konovalov wrote:

> On Mon, Apr 15, 2019 at 5:16 PM Andrey Konovalov <andre...@google.com> wrote:
> >
> > On Mon, Apr 15, 2019 at 2:34 PM syzbot
> > <syzbot+7634ed...@syzkaller.appspotmail.com> wrote:
> > >
> > > Hello,
> > >
> > > syzbot has tested the proposed patch and the reproducer did not trigger
> > > crash:
> > >
> > > Reported-and-tested-by:
> > > syzbot+7634ed...@syzkaller.appspotmail.com
> >
> > Hm, I think this is some kind of race and the patch affects the
> > timings, so this can't be reproduced that easily. I'll try to do it
> > manually.
>
> Hm, now I'm having troubles to reproduce it manually. Let's try your
> debug patch once more on the exact commit this was reported. If it
> doesn't trigger, I think the best thing would be to close this report
> as invalid, and wait for syzbot to (hopefully) generate a fresh
> reproducer.
>
> #syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
> e12e00e388de

I can also try modifying the patch to reduce the amount of extra
debugging info.

Alan

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger
crash:

Reported-and-tested-by:
syzbot+7634ed...@syzkaller.appspotmail.com

Tested on:

commit: e12e00e3 Merge tag 'kbuild-fixes-v4.20' of git://git.kerne..
git tree:

git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
kernel config: https://syzkaller.appspot.com/x/.config?x=69667e62a5e247a7

compiler: gcc (GCC) 9.0.0 20181231 (experimental)

patch: https://syzkaller.appspot.com/x/patch.diff?x=14c2312d200000

[Andrey Konovalov]

Feel free to try it.

>
> Alan
>

[Alan Stern]

On Mon, 15 Apr 2019, Andrey Konovalov wrote:

> On Mon, Apr 15, 2019 at 5:16 PM Andrey Konovalov <andre...@google.com> wrote:
> >
> > On Mon, Apr 15, 2019 at 2:34 PM syzbot
> > <syzbot+7634ed...@syzkaller.appspotmail.com> wrote:
> > >
> > > Hello,
> > >
> > > syzbot has tested the proposed patch and the reproducer did not trigger
> > > crash:
> > >
> > > Reported-and-tested-by:
> > > syzbot+7634ed...@syzkaller.appspotmail.com
> >
> > Hm, I think this is some kind of race and the patch affects the
> > timings, so this can't be reproduced that easily. I'll try to do it
> > manually.
>
> Hm, now I'm having troubles to reproduce it manually. Let's try your
> debug patch once more on the exact commit this was reported. If it
> doesn't trigger, I think the best thing would be to close this report
> as invalid, and wait for syzbot to (hopefully) generate a fresh
> reproducer.
>
> #syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
> e12e00e388de

I may have missed the test report for this attempt. Did it trigger the
warning? Or was there a parsing error caused by the fact that you put
the commit ID on a separate line from the "#syz test:"?

Alan

[Andrey Konovalov]

On Tue, Apr 16, 2019 at 5:54 PM Alan Stern <st...@rowland.harvard.edu> wrote:
>
> On Mon, 15 Apr 2019, Andrey Konovalov wrote:
>
> > On Mon, Apr 15, 2019 at 5:16 PM Andrey Konovalov <andre...@google.com> wrote:
> > >
> > > On Mon, Apr 15, 2019 at 2:34 PM syzbot
> > > <syzbot+7634ed...@syzkaller.appspotmail.com> wrote:
> > > >
> > > > Hello,
> > > >
> > > > syzbot has tested the proposed patch and the reproducer did not trigger
> > > > crash:
> > > >
> > > > Reported-and-tested-by:
> > > > syzbot+7634ed...@syzkaller.appspotmail.com
> > >
> > > Hm, I think this is some kind of race and the patch affects the
> > > timings, so this can't be reproduced that easily. I'll try to do it
> > > manually.
> >
> > Hm, now I'm having troubles to reproduce it manually. Let's try your
> > debug patch once more on the exact commit this was reported. If it
> > doesn't trigger, I think the best thing would be to close this report
> > as invalid, and wait for syzbot to (hopefully) generate a fresh
> > reproducer.
> >
> > #syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
> > e12e00e388de
>
> I may have missed the test report for this attempt. Did it trigger the
> warning?

Syzbot replied with "syzbot has tested the proposed patch and the
reproducer did not trigger crash:" so no warning was triggered :(

> Or was there a parsing error caused by the fact that you put
> the commit ID on a separate line from the "#syz test:"?

No, luckily this is parsed correctly :)

>
> Alan
>
>

[Alan Stern]

On Mon, 15 Apr 2019, Andrey Konovalov wrote:

> On Mon, Apr 15, 2019 at 5:16 PM Andrey Konovalov <andre...@google.com> wrote:
> >
> > On Mon, Apr 15, 2019 at 2:34 PM syzbot
> > <syzbot+7634ed...@syzkaller.appspotmail.com> wrote:
> > >
> > > Hello,
> > >
> > > syzbot has tested the proposed patch and the reproducer did not trigger
> > > crash:
> > >
> > > Reported-and-tested-by:
> > > syzbot+7634ed...@syzkaller.appspotmail.com
> >
> > Hm, I think this is some kind of race and the patch affects the
> > timings, so this can't be reproduced that easily. I'll try to do it
> > manually.
>
> Hm, now I'm having troubles to reproduce it manually. Let's try your
> debug patch once more on the exact commit this was reported. If it
> doesn't trigger, I think the best thing would be to close this report
> as invalid, and wait for syzbot to (hopefully) generate a fresh
> reproducer.
>
> #syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
> e12e00e388de

Okay, let's try a simpler and less intrusive debugging patch.

Alan Stern

#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git e12e00e388de

--- a/drivers/usb/core/hub.c
+++ b/drivers/usb/core/hub.c
@@ -1016,6 +1016,8 @@ static void hub_activate(struct usb_hub

bool need_debounce_delay = false;
unsigned delay;

+ dev_info(hub->intfdev, "%s type %d\n", __func__, type);
+
/* Continue a partial initialization */
if (type == HUB_INIT2 || type == HUB_INIT3) {
device_lock(&hdev->dev);

@@ -1254,6 +1256,7 @@ static void hub_activate(struct usb_hub

init3:
hub->quiescing = 0;

+ dev_info(hub->intfdev, "Submitting status URB\n");
status = usb_submit_urb(hub->urb, GFP_NOIO);
if (status < 0)
dev_err(hub->intfdev, "activate --> %d\n", status);

@@ -3711,7 +3714,7 @@ static int hub_suspend(struct usb_interf
}
}

- dev_dbg(&intf->dev, "%s\n", __func__);
+ dev_info(&intf->dev, "%s\n", __func__);

/* stop hub_wq and related activity */
hub_quiesce(hub, HUB_SUSPEND);
@@ -3756,7 +3759,7 @@ static int hub_resume(struct usb_interfa
{
struct usb_hub *hub = usb_get_intfdata(intf);

- dev_dbg(&intf->dev, "%s\n", __func__);
+ dev_info(&intf->dev, "%s\n", __func__);
hub_activate(hub, HUB_RESUME);

/*

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer still triggered
crash:
WARNING in usb_submit_urb

hub 3-0:1.0: hub_activate type 4
hub 3-0:1.0: Submitting status URB
hub 3-0:1.0: Submitting status URB
------------[ cut here ]------------
URB 00000000a8d7a6c6 submitted while active
WARNING: CPU: 0 PID: 3405 at drivers/usb/core/urb.c:363
usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:363

Kernel panic - not syncing: panic_on_warn set ...

CPU: 0 PID: 3405 Comm: kworker/0:2 Not tainted 4.20.0-rc1+ #1

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Workqueue: events_power_efficient hub_init_func2
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]

dump_stack+0x253/0x3bb lib/dump_stack.c:113
panic+0x2cb/0x586 kernel/panic.c:188
__warn.cold+0x20/0x4e kernel/panic.c:540
report_bug+0x263/0x2b0 lib/bug.c:186
fixup_bug arch/x86/kernel/traps.c:178 [inline]
fixup_bug arch/x86/kernel/traps.c:173 [inline]
do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:271
do_invalid_op+0x37/0x50 arch/x86/kernel/traps.c:290
invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:969
RIP: 0010:usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:363
Code: 89 de e8 93 22 7d fc 84 db 0f 85 fe f5 ff ff e8 46 21 7d fc 4c 89 fe
48 c7 c7 80 48 93 88 c6 05 13 1c 10 05 01 e8 20 96 46 fc <0f> 0b e9 dc f5

ff ff c7 45 c8 01 00 00 00 e9 94 f6 ff ff 41 be ed

RSP: 0018:ffff8881c64ef828 EFLAGS: 00010282

RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000

RDX: 0000000000000000 RSI: ffffffff81656e66 RDI: 0000000000000005
RBP: ffff8881c64ef888 R08: ffff8881c6532340 R09: ffffed103b5c5021
R10: ffffed103b5c5020 R11: ffff8881dae28107 R12: ffff8881c64ef9a0
R13: ffff8881c3c26050 R14: 00000000fffffff0 R15: ffff8881c0b0ca00
hub_activate+0xce0/0x1980 drivers/usb/core/hub.c:1218
hub_init_func2+0x1e/0x30 drivers/usb/core/hub.c:1243
process_one_work+0xd0c/0x1ce0 kernel/workqueue.c:2153
worker_thread+0x143/0x14a0 kernel/workqueue.c:2296
kthread+0x357/0x430 kernel/kthread.c:246

ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:352
Kernel Offset: disabled
Rebooting in 86400 seconds..

Tested on:

commit: e12e00e3 Merge tag 'kbuild-fixes-v4.20' of git://git.kerne..
git tree:
git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git

console output: https://syzkaller.appspot.com/x/log.txt?x=15d0b5bf200000

kernel config: https://syzkaller.appspot.com/x/.config?x=69667e62a5e247a7
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

patch: https://syzkaller.appspot.com/x/patch.diff?x=1244a26b200000

[Alan Stern]

On Tue, 16 Apr 2019, syzbot wrote:

> Hello,
>
> syzbot has tested the proposed patch but the reproducer still triggered
> crash:
> WARNING in usb_submit_urb
>
> hub 3-0:1.0: hub_activate type 4
> hub 3-0:1.0: Submitting status URB
> hub 3-0:1.0: Submitting status URB
> ------------[ cut here ]------------
> URB 00000000a8d7a6c6 submitted while active

The console output shows pretty clearly that there is a race. But I
can't quite see how it is caused. Let's try a little bit more
debugging.

Alan Stern


#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git e12e00e388de

--- a/drivers/usb/core/hub.c
+++ b/drivers/usb/core/hub.c

@@ -1016,6 +1016,9 @@ static void hub_activate(struct usb_hub

bool need_debounce_delay = false;
unsigned delay;

+ dev_info(hub->intfdev, "%p %s type %d discon %d\n",
+ hub, __func__, type, hub->disconnected);

+
/* Continue a partial initialization */
if (type == HUB_INIT2 || type == HUB_INIT3) {
device_lock(&hdev->dev);

@@ -1254,6 +1257,7 @@ static void hub_activate(struct usb_hub

init3:
hub->quiescing = 0;

+ dev_info(hub->intfdev, "%p Submitting status URB\n", hub);

status = usb_submit_urb(hub->urb, GFP_NOIO);
if (status < 0)
dev_err(hub->intfdev, "activate --> %d\n", status);

@@ -1299,6 +1303,8 @@ static void hub_quiesce(struct usb_hub *
unsigned long flags;
int i;

+ dev_info(hub->intfdev, "%p %s type %d\n", hub, __func__, type);
+
/* hub_wq and related activity won't re-trigger */
spin_lock_irqsave(&hub->irq_urb_lock, flags);
hub->quiescing = 1;
@@ -3711,7 +3717,7 @@ static int hub_suspend(struct usb_interf

}
}

- dev_dbg(&intf->dev, "%s\n", __func__);

+ dev_info(&intf->dev, "%p %s\n", hub, __func__);

/* stop hub_wq and related activity */
hub_quiesce(hub, HUB_SUSPEND);

@@ -3756,7 +3762,7 @@ static int hub_resume(struct usb_interfa

{
struct usb_hub *hub = usb_get_intfdata(intf);

- dev_dbg(&intf->dev, "%s\n", __func__);

+ dev_info(&intf->dev, "%p %s\n", hub, __func__);
hub_activate(hub, HUB_RESUME);

/*

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer still triggered
crash:
WARNING in usb_submit_urb

hub 3-0:1.0: 0000000015733366 hub_activate type 4 discon 0
hub 3-0:1.0: 0000000015733366 Submitting status URB
hub 3-0:1.0: 0000000015733366 Submitting status URB
------------[ cut here ]------------
URB 000000006ea6e83c submitted while active
WARNING: CPU: 0 PID: 6476 at drivers/usb/core/urb.c:363

usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:363
Kernel panic - not syncing: panic_on_warn set ...

CPU: 0 PID: 6476 Comm: kworker/0:3 Not tainted 4.20.0-rc1+ #1

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Workqueue: events_power_efficient hub_init_func2
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x253/0x3bb lib/dump_stack.c:113
panic+0x2cb/0x586 kernel/panic.c:188
__warn.cold+0x20/0x4e kernel/panic.c:540
report_bug+0x263/0x2b0 lib/bug.c:186
fixup_bug arch/x86/kernel/traps.c:178 [inline]
fixup_bug arch/x86/kernel/traps.c:173 [inline]
do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:271
do_invalid_op+0x37/0x50 arch/x86/kernel/traps.c:290
invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:969
RIP: 0010:usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:363

Code: 89 de e8 d3 21 7d fc 84 db 0f 85 fe f5 ff ff e8 86 20 7d fc 4c 89 fe
48 c7 c7 00 49 93 88 c6 05 d3 1b 10 05 01 e8 60 95 46 fc <0f> 0b e9 dc f5

ff ff c7 45 c8 01 00 00 00 e9 94 f6 ff ff 41 be ed

RSP: 0018:ffff8881c397f820 EFLAGS: 00010286

RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff81656e66 RDI: 0000000000000005

RBP: ffff8881c397f880 R08: ffff8881b82185c0 R09: ffff8881b8218e88
R10: ffff8881b82185c0 R11: 0000000000000000 R12: ffff8881c397f9a0
R13: ffff8881cdf73b10 R14: 00000000fffffff0 R15: ffff8881d507d700
hub_activate+0xcef/0x19f0 drivers/usb/core/hub.c:1219
hub_init_func2+0x1e/0x30 drivers/usb/core/hub.c:1244

process_one_work+0xd0c/0x1ce0 kernel/workqueue.c:2153
worker_thread+0x143/0x14a0 kernel/workqueue.c:2296
kthread+0x357/0x430 kernel/kthread.c:246
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:352
Kernel Offset: disabled
Rebooting in 86400 seconds..


Tested on:

commit: e12e00e3 Merge tag 'kbuild-fixes-v4.20' of git://git.kerne..
git tree:
git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git

console output: https://syzkaller.appspot.com/x/log.txt?x=166b19b7200000

kernel config: https://syzkaller.appspot.com/x/.config?x=69667e62a5e247a7
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

patch: https://syzkaller.appspot.com/x/patch.diff?x=144ac55b200000

[Alan Stern]

On Tue, 16 Apr 2019, syzbot wrote:

> Hello,
>
> syzbot has tested the proposed patch but the reproducer still triggered
> crash:
> WARNING in usb_submit_urb
>
> hub 3-0:1.0: 0000000015733366 hub_activate type 4 discon 0
> hub 3-0:1.0: 0000000015733366 Submitting status URB
> hub 3-0:1.0: 0000000015733366 Submitting status URB
> ------------[ cut here ]------------
> URB 000000006ea6e83c submitted while active
> WARNING: CPU: 0 PID: 6476 at drivers/usb/core/urb.c:363

Here's more of the context, showing the important part:

[ 115.102684] hub 3-0:1.0: USB hub found
[ 115.107011] hub 3-0:1.0: 8 ports detected

A new USB bus was registered and its root hub was probed.

[ 115.114470] hub 3-0:1.0: 0000000015733366 hub_activate type 0 discon 0

Type 0 is HUB_INIT, the first stage of activating a new hub. This
stage involves a long delay, so it calls
usb_autopm_get_interface_no_resume(), schedules a delayed work routine
to carry out the next stage, and returns.

[ 115.180282] hub 3-0:1.0: 0000000015733366 hub_suspend
[ 115.214681] hub 3-0:1.0: 0000000015733366 hub_quiesce type 2

Type 2 quiesce is HUB_SUSPEND. Somehow the hub was autosuspended even
though its runtime PM usage count was elevated!

[ 115.231986] hub 3-0:1.0: 0000000015733366 hub_resume
[ 115.241706] hub 3-0:1.0: 0000000015733366 hub_activate type 1 discon 0
[ 115.249931] hub 3-0:1.0: 0000000015733366 hub_activate type 4 discon 0

Then the hub was resumed again. Type 1 activation is HUB_INIT2, the
second stage of the original hub activation. Type 4 is HUB_RESUME.
Evidently both types of activation are running concurrently.

[ 115.276027] hub 3-0:1.0: 0000000015733366 Submitting status URB
[ 115.288239] hub 3-0:1.0: 0000000015733366 Submitting status URB
[ 115.295347] ------------[ cut here ]------------
[ 115.300505] URB 000000006ea6e83c submitted while active

Both activation threads submit the same status URB, leading to the
error.

So the question is: Why was the hub suspended at a time when it should
have remained active? Let's see what the runtime PM values are when
hub_suspend is called.

@@ -3711,7 +3717,11 @@ static int hub_suspend(struct usb_interf

}
}

- dev_dbg(&intf->dev, "%s\n", __func__);

+ dev_info(&intf->dev, "%p %s disable %d usage %d status %d\n",
+ hub, __func__,
+ intf->dev.power.disable_depth,
+ atomic_read(&intf->dev.power.usage_count),
+ intf->dev.power.runtime_status);

/* stop hub_wq and related activity */
hub_quiesce(hub, HUB_SUSPEND);

@@ -3756,7 +3766,7 @@ static int hub_resume(struct usb_interfa

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer still triggered
crash:
WARNING in usb_submit_urb

hub 3-0:1.0: 0000000090da6a2e hub_activate type 4 discon 0
hub 3-0:1.0: 0000000090da6a2e Submitting status URB
hub 3-0:1.0: 0000000090da6a2e Submitting status URB
------------[ cut here ]------------
URB 000000000612b84f submitted while active
WARNING: CPU: 1 PID: 3403 at drivers/usb/core/urb.c:363

usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:363
Kernel panic - not syncing: panic_on_warn set ...

CPU: 1 PID: 3403 Comm: kworker/1:2 Not tainted 4.20.0-rc1+ #1

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Workqueue: events_power_efficient hub_init_func2
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x253/0x3bb lib/dump_stack.c:113
panic+0x2cb/0x586 kernel/panic.c:188
__warn.cold+0x20/0x4e kernel/panic.c:540
report_bug+0x263/0x2b0 lib/bug.c:186
fixup_bug arch/x86/kernel/traps.c:178 [inline]
fixup_bug arch/x86/kernel/traps.c:173 [inline]
do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:271
do_invalid_op+0x37/0x50 arch/x86/kernel/traps.c:290
invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:969
RIP: 0010:usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:363

Code: 89 de e8 73 20 7d fc 84 db 0f 85 fe f5 ff ff e8 26 1f 7d fc 4c 89 fe
48 c7 c7 60 49 93 88 c6 05 b3 1a 10 05 01 e8 00 94 46 fc <0f> 0b e9 dc f5

ff ff c7 45 c8 01 00 00 00 e9 94 f6 ff ff 41 be ed

RSP: 0018:ffff8881c64d7820 EFLAGS: 00010286

RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff81656e66 RDI: 0000000000000005

RBP: ffff8881c64d7880 R08: ffff8881c64fe2c0 R09: ffff8881c64feb88
R10: ffff8881c64fe2c0 R11: 0000000000000000 R12: ffff8881c64d79a0
R13: ffff8881ba64f690 R14: 00000000fffffff0 R15: ffff8881cc9bd200

hub_activate+0xcef/0x19f0 drivers/usb/core/hub.c:1219
hub_init_func2+0x1e/0x30 drivers/usb/core/hub.c:1244
process_one_work+0xd0c/0x1ce0 kernel/workqueue.c:2153
worker_thread+0x143/0x14a0 kernel/workqueue.c:2296
kthread+0x357/0x430 kernel/kthread.c:246
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:352
Kernel Offset: disabled
Rebooting in 86400 seconds..


Tested on:

commit: e12e00e3 Merge tag 'kbuild-fixes-v4.20' of git://git.kerne..
git tree:
git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git

console output: https://syzkaller.appspot.com/x/log.txt?x=154bbb87200000

kernel config: https://syzkaller.appspot.com/x/.config?x=69667e62a5e247a7
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

patch: https://syzkaller.appspot.com/x/patch.diff?x=1721f267200000

[Alan Stern]

On Tue, 16 Apr 2019, syzbot wrote:

> Hello,
>
> syzbot has tested the proposed patch but the reproducer still triggered
> crash:
> WARNING in usb_submit_urb
>
> hub 3-0:1.0: 0000000090da6a2e hub_activate type 4 discon 0
> hub 3-0:1.0: 0000000090da6a2e Submitting status URB
> hub 3-0:1.0: 0000000090da6a2e Submitting status URB
> ------------[ cut here ]------------
> URB 000000000612b84f submitted while active
> WARNING: CPU: 1 PID: 3403 at drivers/usb/core/urb.c:363
> usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:363

I'm still having trouble understanding this. Here's some more
debugging.

Alan Stern

#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git e12e00e388de

--- a/drivers/usb/core/hub.c
+++ b/drivers/usb/core/hub.c
@@ -1016,6 +1016,9 @@ static void hub_activate(struct usb_hub
bool need_debounce_delay = false;
unsigned delay;

+ dev_info(hub->intfdev, "%p %s type %d discon %d\n",
+ hub, __func__, type, hub->disconnected);
+
/* Continue a partial initialization */
if (type == HUB_INIT2 || type == HUB_INIT3) {
device_lock(&hdev->dev);

@@ -1299,6 +1302,8 @@ static void hub_quiesce(struct usb_hub *

unsigned long flags;
int i;

+ dev_info(hub->intfdev, "%p %s type %d\n", hub, __func__, type);
+
/* hub_wq and related activity won't re-trigger */
spin_lock_irqsave(&hub->irq_urb_lock, flags);
hub->quiescing = 1;

@@ -3711,7 +3716,9 @@ static int hub_suspend(struct usb_interf

}
}

- dev_dbg(&intf->dev, "%s\n", __func__);

+ dev_info(&intf->dev, "%p %s usage %d\n",
+ hub, __func__,
+ atomic_read(&intf->dev.power.usage_count));

/* stop hub_wq and related activity */
hub_quiesce(hub, HUB_SUSPEND);

@@ -3756,7 +3763,7 @@ static int hub_resume(struct usb_interfa

{
struct usb_hub *hub = usb_get_intfdata(intf);

- dev_dbg(&intf->dev, "%s\n", __func__);
+ dev_info(&intf->dev, "%p %s\n", hub, __func__);
hub_activate(hub, HUB_RESUME);

/*

Index: usb-devel/drivers/usb/core/driver.c
===================================================================
--- usb-devel.orig/drivers/usb/core/driver.c
+++ usb-devel/drivers/usb/core/driver.c

@@ -358,7 +358,11 @@ static int usb_probe_interface(struct de
intf->needs_altsetting0 = 0;
}

+ dev_info(dev, "pre-probe usage %d\n",
+ atomic_read(&intf->dev.power.usage_count));
error = driver->probe(intf, id);
+ dev_info(dev, "post-probe usage %d\n",
+ atomic_read(&intf->dev.power.usage_count));
if (error)
goto err;

@@ -420,7 +424,11 @@ static int usb_unbind_interface(struct d
if (!driver->soft_unbind || udev->state == USB_STATE_NOTATTACHED)
usb_disable_interface(udev, intf, false);

+ dev_info(dev, "pre-discon usage %d\n",
+ atomic_read(&intf->dev.power.usage_count));
driver->disconnect(intf);
+ dev_info(dev, "post-discon usage %d\n",
+ atomic_read(&intf->dev.power.usage_count));

/* Free streams */
for (i = 0, j = 0; i < intf->cur_altsetting->desc.bNumEndpoints; i++) {

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer still triggered
crash:
WARNING in usb_submit_urb

hub 3-0:1.0: 00000000e9b0f156 hub_resume
hub 3-0:1.0: 00000000e9b0f156 hub_activate type 4 discon 0
hub 3-0:1.0: 00000000e9b0f156 hub_activate type 1 discon 0
------------[ cut here ]------------
URB 0000000098fd290c submitted while active
WARNING: CPU: 0 PID: 12 at drivers/usb/core/urb.c:363
usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:363

Kernel panic - not syncing: panic_on_warn set ...

CPU: 0 PID: 12 Comm: kworker/0:1 Not tainted 4.20.0-rc1+ #1

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Workqueue: events_power_efficient hub_init_func2
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x253/0x3bb lib/dump_stack.c:113
panic+0x2cb/0x586 kernel/panic.c:188
__warn.cold+0x20/0x4e kernel/panic.c:540
report_bug+0x263/0x2b0 lib/bug.c:186
fixup_bug arch/x86/kernel/traps.c:178 [inline]
fixup_bug arch/x86/kernel/traps.c:173 [inline]
do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:271
do_invalid_op+0x37/0x50 arch/x86/kernel/traps.c:290
invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:969
RIP: 0010:usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:363

Code: 89 de e8 43 21 7d fc 84 db 0f 85 fe f5 ff ff e8 f6 1f 7d fc 4c 89 fe
48 c7 c7 00 49 93 88 c6 05 43 1b 10 05 01 e8 d0 94 46 fc <0f> 0b e9 dc f5

ff ff c7 45 c8 01 00 00 00 e9 94 f6 ff ff 41 be ed

RSP: 0018:ffff8881d9b1f820 EFLAGS: 00010286

RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff81656e66 RDI: 0000000000000005

RBP: ffff8881d9b1f880 R08: ffff8881d9b12300 R09: ffffed103b5c3ef9
R10: ffffed103b5c3ef8 R11: ffff8881dae1f7c7 R12: ffff8881d9b1f9a0
R13: ffff8881c49b9210 R14: 00000000fffffff0 R15: ffff8881c990dd00
hub_activate+0xcc2/0x19c0 drivers/usb/core/hub.c:1218
hub_init_func2+0x1e/0x30 drivers/usb/core/hub.c:1243

process_one_work+0xd0c/0x1ce0 kernel/workqueue.c:2153
worker_thread+0x143/0x14a0 kernel/workqueue.c:2296
kthread+0x357/0x430 kernel/kthread.c:246
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:352
Kernel Offset: disabled
Rebooting in 86400 seconds..


Tested on:

commit: e12e00e3 Merge tag 'kbuild-fixes-v4.20' of git://git.kerne..
git tree:
git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git

console output: https://syzkaller.appspot.com/x/log.txt?x=16cacd2d200000

kernel config: https://syzkaller.appspot.com/x/.config?x=69667e62a5e247a7
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

patch: https://syzkaller.appspot.com/x/patch.diff?x=17b94d8f200000

[Alan Stern]

On Wed, 17 Apr 2019, Alan Stern wrote:

> I'm still having trouble understanding this. Here's some more
> debugging.

Let's try this again. The patch format was wrong.

Alan Stern

--- a/drivers/usb/core/driver.c
+++ b/drivers/usb/core/driver.c

[Alan Stern]

On Thu, 18 Apr 2019, Alan Stern wrote:

> On Wed, 17 Apr 2019, Alan Stern wrote:
>
> > I'm still having trouble understanding this. Here's some more
> > debugging.
>
> Let's try this again. The patch format was wrong.

One more try, this time with the syz command line.

Incidentally, the console log from the last test had a very troubling
entry showing the runtime PM usage counter for the hub interface was
set to -4! Whatever caused the counter to go negative is probably also
the reason for this bug.

Alan Stern


#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git e12e00e388de

[syzbot]

Hello,

syzbot has tested the proposed patch but the reproducer still triggered
crash:
WARNING in usb_submit_urb

hub 3-0:1.0: 00000000b89ba4aa hub_resume
hub 3-0:1.0: 00000000b89ba4aa hub_activate type 1 discon 0
hub 3-0:1.0: 00000000b89ba4aa hub_activate type 4 discon 0
------------[ cut here ]------------
URB 0000000031fb463e submitted while active
WARNING: CPU: 0 PID: 2917 at drivers/usb/core/urb.c:363

usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:363
Kernel panic - not syncing: panic_on_warn set ...

CPU: 0 PID: 2917 Comm: kworker/0:2 Not tainted 4.20.0-rc1+ #1

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Workqueue: events_power_efficient hub_init_func2
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x253/0x3bb lib/dump_stack.c:113
panic+0x2cb/0x586 kernel/panic.c:188
__warn.cold+0x20/0x4e kernel/panic.c:540
report_bug+0x263/0x2b0 lib/bug.c:186
fixup_bug arch/x86/kernel/traps.c:178 [inline]
fixup_bug arch/x86/kernel/traps.c:173 [inline]
do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:271
do_invalid_op+0x37/0x50 arch/x86/kernel/traps.c:290
invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:969
RIP: 0010:usb_submit_urb+0x1110/0x1400 drivers/usb/core/urb.c:363
Code: 89 de e8 43 21 7d fc 84 db 0f 85 fe f5 ff ff e8 f6 1f 7d fc 4c 89 fe

48 c7 c7 00 49 93 88 c6 05 43 1c 10 05 01 e8 d0 94 46 fc <0f> 0b e9 dc f5

ff ff c7 45 c8 01 00 00 00 e9 94 f6 ff ff 41 be ed

RSP: 0018:ffff8881cb9cf820 EFLAGS: 00010286

RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff81656e66 RDI: 0000000000000005

RBP: ffff8881cb9cf880 R08: ffff8881cb9c2480 R09: ffffed103b5c5021
R10: ffffed103b5c5020 R11: ffff8881dae28107 R12: ffff8881cb9cf9a0
R13: ffff8881c43d9250 R14: 00000000fffffff0 R15: ffff8881d7718300

hub_activate+0xcc2/0x19c0 drivers/usb/core/hub.c:1218
hub_init_func2+0x1e/0x30 drivers/usb/core/hub.c:1243
process_one_work+0xd0c/0x1ce0 kernel/workqueue.c:2153
worker_thread+0x143/0x14a0 kernel/workqueue.c:2296
kthread+0x357/0x430 kernel/kthread.c:246
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:352
Kernel Offset: disabled
Rebooting in 86400 seconds..


Tested on:

commit: e12e00e3 Merge tag 'kbuild-fixes-v4.20' of git://git.kerne..
git tree:
git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git

console output: https://syzkaller.appspot.com/x/log.txt?x=16a7f38f200000

kernel config: https://syzkaller.appspot.com/x/.config?x=69667e62a5e247a7
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

patch: https://syzkaller.appspot.com/x/patch.diff?x=112bbbbf200000

[Alan Stern]

On Thu, 18 Apr 2019, syzbot wrote:

> Hello,
>
> syzbot has tested the proposed patch but the reproducer still triggered
> crash:
> WARNING in usb_submit_urb
>
> hub 3-0:1.0: 00000000b89ba4aa hub_resume
> hub 3-0:1.0: 00000000b89ba4aa hub_activate type 1 discon 0
> hub 3-0:1.0: 00000000b89ba4aa hub_activate type 4 discon 0

Oh, now I see the problem. And it was my fault to begin with...
Let's see if this fixes it.

@@ -473,11 +481,6 @@ static int usb_unbind_interface(struct d
pm_runtime_disable(dev);
pm_runtime_set_suspended(dev);

- /* Undo any residual pm_autopm_get_interface_* calls */
- for (r = atomic_read(&intf->pm_usage_cnt); r > 0; --r)
- usb_autopm_put_interface_no_suspend(intf);
- atomic_set(&intf->pm_usage_cnt, 0);
-
if (!error)
usb_autosuspend_device(udev);

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger
crash:

Reported-and-tested-by:
syzbot+7634ed...@syzkaller.appspotmail.com

Tested on:

commit: e12e00e3 Merge tag 'kbuild-fixes-v4.20' of git://git.kerne..
git tree:
git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git

kernel config: https://syzkaller.appspot.com/x/.config?x=69667e62a5e247a7
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

patch: https://syzkaller.appspot.com/x/patch.diff?x=17a7eaa0a00000

[Alan Stern]

On Thu, 18 Apr 2019, syzbot wrote:

Great! Okay, let's try one more time, with the patch I will actually
submit.

Alan Stern


#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git e12e00e388de

--- a/include/linux/usb.h
+++ b/include/linux/usb.h
@@ -200,7 +200,6 @@ usb_find_last_int_out_endpoint(struct us
* @dev: driver model's view of this device
* @usb_dev: if an interface is bound to the USB major, this will point
* to the sysfs representation for that device.
- * @pm_usage_cnt: PM usage counter for this interface
* @reset_ws: Used for scheduling resets from atomic context.
* @resetting_device: USB core reset the device, so use alt setting 0 as
* current; needs bandwidth alloc after reset.
@@ -257,7 +256,6 @@ struct usb_interface {

struct device dev; /* interface specific device info */
struct device *usb_dev;
- atomic_t pm_usage_cnt; /* usage counter for autosuspend */
struct work_struct reset_ws; /* for resets in atomic context */
};
#define to_usb_interface(d) container_of(d, struct usb_interface, dev)
--- a/drivers/usb/core/driver.c
+++ b/drivers/usb/core/driver.c
@@ -473,11 +473,6 @@ static int usb_unbind_interface(struct d

pm_runtime_disable(dev);
pm_runtime_set_suspended(dev);

- /* Undo any residual pm_autopm_get_interface_* calls */
- for (r = atomic_read(&intf->pm_usage_cnt); r > 0; --r)
- usb_autopm_put_interface_no_suspend(intf);
- atomic_set(&intf->pm_usage_cnt, 0);
-
if (!error)
usb_autosuspend_device(udev);

@@ -1633,7 +1628,6 @@ void usb_autopm_put_interface(struct usb
int status;

usb_mark_last_busy(udev);
- atomic_dec(&intf->pm_usage_cnt);
status = pm_runtime_put_sync(&intf->dev);
dev_vdbg(&intf->dev, "%s: cnt %d -> %d\n",
__func__, atomic_read(&intf->dev.power.usage_count),
@@ -1662,7 +1656,6 @@ void usb_autopm_put_interface_async(stru
int status;

usb_mark_last_busy(udev);
- atomic_dec(&intf->pm_usage_cnt);
status = pm_runtime_put(&intf->dev);
dev_vdbg(&intf->dev, "%s: cnt %d -> %d\n",
__func__, atomic_read(&intf->dev.power.usage_count),
@@ -1684,7 +1677,6 @@ void usb_autopm_put_interface_no_suspend
struct usb_device *udev = interface_to_usbdev(intf);

usb_mark_last_busy(udev);
- atomic_dec(&intf->pm_usage_cnt);
pm_runtime_put_noidle(&intf->dev);
}
EXPORT_SYMBOL_GPL(usb_autopm_put_interface_no_suspend);
@@ -1715,8 +1707,6 @@ int usb_autopm_get_interface(struct usb_
status = pm_runtime_get_sync(&intf->dev);
if (status < 0)
pm_runtime_put_sync(&intf->dev);
- else
- atomic_inc(&intf->pm_usage_cnt);
dev_vdbg(&intf->dev, "%s: cnt %d -> %d\n",
__func__, atomic_read(&intf->dev.power.usage_count),
status);
@@ -1750,8 +1740,6 @@ int usb_autopm_get_interface_async(struc
status = pm_runtime_get(&intf->dev);
if (status < 0 && status != -EINPROGRESS)
pm_runtime_put_noidle(&intf->dev);
- else
- atomic_inc(&intf->pm_usage_cnt);
dev_vdbg(&intf->dev, "%s: cnt %d -> %d\n",
__func__, atomic_read(&intf->dev.power.usage_count),
status);
@@ -1775,7 +1763,6 @@ void usb_autopm_get_interface_no_resume(
struct usb_device *udev = interface_to_usbdev(intf);

usb_mark_last_busy(udev);
- atomic_inc(&intf->pm_usage_cnt);
pm_runtime_get_noresume(&intf->dev);
}
EXPORT_SYMBOL_GPL(usb_autopm_get_interface_no_resume);
--- a/Documentation/driver-api/usb/power-management.rst
+++ b/Documentation/driver-api/usb/power-management.rst
@@ -370,11 +370,15 @@ autosuspend the interface's device. Whe
then the interface is considered to be idle, and the kernel may
autosuspend the device.

-Drivers need not be concerned about balancing changes to the usage
-counter; the USB core will undo any remaining "get"s when a driver
-is unbound from its interface. As a corollary, drivers must not call
-any of the ``usb_autopm_*`` functions after their ``disconnect``
-routine has returned.
+Drivers must be careful to balance their overall changes to the usage
+counter. Unbalanced "get"s will remain in effect when a driver is
+unbound from its interface, preventing the device from going into
+runtime suspend should the interface be bound to a driver again. On
+the other hand, drivers are allowed to achieve this balance by calling
+the ``usb_autopm_*`` functions even after their ``disconnect`` routine
+has returned -- say from within a work-queue routine -- provided they
+retain an active reference to the interface (via ``usb_get_intf`` and
+``usb_put_intf``).

Drivers using the async routines are responsible for their own
synchronization and mutual exclusion.
--- a/drivers/usb/storage/realtek_cr.c
+++ b/drivers/usb/storage/realtek_cr.c
@@ -763,18 +763,16 @@ static void rts51x_suspend_timer_fn(stru
break;
case RTS51X_STAT_IDLE:
case RTS51X_STAT_SS:
- usb_stor_dbg(us, "RTS51X_STAT_SS, intf->pm_usage_cnt:%d, power.usage:%d\n",
- atomic_read(&us->pusb_intf->pm_usage_cnt),
+ usb_stor_dbg(us, "RTS51X_STAT_SS, power.usage:%d\n",
atomic_read(&us->pusb_intf->dev.power.usage_count));

- if (atomic_read(&us->pusb_intf->pm_usage_cnt) > 0) {
+ if (atomic_read(&us->pusb_intf->dev.power.usage_count) > 0) {
usb_stor_dbg(us, "Ready to enter SS state\n");
rts51x_set_stat(chip, RTS51X_STAT_SS);
/* ignore mass storage interface's children */
pm_suspend_ignore_children(&us->pusb_intf->dev, true);
usb_autopm_put_interface_async(us->pusb_intf);
- usb_stor_dbg(us, "RTS51X_STAT_SS 01, intf->pm_usage_cnt:%d, power.usage:%d\n",
- atomic_read(&us->pusb_intf->pm_usage_cnt),
+ usb_stor_dbg(us, "RTS51X_STAT_SS 01, power.usage:%d\n",
atomic_read(&us->pusb_intf->dev.power.usage_count));
}
break;
@@ -807,11 +805,10 @@ static void rts51x_invoke_transport(stru
int ret;

if (working_scsi(srb)) {
- usb_stor_dbg(us, "working scsi, intf->pm_usage_cnt:%d, power.usage:%d\n",
- atomic_read(&us->pusb_intf->pm_usage_cnt),
+ usb_stor_dbg(us, "working scsi, power.usage:%d\n",
atomic_read(&us->pusb_intf->dev.power.usage_count));

- if (atomic_read(&us->pusb_intf->pm_usage_cnt) <= 0) {
+ if (atomic_read(&us->pusb_intf->dev.power.usage_count) <= 0) {
ret = usb_autopm_get_interface(us->pusb_intf);
usb_stor_dbg(us, "working scsi, ret=%d\n", ret);
}

[syzbot]

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger
crash:

Reported-and-tested-by:
syzbot+7634ed...@syzkaller.appspotmail.com

Tested on:

commit: e12e00e3 Merge tag 'kbuild-fixes-v4.20' of git://git.kerne..
git tree:
git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
kernel config: https://syzkaller.appspot.com/x/.config?x=69667e62a5e247a7
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

patch: https://syzkaller.appspot.com/x/patch.diff?x=12231967200000