On Thu, Jun 18, 2020 at 2:49 AM Tetsuo Handa
<penguin-kernel@xxxxxxxxxxxxxxxxxxx> wrote:
>
> On 2020/06/08 11:24, Tetsuo Handa wrote:
> > As far as I tested, it seems that usb_kill_urb() sometimes fails to call
> > wdm_out_callback() despite the comment for usb_kill_urb() says
> >
> > * This routine cancels an in-progress request. It is guaranteed that
> > * upon return all completion handlers will have finished and the URB
> > * will be totally idle and available for reuse. These features make
> > * this an ideal way to stop I/O in a disconnect() callback or close()
> > * function. If the request has not already finished or been unlinked
> > * the completion handler will see urb->status == -ENOENT.
> >
> > . Is something still wrong? Or just replacing
> >
> > BUG_ON(test_bit(WDM_IN_USE, &desc->flags) &&
> > !test_bit(WDM_DISCONNECTING, &desc->flags));
> >
> > with
> >
> > wait_event(desc->wait, !test_bit(WDM_IN_USE, &desc->flags) ||
> > test_bit(WDM_DISCONNECTING, &desc->flags));
> >
> > in the patch shown below is sufficient?
>
> How is the progress?
>
> Another debug printk() patch shown below says that while wdm_flush() waits for
> clearing of WDM_IN_USE using wait_event(), concurrently executed wdm_write() also
> waits for clearing of WDM_IN_USE using wait_event_interruptible(), and wdm_write() can
> immediately set WDM_IN_USE again as soon as returning from wait_event_interruptible()
> even if somebody was already waiting at wdm_flush() to clear WDM_IN_USE.
>
> That is, wait_event() in wdm_flush() does not know whether there is usb_submit_urb()
> request which is started after wait_event() found that WDM_IN_USE was cleared. Then,
> what does this wait_event() in wdm_flush() want to flush? There is no need to wait for
> completion of usb_submit_urb() ?
Oliver, any chance you could help us with fixing the hang in this
driver? You seem to be its original author. This hang is one of the
top crashers on syzbot, with over 32000 crashed kernels.
>
> diff --git a/drivers/usb/class/cdc-wdm.c b/drivers/usb/class/cdc-wdm.c
> index e3db6fbeadef..d2c4d8b9cc18 100644
> --- a/drivers/usb/class/cdc-wdm.c
> +++ b/drivers/usb/class/cdc-wdm.c
> @@ -82,6 +82,7 @@ struct wdm_device {
> spinlock_t iuspin;
>
> unsigned long flags;
> + atomic_t flushers;
> u16 bufsize;
> u16 wMaxCommand;
> u16 wMaxPacketSize;
> @@ -151,7 +152,7 @@ static void wdm_out_callback(struct urb *urb)
> kfree(desc->outbuf);
> desc->outbuf = NULL;
> clear_bit(WDM_IN_USE, &desc->flags);
> - wake_up(&desc->wait);
> + wake_up_all(&desc->wait);
> }
>
> static void wdm_in_callback(struct urb *urb)
> @@ -417,6 +418,13 @@ static ssize_t wdm_write
> req->wValue = 0;
> req->wIndex = desc->inum; /* already converted */
> req->wLength = cpu_to_le16(count);
> + {
> + const int flushers = atomic_read(&desc->flushers);
> + if (flushers) {
> + printk(KERN_ERR "There is %u flushers.\n", flushers);
> + BUG_ON(1);
> + }
> + }
> set_bit(WDM_IN_USE, &desc->flags);
> desc->outbuf = buf;
>
> @@ -424,6 +432,7 @@ static ssize_t wdm_write
> if (rv < 0) {
> desc->outbuf = NULL;
> clear_bit(WDM_IN_USE, &desc->flags);
> + wake_up_all(&desc->wait);
> dev_err(&desc->intf->dev, "Tx URB error: %d\n", rv);
> rv = usb_translate_errors(rv);
> goto out_free_mem_pm;
> @@ -587,15 +596,20 @@ static int wdm_flush(struct file *file, fl_owner_t id)
> {
> struct wdm_device *desc = file->private_data;
>
> - wait_event(desc->wait,
> - /*
> - * needs both flags. We cannot do with one
> - * because resetting it would cause a race
> - * with write() yet we need to signal
> - * a disconnect
> - */
> - !test_bit(WDM_IN_USE, &desc->flags) ||
> - test_bit(WDM_DISCONNECTING, &desc->flags));
> + /*
> + * needs both flags. We cannot do with one because resetting it would
> + * cause a race with write() yet we need to signal a disconnect
> + */
> + atomic_inc(&desc->flushers);
> + if (!wait_event_timeout(desc->wait, !test_bit(WDM_IN_USE, &desc->flags) ||
> + test_bit(WDM_DISCONNECTING, &desc->flags), 20 * HZ)) {
> + atomic_dec(&desc->flushers);
> + kill_urbs(desc);
> + BUG_ON(test_bit(WDM_IN_USE, &desc->flags) &&
> + !test_bit(WDM_DISCONNECTING, &desc->flags));
> + } else {
> + atomic_dec(&desc->flushers);
> + }
>
> /* cannot dereference desc->intf if WDM_DISCONNECTING */
> if (test_bit(WDM_DISCONNECTING, &desc->flags))
>
>
>
> [ 103.934085][ T118] usb 5-1: New USB device found, idVendor=2400, idProduct=4200, bcdDevice=42.ef
> [ 103.934093][ T118] usb 5-1: New USB device strings: Mfr=0, Product=0, SerialNumber=2
> [ 103.934100][ T118] usb 5-1: SerialNumber: syz
> [ 103.934145][ T4108] udc-core: couldn't find an available UDC or it's busy
> [ 103.934151][ T4108] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.934810][ T4109] udc-core: couldn't find an available UDC or it's busy
> [ 103.934821][ T4109] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.935385][ T4110] udc-core: couldn't find an available UDC or it's busy
> [ 103.935392][ T4110] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.935411][ T4106] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.938481][ T4112] udc-core: couldn't find an available UDC or it's busy
> [ 103.939183][ T4113] udc-core: couldn't find an available UDC or it's busy
> [ 103.939192][ T4113] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.939415][ T4114] udc-core: couldn't find an available UDC or it's busy
> [ 103.939421][ T4114] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.943069][ T4115] udc-core: couldn't find an available UDC or it's busy
> [ 103.943257][ T4116] udc-core: couldn't find an available UDC or it's busy
> [ 103.943266][ T4116] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.944118][ T4117] udc-core: couldn't find an available UDC or it's busy
> [ 103.944129][ T4117] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.944160][ T4118] udc-core: couldn't find an available UDC or it's busy
> [ 103.944169][ T4118] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.944738][ T4112] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.946715][ T4115] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.947159][ T4119] udc-core: couldn't find an available UDC or it's busy
> [ 103.947165][ T4119] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.947315][ T4120] udc-core: couldn't find an available UDC or it's busy
> [ 103.947324][ T4120] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.948093][ T4121] udc-core: couldn't find an available UDC or it's busy
> [ 103.948103][ T4121] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.949190][ T4122] udc-core: couldn't find an available UDC or it's busy
> [ 103.950070][ T4123] udc-core: couldn't find an available UDC or it's busy
> [ 103.950080][ T4123] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.950580][ T4124] udc-core: couldn't find an available UDC or it's busy
> [ 103.950587][ T4124] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.953081][ T4125] udc-core: couldn't find an available UDC or it's busy
> [ 103.953430][ T4126] udc-core: couldn't find an available UDC or it's busy
> [ 103.953437][ T4126] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.953963][ T4122] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.954780][ T4128] udc-core: couldn't find an available UDC or it's busy
> [ 103.954786][ T4128] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.955864][ T4129] udc-core: couldn't find an available UDC or it's busy
> [ 103.955872][ T4129] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.955962][ T4127] udc-core: couldn't find an available UDC or it's busy
> [ 103.955968][ T4127] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.956010][ T4125] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.958600][ T4130] udc-core: couldn't find an available UDC or it's busy
> [ 103.958962][ T4131] udc-core: couldn't find an available UDC or it's busy
> [ 103.958972][ T4131] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.959737][ T4132] udc-core: couldn't find an available UDC or it's busy
> [ 103.959749][ T4132] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.963405][ T4133] udc-core: couldn't find an available UDC or it's busy
> [ 103.963413][ T4133] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.964329][ T4134] udc-core: couldn't find an available UDC or it's busy
> [ 103.965201][ T4135] udc-core: couldn't find an available UDC or it's busy
> [ 103.965211][ T4135] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.965511][ T4136] udc-core: couldn't find an available UDC or it's busy
> [ 103.965520][ T4136] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.966011][ T4130] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.966939][ T4137] udc-core: couldn't find an available UDC or it's busy
> [ 103.966946][ T4137] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.967467][ T4138] udc-core: couldn't find an available UDC or it's busy
> [ 103.967473][ T4138] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.967909][ T4134] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.969292][ T4139] udc-core: couldn't find an available UDC or it's busy
> [ 103.969301][ T4139] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.969708][ T4140] udc-core: couldn't find an available UDC or it's busy
> [ 103.969717][ T4140] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.970343][ T4141] udc-core: couldn't find an available UDC or it's busy
> [ 103.973658][ T118] hub 5-1:118.0: bad descriptor, ignoring hub
> [ 103.974100][ T4142] udc-core: couldn't find an available UDC or it's busy
> [ 103.974107][ T4142] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.974518][ T4141] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.974657][ T4143] udc-core: couldn't find an available UDC or it's busy
> [ 103.974663][ T4143] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.975767][ T4144] udc-core: couldn't find an available UDC or it's busy
> [ 103.975774][ T4144] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.976777][ T118] hub: probe of 5-1:118.0 failed with error -5
> [ 103.977257][ T4145] udc-core: couldn't find an available UDC or it's busy
> [ 103.977263][ T4145] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.978020][ T4146] udc-core: couldn't find an available UDC or it's busy
> [ 103.978029][ T4146] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.978223][ T4148] udc-core: couldn't find an available UDC or it's busy
> [ 103.978229][ T4148] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.978388][ T4147] udc-core: couldn't find an available UDC or it's busy
> [ 103.978396][ T4147] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.980149][ T4149] udc-core: couldn't find an available UDC or it's busy
> [ 103.982395][ T4151] udc-core: couldn't find an available UDC or it's busy
> [ 103.982468][ T4152] udc-core: couldn't find an available UDC or it's busy
> [ 103.982478][ T4152] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.982674][ T4153] udc-core: couldn't find an available UDC or it's busy
> [ 103.982682][ T4153] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.982780][ T4150] udc-core: couldn't find an available UDC or it's busy
> [ 103.982788][ T4150] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.983634][ T4149] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.983843][ T118] cdc_wdm 5-1:118.0: cdc-wdm0: USB WDM device
> [ 103.984589][ T4155] udc-core: couldn't find an available UDC or it's busy
> [ 103.984595][ T4155] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.985615][ T4156] udc-core: couldn't find an available UDC or it's busy
> [ 103.985624][ T4156] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.985747][ T4151] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.985906][ T4157] udc-core: couldn't find an available UDC or it's busy
> [ 103.985912][ T4157] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.987838][ T4158] udc-core: couldn't find an available UDC or it's busy
> [ 103.987845][ T4158] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.987955][ T4159] udc-core: couldn't find an available UDC or it's busy
> [ 103.987962][ T4159] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.988233][ T4160] udc-core: couldn't find an available UDC or it's busy
> [ 103.988239][ T4160] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.989778][ T4161] udc-core: couldn't find an available UDC or it's busy
> [ 103.990308][ T4162] udc-core: couldn't find an available UDC or it's busy
> [ 103.990319][ T4162] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.991055][ T4163] udc-core: couldn't find an available UDC or it's busy
> [ 103.993669][ T4161] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.994007][ T4164] udc-core: couldn't find an available UDC or it's busy
> [ 103.994142][ T4165] udc-core: couldn't find an available UDC or it's busy
> [ 103.994151][ T4165] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.995212][ T4166] udc-core: couldn't find an available UDC or it's busy
> [ 103.995222][ T4166] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 103.996400][ T4163] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 106.505076][ T4164] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 124.793950][ T3360] cdc_wdm 5-1:118.0: Error in flush path: -2
> [ 124.793977][ T4165] cdc_wdm 5-1:118.0: Error in flush path: -2
> [ 124.793987][ T4166] cdc_wdm 5-1:118.0: Error in flush path: -2
> [ 124.793997][ T4164] cdc_wdm 5-1:118.0: Error in flush path: -2
> [ 124.794461][ T4163] cdc_wdm 5-1:118.0: Error in flush path: -2
> [ 124.798193][ T4168] udc-core: couldn't find an available UDC or it's busy
> [ 124.798218][ T4168] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 124.798292][ T4169] udc-core: couldn't find an available UDC or it's busy
> [ 124.798315][ T4169] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 124.798531][ T4170] udc-core: couldn't find an available UDC or it's busy
> [ 124.798537][ T4170] misc raw-gadget: fail, usb_gadget_probe_driver returned -19
> [ 124.812947][ T4170] There is 2 flushers.
> [ 124.812973][ T4161] cdc_wdm 5-1:118.0: Error in flush path: -32
> [ 124.812982][ T4168] cdc_wdm 5-1:118.0: Error in flush path: -32
> [ 124.812987][ T4169] cdc_wdm 5-1:118.0: Error in flush path: -32
> [ 124.823862][ T4170] ------------[ cut here ]------------
> [ 124.825440][ T4170] kernel BUG at drivers/usb/class/cdc-wdm.c:425!
> [ 124.827049][ T4170] invalid opcode: 0000 [#1] SMP KASAN
> [ 124.828439][ T4170] CPU: 3 PID: 4170 Comm: a.out Not tainted 5.7.0-rc5+ #27
> [ 124.830192][ T4170] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 02/27/2020
> [ 124.833192][ T4170] RIP: 0010:wdm_write+0xce7/0xf00
> [ 124.834683][ T4170] Code: 8b 7c 24 20 e8 ca 16 e5 fd 48 8b 54 24 18 e9 49 fa ff ff 89 34 24 e8 a8 ca be fd 8b 34 24 48 c7 c7 40 0f 01 86 e8 b2 2e aa fd <0f> 0b 48 89 ef e8 1f 16 e5 fd e9 ba f5 ff ff 48 89 cf 48 89 54 24
> [ 124.839523][ T4170] RSP: 0018:ffff8881e5ff7d30 EFLAGS: 00010286
> [ 124.841496][ T4170] RAX: 0000000000000014 RBX: ffff8881ee647800 RCX: ffffffff81d9c9dc
> [ 124.843673][ T4170] RDX: 0000000000000000 RSI: ffffffff81283169 RDI: ffff8881f6ce8dec
> [ 124.846399][ T4170] RBP: ffff8881ee647890 R08: ffffed103ed9e292 R09: ffff8881f6cf148f
> [ 124.848563][ T4170] R10: ffffed103dcc8f13 R11: ffffed103ed9e292 R12: 1ffff1103cbfefac
> [ 124.850559][ T4170] R13: 0000000000000010 R14: ffff8881e7fb5fac R15: 0000000000000000
> [ 124.852875][ T4170] FS: 00007fbf56199440(0000) GS:ffff8881f6cc0000(0000) knlGS:0000000000000000
> [ 124.855270][ T4170] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 124.857106][ T4170] CR2: 00007fbf55bef225 CR3: 00000001e61cd002 CR4: 00000000003606e0
> [ 124.859118][ T4170] Call Trace:
> [ 124.860123][ T4170] ? wdm_probe+0x2b0/0x2b0
> [ 124.861567][ T4170] ? remove_wait_queue+0x190/0x190
> [ 124.862896][ T4170] ? wdm_probe+0x2b0/0x2b0
> [ 124.864214][ T4170] __vfs_write+0x76/0x100
> [ 124.865314][ T4170] vfs_write+0x185/0x510
> [ 124.866418][ T4170] ksys_write+0xff/0x200
> [ 124.867653][ T4170] ? __ia32_sys_read+0xb0/0xb0
> [ 124.868851][ T4170] ? trace_hardirqs_off_caller+0x22/0x1c0
> [ 124.870283][ T4170] do_syscall_64+0x9b/0x510
> [ 124.871575][ T4170] entry_SYSCALL_64_after_hwframe+0x49/0xb3
> [ 124.873352][ T4170] RIP: 0033:0x7fbf55cc2469
> [ 124.874481][ T4170] Code: 00 f3 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d ff 49 2b 00 f7 d8 64 89 01 48
> [ 124.879954][ T4170] RSP: 002b:00007ffdc294dd58 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
> [ 124.882090][ T4170] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007fbf55cc2469
> [ 124.884573][ T4170] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000004
> [ 124.887178][ T4170] RBP: 0000000000000000 R08: 000000000000000f R09: 00007ffdc294dd8e
> [ 124.889941][ T4170] R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
> [ 124.892208][ T4170] R13: 00000000000193a4 R14: 0000000000000000 R15: 0000000000000000
> [ 124.894103][ T4170] Modules linked in:
> [ 124.895465][ T4170] ---[ end trace 2aea2ce7d52c22e0 ]---
> [ 124.897307][ T4170] RIP: 0010:wdm_write+0xce7/0xf00
> [ 124.898975][ T4170] Code: 8b 7c 24 20 e8 ca 16 e5 fd 48 8b 54 24 18 e9 49 fa ff ff 89 34 24 e8 a8 ca be fd 8b 34 24 48 c7 c7 40 0f 01 86 e8 b2 2e aa fd <0f> 0b 48 89 ef e8 1f 16 e5 fd e9 ba f5 ff ff 48 89 cf 48 89 54 24
> [ 124.905012][ T4170] RSP: 0018:ffff8881e5ff7d30 EFLAGS: 00010286
> [ 124.906793][ T4170] RAX: 0000000000000014 RBX: ffff8881ee647800 RCX: ffffffff81d9c9dc
> [ 124.909151][ T4170] RDX: 0000000000000000 RSI: ffffffff81283169 RDI: ffff8881f6ce8dec
> [ 124.911276][ T4170] RBP: ffff8881ee647890 R08: ffffed103ed9e292 R09: ffff8881f6cf148f
> [ 124.913784][ T4170] R10: ffffed103dcc8f13 R11: ffffed103ed9e292 R12: 1ffff1103cbfefac
> [ 124.916882][ T4170] R13: 0000000000000010 R14: ffff8881e7fb5fac R15: 0000000000000000
> [ 124.919078][ T4170] FS: 00007fbf56199440(0000) GS:ffff8881f6cc0000(0000) knlGS:0000000000000000
> [ 124.921484][ T4170] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 124.923337][ T4170] CR2: 00007fbf55bef225 CR3: 00000001e61cd002 CR4: 00000000003606e0
> [ 124.925606][ T4170] cdc_wdm 5-1:118.0: Error in flush path: -32
>
