On Wed, May 27, 2020 at 6:47 AM Tetsuo Handa <penguin-kernel@xxxxxxxxxxxxxxxxxxx> wrote: > > On 2020/05/25 22:32, Tetsuo Handa wrote: > > On 2020/05/25 21:06, Oliver Neukum wrote: > >> Am Freitag, den 22.05.2020, 17:26 +0900 schrieb Tetsuo Handa: > >>> On 2020/05/22 17:04, Oliver Neukum wrote: > >>>> May I ask you to redo the patch with comments added stating > >>>> that the wake up is done for the sake of wdm_flush(), change > >>>> the description and add the link to syzkaller? > >>> > >>> You can take over this patch. syzbot tried this patch on 2020/02/11 01:23 at > >>> https://syzkaller.appspot.com/bug?id=e7b761593b23eb50855b9ea31e3be5472b711186 , > >>> but this patch did not solve the problem syzbot has found. Thus, I don't add > >>> a link to syzkaller... > >> > >> Hi, > >> > >> this is odd. I looked at the driver and it looks to me like > >> pre/post_reset() is the only other place that touches WDM_IN_USE. > >> And it does so correctly. Any idea what could be wrong? > > > > I haven't understood the root cause of this problem. You were in the thread at > > https://groups.google.com/forum/#!msg/syzkaller-bugs/q3QMjt_t83c/GqP58GaTAQAJ . > > My patch was made from that thread (which simply makes sure to call wake_up_all() > > when clearing WDM_IN_USE bit) apart from the root cause of this problem. > > > > I might have found what is wrong. > > My understanding is that a process using /dev/raw-gadget is responsible for > reacting to every USB request. I don't know whether /dev/raw-gadget already > provides callback for aborting the in-flight USB requests (in order to resume > wdm_flush()) when /dev/raw-gadget is closed (due to explicit close() syscall or > implicit exit_files() from do_exit() upon SIGKILL). I assume /dev/raw-gadget > already provides such callback in the following paragraphs. raw-gadget should kill all unfishished USB requests when the file is closed. > > Since the reproducer is opening both /dev/raw-gadget (which is char-10-62) and > /dev/cdc-wdm0 (which is char-180-0), it seems that the kernel is falling into > deadlock condition due to the need to close both files when the reproducer is > killed. My guess is that since that process is stuck at wdm_flush() (due to > explicit close() syscall or implicit exit_files() from do_exit() upon SIGKILL), > that process cannot react to USB requests which are needed for resuming wdm_flush(). > Unexpectedly blocking a process which is responsible for reacting to USB requests > will look as if it is a broken hardware. Hm, so wdm_flush() is unable to finish unless an expected USB request is received from the device? This is a bug in the wdm driver then. Should we use wait_event_interruptible() instead of wait_event() in wdm_flush()? > > A debug printk() patch (shown below) says that the desc->command urb issued by > wdm_write() never gets wdm_out_callback(). I guess that it is an evidence of > such dependency exists, and I think that a process had better avoid opening both > /dev/raw-gadget and /dev/cdc-wdm0 at the same time. > > ---------------------------------------- > diff --git a/arch/x86/kernel/unwind_orc.c b/arch/x86/kernel/unwind_orc.c > index 5b0bd8581fe6..e352b54dbbf2 100644 > --- a/arch/x86/kernel/unwind_orc.c > +++ b/arch/x86/kernel/unwind_orc.c > @@ -320,12 +320,19 @@ EXPORT_SYMBOL_GPL(unwind_get_return_address); > > unsigned long *unwind_get_return_address_ptr(struct unwind_state *state) > { > + struct task_struct *task = state->task; > + > if (unwind_done(state)) > return NULL; > > if (state->regs) > return &state->regs->ip; > > + if (task != current && state->sp == task->thread.sp) { > + struct inactive_task_frame *frame = (void *)task->thread.sp; > + return &frame->ret_addr; > + } > + > if (state->sp) > return (unsigned long *)state->sp - 1; > > diff --git a/drivers/usb/class/cdc-wdm.c b/drivers/usb/class/cdc-wdm.c > index e3db6fbeadef..5d28a1a2521d 100644 > --- a/drivers/usb/class/cdc-wdm.c > +++ b/drivers/usb/class/cdc-wdm.c > @@ -150,8 +150,9 @@ static void wdm_out_callback(struct urb *urb) > spin_unlock_irqrestore(&desc->iuspin, flags); > kfree(desc->outbuf); > desc->outbuf = NULL; > + printk("%s : clear WDM_IN_USE %px\n", __func__, desc); > 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,17 +418,21 @@ static ssize_t wdm_write > req->wValue = 0; > req->wIndex = desc->inum; /* already converted */ > req->wLength = cpu_to_le16(count); > + printk("%s : set WDM_IN_USE %px %px\n", __func__, desc, desc->command); > set_bit(WDM_IN_USE, &desc->flags); > desc->outbuf = buf; > > rv = usb_submit_urb(desc->command, GFP_KERNEL); > if (rv < 0) { > desc->outbuf = NULL; > + printk("%s : clear WDM_IN_USE %px\n", __func__, desc); > clear_bit(WDM_IN_USE, &desc->flags); > dev_err(&desc->intf->dev, "Tx URB error: %d\n", rv); > rv = usb_translate_errors(rv); > + wake_up_all(&desc->wait); > goto out_free_mem_pm; > } else { > + printk("%s : waiting for wdm_out_callback %px\n", __func__, desc); > dev_dbg(&desc->intf->dev, "Tx URB has been submitted index=%d\n", > le16_to_cpu(req->wIndex)); > } > @@ -587,6 +592,7 @@ static int wdm_flush(struct file *file, fl_owner_t id) > { > struct wdm_device *desc = file->private_data; > > + printk("%s : start wait_event %px\n", __func__, desc); > wait_event(desc->wait, > /* > * needs both flags. We cannot do with one > @@ -596,6 +602,7 @@ static int wdm_flush(struct file *file, fl_owner_t id) > */ > !test_bit(WDM_IN_USE, &desc->flags) || > test_bit(WDM_DISCONNECTING, &desc->flags)); > + printk("%s : end wait_event %px\n", __func__, desc); > > /* cannot dereference desc->intf if WDM_DISCONNECTING */ > if (test_bit(WDM_DISCONNECTING, &desc->flags)) > @@ -642,6 +649,7 @@ static int wdm_open(struct inode *inode, struct file *file) > > mutex_lock(&wdm_mutex); > desc = wdm_find_device_by_minor(minor); > + printk("%s : start %px\n", __func__, desc); > if (!desc) > goto out; > > @@ -676,6 +684,7 @@ static int wdm_open(struct inode *inode, struct file *file) > desc->manage_power(intf, 1); > usb_autopm_put_interface(desc->intf); > out: > + printk("%s : done %px\n", __func__, desc); > mutex_unlock(&wdm_mutex); > return rv; > } > @@ -685,6 +694,7 @@ static int wdm_release(struct inode *inode, struct file *file) > struct wdm_device *desc = file->private_data; > > mutex_lock(&wdm_mutex); > + printk("%s : start %px\n", __func__, desc); > > /* using write lock to protect desc->count */ > mutex_lock(&desc->wlock); > @@ -694,6 +704,7 @@ static int wdm_release(struct inode *inode, struct file *file) > if (!desc->count) { > if (!test_bit(WDM_DISCONNECTING, &desc->flags)) { > dev_dbg(&desc->intf->dev, "wdm_release: cleanup\n"); > + printk("%s : kill_urbs() %px\n", __func__, desc); > kill_urbs(desc); > spin_lock_irq(&desc->iuspin); > desc->resp_count = 0; > @@ -705,6 +716,7 @@ static int wdm_release(struct inode *inode, struct file *file) > cleanup(desc); > } > } > + printk("%s : done %px\n", __func__, desc); > mutex_unlock(&wdm_mutex); > return 0; > } > @@ -832,6 +844,7 @@ static int wdm_create(struct usb_interface *intf, struct usb_endpoint_descriptor > desc->command = usb_alloc_urb(0, GFP_KERNEL); > if (!desc->command) > goto err; > + desc->command->trace_me = true; > > desc->ubuf = kmalloc(desc->wMaxCommand, GFP_KERNEL); > if (!desc->ubuf) > @@ -979,15 +992,18 @@ static void wdm_disconnect(struct usb_interface *intf) > usb_deregister_dev(intf, &wdm_class); > desc = wdm_find_device(intf); > mutex_lock(&wdm_mutex); > + printk("%s : start %px\n", __func__, desc); > > /* the spinlock makes sure no new urbs are generated in the callbacks */ > spin_lock_irqsave(&desc->iuspin, flags); > + printk("%s : set WDM_DISCONNECTING %px\n", __func__, desc); > set_bit(WDM_DISCONNECTING, &desc->flags); > set_bit(WDM_READ, &desc->flags); > spin_unlock_irqrestore(&desc->iuspin, flags); > wake_up_all(&desc->wait); > mutex_lock(&desc->rlock); > mutex_lock(&desc->wlock); > + printk("%s : kill_urbs() %px\n", __func__, desc); > kill_urbs(desc); > cancel_work_sync(&desc->rxwork); > cancel_work_sync(&desc->service_outs_intr); > @@ -1003,6 +1019,7 @@ static void wdm_disconnect(struct usb_interface *intf) > cleanup(desc); > else > dev_dbg(&intf->dev, "%d open files - postponing cleanup\n", desc->count); > + printk("%s : done %px\n", __func__, desc); > mutex_unlock(&wdm_mutex); > } > > @@ -1031,6 +1048,7 @@ static int wdm_suspend(struct usb_interface *intf, pm_message_t message) > set_bit(WDM_SUSPENDING, &desc->flags); > spin_unlock_irq(&desc->iuspin); > /* callback submits work - order is essential */ > + printk("%s : kill_urbs() %px\n", __func__, desc); > kill_urbs(desc); > cancel_work_sync(&desc->rxwork); > cancel_work_sync(&desc->service_outs_intr); > @@ -1082,15 +1100,19 @@ static int wdm_pre_reset(struct usb_interface *intf) > * must be done before recovery lest a spontaneous > * message from the device is lost > */ > + printk("%s : start\n", __func__); > spin_lock_irq(&desc->iuspin); > + printk("%s : set WDM_RESETTING %px\n", __func__, desc); > set_bit(WDM_RESETTING, &desc->flags); /* inform read/write */ > set_bit(WDM_READ, &desc->flags); /* unblock read */ > + printk("%s : clear WDM_IN_USE %px\n", __func__, desc); > clear_bit(WDM_IN_USE, &desc->flags); /* unblock write */ > desc->rerr = -EINTR; > spin_unlock_irq(&desc->iuspin); > wake_up_all(&desc->wait); > mutex_lock(&desc->rlock); > mutex_lock(&desc->wlock); > + printk("%s : kill_urbs() %px\n", __func__, desc); > kill_urbs(desc); > cancel_work_sync(&desc->rxwork); > cancel_work_sync(&desc->service_outs_intr); > @@ -1103,10 +1125,12 @@ static int wdm_post_reset(struct usb_interface *intf) > int rv; > > clear_bit(WDM_OVERFLOW, &desc->flags); > + printk("%s : clear WDM_RESETTING %px\n", __func__, desc); > clear_bit(WDM_RESETTING, &desc->flags); > rv = recover_from_urb_loss(desc); > mutex_unlock(&desc->wlock); > mutex_unlock(&desc->rlock); > + printk("%s : done\n", __func__); > return rv; > } > > diff --git a/drivers/usb/core/hcd.c b/drivers/usb/core/hcd.c > index aa45840d8273..ab3d3b65a6cf 100644 > --- a/drivers/usb/core/hcd.c > +++ b/drivers/usb/core/hcd.c > @@ -1521,6 +1521,8 @@ int usb_hcd_submit_urb (struct urb *urb, gfp_t mem_flags) > int status; > struct usb_hcd *hcd = bus_to_hcd(urb->dev->bus); > > + if (urb->trace_me) > + printk("%s : start %px\n", __func__, urb); > /* increment urb's reference count as part of giving it to the HCD > * (which will control it). HCD guarantees that it either returns > * an error or calls giveback(), but not both. > @@ -1550,6 +1552,8 @@ int usb_hcd_submit_urb (struct urb *urb, gfp_t mem_flags) > } > > if (unlikely(status)) { > + if (urb->trace_me) > + printk("%s : error %px %d\n", __func__, urb, status); > usbmon_urb_submit_error(&hcd->self, urb, status); > urb->hcpriv = NULL; > INIT_LIST_HEAD(&urb->urb_list); > @@ -1559,6 +1563,8 @@ int usb_hcd_submit_urb (struct urb *urb, gfp_t mem_flags) > wake_up(&usb_kill_urb_queue); > usb_put_urb(urb); > } > + if (urb->trace_me) > + printk("%s : end %px %d\n", __func__, urb, status); > return status; > } > > @@ -1582,6 +1588,8 @@ static int unlink1(struct usb_hcd *hcd, struct urb *urb, int status) > * Such failures should be harmless. */ > value = hcd->driver->urb_dequeue(hcd, urb, status); > } > + if (urb->trace_me) > + printk("%s : %px %d\n", __func__, urb, value); > return value; > } > > @@ -1645,6 +1653,8 @@ static void __usb_hcd_giveback_urb(struct urb *urb) > > /* pass ownership to the completion handler */ > urb->status = status; > + if (urb->trace_me) > + printk("%s : complete %px %d\n", __func__, urb, status); > urb->complete(urb); > > usb_anchor_resume_wakeups(anchor); > diff --git a/drivers/usb/gadget/legacy/raw_gadget.c b/drivers/usb/gadget/legacy/raw_gadget.c > index e01e366d89cd..9adcc978804e 100644 > --- a/drivers/usb/gadget/legacy/raw_gadget.c > +++ b/drivers/usb/gadget/legacy/raw_gadget.c > @@ -33,6 +33,10 @@ MODULE_DESCRIPTION(DRIVER_DESC); > MODULE_AUTHOR("Andrey Konovalov"); > MODULE_LICENSE("GPL"); > > +#undef dev_dbg > +#define dev_dbg(dev, fmt, ...) \ > + dev_printk(KERN_INFO, dev, dev_fmt(fmt), ##__VA_ARGS__) > + > /*----------------------------------------------------------------------*/ > > #define RAW_EVENT_QUEUE_SIZE 16 > diff --git a/include/linux/usb.h b/include/linux/usb.h > index 9f3c721c70dc..0843e07f6cc2 100644 > --- a/include/linux/usb.h > +++ b/include/linux/usb.h > @@ -1589,6 +1589,7 @@ struct urb { > int error_count; /* (return) number of ISO errors */ > void *context; /* (in) context for completion */ > usb_complete_t complete; /* (in) completion routine */ > + bool trace_me; > struct usb_iso_packet_descriptor iso_frame_desc[]; > /* (in) ISO ONLY */ > }; > ---------------------------------------- > > ---------------------------------------- > [ 25.056066][ T12] usb 5-1: New USB device found, idVendor=2400, idProduct=4200, bcdDevice=42.ef > [ 25.056724][ T1175] udc-core: couldn't find an available UDC or it's busy > [ 25.056730][ T1175] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.057711][ T1176] udc-core: couldn't find an available UDC or it's busy > [ 25.057719][ T1176] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.058090][ T1171] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.058104][ T1178] udc-core: couldn't find an available UDC or it's busy > [ 25.058233][ T1177] udc-core: couldn't find an available UDC or it's busy > [ 25.058238][ T1177] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.058685][ T1179] udc-core: couldn't find an available UDC or it's busy > [ 25.058692][ T1179] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.060237][ T12] usb 5-1: New USB device strings: Mfr=0, Product=0, SerialNumber=2 > [ 25.060250][ T1180] udc-core: couldn't find an available UDC or it's busy > [ 25.060255][ T1180] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.060737][ T1181] udc-core: couldn't find an available UDC or it's busy > [ 25.060741][ T1181] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.060836][ T1182] udc-core: couldn't find an available UDC or it's busy > [ 25.060840][ T1182] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.061235][ T1183] udc-core: couldn't find an available UDC or it's busy > [ 25.061241][ T1183] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.062374][ T1178] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.064298][ T12] usb 5-1: SerialNumber: syz > [ 25.065151][ T1185] udc-core: couldn't find an available UDC or it's busy > [ 25.065161][ T1184] udc-core: couldn't find an available UDC or it's busy > [ 25.065168][ T1184] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.065191][ T1186] udc-core: couldn't find an available UDC or it's busy > [ 25.065195][ T1186] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.065451][ T1187] udc-core: couldn't find an available UDC or it's busy > [ 25.065457][ T1187] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.068979][ T1189] udc-core: couldn't find an available UDC or it's busy > [ 25.070166][ T1185] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.072145][ T1191] udc-core: couldn't find an available UDC or it's busy > [ 25.072151][ T1191] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.072166][ T1190] udc-core: couldn't find an available UDC or it's busy > [ 25.072174][ T1190] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.072254][ T1189] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.073991][ T1193] udc-core: couldn't find an available UDC or it's busy > [ 25.073997][ T1193] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.074002][ T1192] udc-core: couldn't find an available UDC or it's busy > [ 25.074006][ T1192] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.087896][ T1196] udc-core: couldn't find an available UDC or it's busy > [ 25.087933][ T1195] udc-core: couldn't find an available UDC or it's busy > [ 25.087941][ T1195] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.088229][ T1197] udc-core: couldn't find an available UDC or it's busy > [ 25.088235][ T1197] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.088239][ T1194] udc-core: couldn't find an available UDC or it's busy > [ 25.088244][ T1194] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.090788][ T1198] udc-core: couldn't find an available UDC or it's busy > [ 25.092032][ T1196] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.093018][ T1199] udc-core: couldn't find an available UDC or it's busy > [ 25.093023][ T1200] udc-core: couldn't find an available UDC or it's busy > [ 25.093027][ T1200] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.093886][ T1198] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.094586][ T1201] udc-core: couldn't find an available UDC or it's busy > [ 25.095028][ T1202] udc-core: couldn't find an available UDC or it's busy > [ 25.095032][ T1202] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.095403][ T1204] udc-core: couldn't find an available UDC or it's busy > [ 25.095409][ T1204] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.095411][ T1203] udc-core: couldn't find an available UDC or it's busy > [ 25.095416][ T1203] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.095896][ T1199] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.099620][ T1205] udc-core: couldn't find an available UDC or it's busy > [ 25.100765][ T1201] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.102512][ T1205] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.104434][ T1207] udc-core: couldn't find an available UDC or it's busy > [ 25.104439][ T1207] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.104483][ T1206] udc-core: couldn't find an available UDC or it's busy > [ 25.104489][ T1206] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.104516][ T1208] udc-core: couldn't find an available UDC or it's busy > [ 25.104521][ T1208] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.122543][ T12] hub 5-1:118.0: bad descriptor, ignoring hub > [ 25.122597][ T1210] udc-core: couldn't find an available UDC or it's busy > [ 25.122604][ T1210] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.122976][ T1211] udc-core: couldn't find an available UDC or it's busy > [ 25.122983][ T1211] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.123591][ T1212] udc-core: couldn't find an available UDC or it's busy > [ 25.123596][ T1212] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.123654][ T1209] udc-core: couldn't find an available UDC or it's busy > [ 25.123659][ T1209] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.124649][ T1213] udc-core: couldn't find an available UDC or it's busy > [ 25.124809][ T1214] udc-core: couldn't find an available UDC or it's busy > [ 25.124814][ T1214] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.125168][ T1215] udc-core: couldn't find an available UDC or it's busy > [ 25.125174][ T1215] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.126547][ T12] hub: probe of 5-1:118.0 failed with error -5 > [ 25.128767][ T1213] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.129656][ T1216] udc-core: couldn't find an available UDC or it's busy > [ 25.129662][ T1216] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.129678][ T1217] udc-core: couldn't find an available UDC or it's busy > [ 25.129684][ T1217] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.129968][ T1218] udc-core: couldn't find an available UDC or it's busy > [ 25.129973][ T1218] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.132093][ T12] cdc_wdm 5-1:118.0: cdc-wdm0: USB WDM device > [ 25.132549][ T1219] udc-core: couldn't find an available UDC or it's busy > [ 25.132554][ T1219] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.133379][ T1222] udc-core: couldn't find an available UDC or it's busy > [ 25.133385][ T1222] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.133552][ T1223] udc-core: couldn't find an available UDC or it's busy > [ 25.133708][ T1221] udc-core: couldn't find an available UDC or it's busy > [ 25.133713][ T1221] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.135592][ T1224] udc-core: couldn't find an available UDC or it's busy > [ 25.135598][ T1224] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.136158][ T12] wdm_suspend : kill_urbs() ffff88822dffd000 > [ 25.136578][ T1225] udc-core: couldn't find an available UDC or it's busy > [ 25.136583][ T1225] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.136638][ T1226] udc-core: couldn't find an available UDC or it's busy > [ 25.136642][ T1226] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.136928][ T1227] udc-core: couldn't find an available UDC or it's busy > [ 25.136933][ T1227] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.138275][ T1228] udc-core: couldn't find an available UDC or it's busy > [ 25.138281][ T1228] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.138293][ T1223] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.138821][ T1229] udc-core: couldn't find an available UDC or it's busy > [ 25.138948][ T1230] udc-core: couldn't find an available UDC or it's busy > [ 25.138952][ T1230] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.139091][ T1231] udc-core: couldn't find an available UDC or it's busy > [ 25.139096][ T1231] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.141700][ T1232] udc-core: couldn't find an available UDC or it's busy > [ 25.142014][ T1233] udc-core: couldn't find an available UDC or it's busy > [ 25.142020][ T1233] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.142097][ T1233] wdm_open : start ffff88822dffd000 > [ 25.142251][ T1234] udc-core: couldn't find an available UDC or it's busy > [ 25.142258][ T1234] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.142285][ T1235] udc-core: couldn't find an available UDC or it's busy > [ 25.142289][ T1235] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.142372][ T1229] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.144150][ T1232] misc raw-gadget: fail, usb_gadget_probe_driver returned -19 > [ 25.319563][ T1233] wdm_open : done ffff88822dffd000 > [ 25.732316][ T1235] wdm_open : start ffff88822dffd000 > [ 25.732389][ T1233] wdm_write : set WDM_IN_USE ffff88822dffd000 ffff888234392f00 > [ 25.736342][ T1233] usb_hcd_submit_urb : start ffff888234392f00 > [ 25.738112][ T1233] usb_hcd_submit_urb : end ffff888234392f00 0 > [ 25.739989][ T1233] wdm_write : waiting for wdm_out_callback ffff88822dffd000 > [ 25.742837][ T1233] wdm_flush : start wait_event ffff88822dffd000 > [ 25.742948][ T1235] wdm_open : done ffff88822dffd000 > [ 25.747707][ T1234] wdm_open : start ffff88822dffd000 > [ 30.141494][ T1234] wdm_open : done ffff88822dffd000 > [ 30.141711][ T1235] wdm_flush : start wait_event ffff88822dffd000 > [ 30.143693][ T1232] wdm_open : start ffff88822dffd000 > [ 30.143916][ T1234] wdm_flush : start wait_event ffff88822dffd000 > [ 30.151409][ T1232] wdm_open : done ffff88822dffd000 > [ 30.153610][ T841] wdm_open : start ffff88822dffd000 > [ 30.153788][ T1232] wdm_flush : start wait_event ffff88822dffd000 > [ 30.155816][ T841] wdm_open : done ffff88822dffd000 > [ 30.159953][ T1229] wdm_open : start ffff88822dffd000 > [ 30.160146][ T841] wdm_flush : start wait_event ffff88822dffd000 > [ 30.162005][ T1229] wdm_open : done ffff88822dffd000 > [ 30.165691][ T1229] wdm_flush : start wait_event ffff88822dffd000 > [ 63.298753][ C3] random: crng init done > [ 63.299926][ C3] random: 7 urandom warning(s) missed due to ratelimiting > [ 168.509958][ T52] INFO: task a.out:1233 blocked for more than 141 seconds. > [ 168.516579][ T52] Not tainted 5.7.0-rc5+ #13 > [ 168.520995][ T52] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 168.528400][ T52] a.out D13024 1233 838 0x00000004 > [ 168.532156][ T52] Call Trace: > [ 168.533970][ T52] __schedule+0x363/0x840 > [ 168.535991][ T52] ? wdm_suspend+0x160/0x160 > [ 168.538199][ T52] schedule+0x5a/0xd0 > [ 168.539782][ T52] wdm_flush+0x124/0x190 > [ 168.541542][ T52] ? remove_wait_queue+0x60/0x60 > [ 168.543503][ T52] filp_close+0x3d/0xa0 > [ 168.544874][ T52] __close_fd+0x8f/0x110 > [ 168.546267][ T52] __x64_sys_close+0x2a/0x60 > [ 168.547843][ T52] do_syscall_64+0x58/0x270 > [ 168.549214][ T52] entry_SYSCALL_64_after_hwframe+0x49/0xb3 > [ 168.550889][ T52] RIP: 0033:0x7f54551f4f30 > [ 168.552150][ T52] Code: Bad RIP value. > [ 168.553323][ T52] RSP: 002b:00007ffe39c17878 EFLAGS: 00000246 ORIG_RAX: 0000000000000003 > [ 168.555439][ T52] RAX: ffffffffffffffda RBX: 0000000000000005 RCX: 00007f54551f4f30 > [ 168.558429][ T52] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000004 > [ 168.561016][ T52] RBP: 0000000000000000 R08: 000000000000000f R09: 00007ffe39c178ae > [ 168.563155][ T52] R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff > [ 168.565136][ T52] R13: 0000000000005fb3 R14: 0000000000000000 R15: 0000000000000000 > [ 168.567108][ T52] > [ 168.567108][ T52] Showing all locks held in the system: > [ 168.569123][ T52] 1 lock held by khungtaskd/52: > [ 168.570400][ T52] #0: ffffffff83a6baa0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0xe/0x1b0 > [ 168.573387][ T52] 1 lock held by in:imklog/465: > [ 168.574597][ T52] #0: ffff88822d28fcf0 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0x55/0x60 > [ 168.576825][ T52] > [ 168.577408][ T52] ============================================= > [ 168.577408][ T52] > [ 168.579559][ T52] NMI backtrace for cpu 1 > [ 168.580819][ T52] CPU: 1 PID: 52 Comm: khungtaskd Not tainted 5.7.0-rc5+ #13 > [ 168.582916][ T52] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/29/2019 > [ 168.585746][ T52] Call Trace: > [ 168.586565][ T52] dump_stack+0x97/0xde > [ 168.588235][ T52] ? irq_force_complete_move+0x61/0x80 > [ 168.590020][ T52] nmi_cpu_backtrace+0xe2/0xf0 > [ 168.591382][ T52] ? lapic_can_unplug_cpu+0x90/0x90 > [ 168.592679][ T52] nmi_trigger_cpumask_backtrace+0x124/0x170 > [ 168.594338][ T52] watchdog+0x4e4/0x950 > [ 168.595543][ T52] ? hungtask_pm_notify+0x70/0x70 > [ 168.596790][ T52] kthread+0x128/0x170 > [ 168.597801][ T52] ? kthread_create_worker_on_cpu+0x90/0x90 > [ 168.599257][ T52] ret_from_fork+0x24/0x30 > [ 168.600448][ T52] Sending NMI from CPU 1 to CPUs 0,2-7: > [ 168.602261][ C2] NMI backtrace for cpu 2 skipped: idling at default_idle+0x25/0x180 > [ 168.602268][ C4] NMI backtrace for cpu 4 skipped: idling at default_idle+0x25/0x180 > [ 168.602272][ C0] NMI backtrace for cpu 0 skipped: idling at default_idle+0x25/0x180 > [ 168.602277][ C3] NMI backtrace for cpu 3 skipped: idling at default_idle+0x25/0x180 > [ 168.602294][ C7] NMI backtrace for cpu 7 skipped: idling at default_idle+0x25/0x180 > [ 168.602299][ C6] NMI backtrace for cpu 6 skipped: idling at default_idle+0x25/0x180 > [ 168.602308][ C5] NMI backtrace for cpu 5 skipped: idling at default_idle+0x25/0x180 > [ 168.603243][ T52] Kernel panic - not syncing: hung_task: blocked tasks > [ 168.623795][ T52] CPU: 1 PID: 52 Comm: khungtaskd Not tainted 5.7.0-rc5+ #13 > [ 168.625777][ T52] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/29/2019 > [ 168.629089][ T52] Call Trace: > [ 168.630281][ T52] dump_stack+0x97/0xde > [ 168.631495][ T52] panic+0x135/0x3d5 > [ 168.632577][ T52] ? watchdog+0x4e4/0x950 > [ 168.633730][ T52] watchdog+0x4f0/0x950 > [ 168.634829][ T52] ? hungtask_pm_notify+0x70/0x70 > [ 168.636160][ T52] kthread+0x128/0x170 > [ 168.637238][ T52] ? kthread_create_worker_on_cpu+0x90/0x90 > [ 168.638792][ T52] ret_from_fork+0x24/0x30 > [ 168.640142][ T52] Kernel Offset: disabled > [ 168.663256][ T52] Rebooting in 86400 seconds.. > ----------------------------------------
