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. 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. 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.. ----------------------------------------
