forwarding to linux-usb with traces in compressed tarball: -------- Forwarded Message -------- Subject: [BUG REPORT] usb: dwc3: rmmod blocks (g_multi) Date: Tue, 7 Jan 2020 14:43:39 +0100 From: Martin Kepplinger <martin.kepplinger@xxxxxxx> To: Felipe Balbi <balbi@xxxxxxxxxx> CC: linux-usb@xxxxxxxxxxxxxxx <linux-usb@xxxxxxxxxxxxxxx> hi, (for the record, I've written before: https://lore.kernel.org/linux-usb/38edc05e-680b-d881-49fc-e8230a93b2c8@xxxxxxx/ and this is an updated version. the problems persist. let's focus on rmmod only here) I'm running this tree https://source.puri.sm/martin.kepplinger/linux-next/tree/next-20200107/librem5 which is just next-20200107 with this defconfig: https://source.puri.sm/martin.kepplinger/linux-next/blob/next-20200107/librem5/arch/arm64/configs/librem5_defconfig on the librem5-devkit: dwc3 dual mode is configured and I load g_multi with "options g_multi file=/var/lib/mass_storage_dummy stall=0" during boot. Actually, rmmod g_multi doesn't work either and results in similar hangs. USB connected ------------- root@pureos:/home/purism# rmmod dwc3 [ 2614.500026] dwc3 38100000.usb: request 000000000c87367b was not queued to ep3in [ 2780.136874] INFO: task rmmod:9031 blocked for more than 120 seconds. [ 2780.143265] Tainted: G W 5.5.0-rc5-next-20200107-00013-gbf5ee18fb9e0 #58 [ 2780.151861] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. the trace is appended. the messages around the error message timestamp above are: rmmod-9031 [002] d..1 2614.499798: dwc3_readl: addr 00000000d1c7e512 value 00050c08 rmmod-9031 [002] d..1 2614.499800: dwc3_gadget_ep_cmd: ep2in: cmd 'End Transfer' [50c08] params 00000000 00000000 00000000 --> status: Timed Out rmmod-9031 [002] d..1 2614.499802: dwc3_readl: addr 00000000e118d0b0 value 40102400 rmmod-9031 [002] d..1 2614.499803: dwc3_writel: addr 00000000e118d0b0 value 40102540 rmmod-9031 [002] d..1 2614.499885: dwc3_readl: addr 000000004b6b2caf value 00000af3 rmmod-9031 [002] d..1 2614.499887: dwc3_writel: addr 000000004b6b2caf value 00000ad3 rmmod-9031 [002] .... 2614.499994: dwc3_free_request: ep2in: req 000000009ec6ea8a length 8/8 zsI ==> 0 rmmod-9031 [002] d..1 2614.500005: dwc3_ep_dequeue: ep3in: req 000000000c87367b length 0/0 zsI ==> 0 rmmod-9031 [002] d..1 2614.507353: dwc3_free_request: ep3in: req 000000000c87367b length 0/0 zsI ==> 0 rmmod-9031 [002] d..1 2614.507608: dwc3_gadget_ep_disable: ep2out: mps 512/1024 streams 15 burst 0 ring 27/11 flags E:swBp:> rmmod-9031 [002] d..1 2614.507615: dwc3_readl: addr 00000000e118d0b0 value 40102540 rmmod-9031 [002] d..1 2614.507618: dwc3_writel: addr 00000000e118d0b0 value 40102400 rmmod-9031 [002] d..1 2614.507619: dwc3_writel: addr 00000000ee77d00b value 00000000 it doesn't hang the system, just the process. USB disconnected ---------------- root@pureos:/home/purism# rmmod dwc3 [ 242.655656] INFO: task rmmod:1024 blocked for more than 120 seconds. [ 242.662072] Not tainted 5.5.0-rc5-next-20200107-00013-gbf5ee18fb9e0 #58 [ 242.669254] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. again, the (short) trace is appended. no error message is printed. the latter case would be more interesting to me, but in any case: Do you know what could go wrong here? Below some more tests: g_zero / USB connected ------------------------------- try to load/unload g_zero only: root@pureos:/home/purism# modprobe g_zero [ 156.277956] dwc3 38100000.usb: failed to enable ep0out root@pureos:/home/purism# rmmod g_zero [ 159.293698] dwc3 38100000.usb: timed out waiting for SETUP phase and again, the trace "g_zero_usb_connected" is appended. rmmod does NOT hang (but take a noticable amount of time < 1 sec though). g_zero / USB disconnected ------------------------- works. trace still appended. so there should be a problem with g_multi... I'm happy for any hints or further questions! thanks, martin g_serial / USB connected ------------------------ lastly, I just modprobe and rmmod g_serial, which resulted in a kernal panic and I couldn't copy the trace -.- (can easily reproduce this. the second run went exactly like "g_zero", but I can't see a /dev/ttyACM device on my host after modprobe...) [ 37.195773] Unable to handle kernel NULL pointer dereference at virtual address 0000000000000160 [ 37.195831] device: 'ttyGS0': device_unregister [ 37.204564] Mem abort info: [ 37.204567] ESR = 0x96000004 [ 37.204572] EC = 0x25: DABT (current EL), IL = 32 bits [ 37.204575] SET = 0, FnV = 0 [ 37.204577] EA = 0, S1PTW = 0 [ 37.204579] Data abort info: [ 37.204582] ISV = 0, ISS = 0x00000004 Message from syslogd@pureos at Jan 7 13:35:20 ... kernel:[ 37.204602] Internal error: Oops: 96000004 [#1] PREEMPT SMP [ 37.204585] CM = 0, WnR = 0 [ 37.204590] user pgtable: 4k pages, 48-bit VAs, pgdp=00000000e6d93000 [ 37.204593] [0000000000000160] pgd=0000000000000000 [ 37.204602] Internal error: Oops: 96000004 [#1] PREEMPT SMP [ 37.204606] Modules linked in: usb_f_acm u_serial g_serial(-) libcomposite qmi_wwan cdc_wdm usbnet mii option usb_wwan usbserial rfkill caam_jr mousedev caamhash_desc caamalg_desc aes_ce_blk crypto_simd st_lsm6dsx_spi crct10dif_ce ghash_ce sha2_ce sha1_ce gpio_vibra tcpci st_magn_spi st_sensors_spi tcpm roles st_magn_i2c st_magn st_sensors_i2c st_sensors st_lsm6dsx_i2c st_lsm6dsx industrialio_triggered_buffer goodix typec kfifo_buf bq25890_charger caam imx2_wdt error imx_sdma watchdog virt_dma ip_tables x_tables ipv6 nf_defrag_ipv6 xhci_plat_hcd xhci_hcd usbcore clk_bd718x7 snvs_pwrkey dwc3 ulpi udc_core usb_common phy_fsl_imx8mq_usb [ 37.209387] PM: Removing info for No Bus:ttyGS0 [ 37.212024] CPU: 3 PID: 1 Comm: systemd Tainted: G W 5.5.0-rc5-next-20200107-00014-gc2b528ade7a0 #59 [ 37.335458] Hardware name: Purism Librem 5 devkit (DT) [ 37.340600] pstate: 80000085 (Nzcv daIf -PAN -UAO) [ 37.345402] pc : _raw_spin_unlock_irqrestore+0x230/0x298 [ 37.350716] lr : _raw_spin_lock_irq+0x2c/0x80 [ 37.355073] sp : ffff80001003b900 [ 37.358388] x29: ffff80001003b900 x28: ffff00008177e000 [ 37.363703] x27: ffff00008177e000 x26: ffff800010a21b08 [ 37.369018] x25: 0000000000020902 x24: ffff0000a05d8b20 [ 37.374332] x23: ffff000081649900 x22: ffff00008177e000 [ 37.379647] x21: 0000000000000160 x20: ffff800010e987c8 [ 37.384961] x19: 0000000000000160 x18: 0000000000000001 [ 37.390275] x17: 0000000000000000 x16: 0000000000000000 [ 37.395590] x15: ffffffffffffffff x14: ffff800010e987c8 [ 37.400904] x13: ffff8000111df000 x12: ffff800010000000 [ 37.406219] x11: ffff800010cd6000 x10: 0140000000000000 [ 37.411533] x9 : ffff800010993cfc x8 : ffff8000113d8260 [ 37.416847] x7 : ffff00008177e210 x6 : ffff80001003b8c0 [ 37.422161] x5 : 0000000000000001 x4 : 0000000000000001 [ 37.427475] x3 : 0000000000000001 x2 : 0000000000000001 [ 37.432789] x1 : 0000000000000000 x0 : ffff800010993cfc [ 37.438104] Call trace: [ 37.440555] _raw_spin_unlock_irqrestore+0x230/0x298 [ 37.445530] gs_close+0x48/0x248 [u_serial] [ 37.449718] tty_release+0x110/0x5e0 [ 37.453294] tty_open+0x120/0x428 [ 37.456614] chrdev_open+0xac/0x1a8 [ 37.460105] do_dentry_open+0x118/0x3a8 [ 37.463942] vfs_open+0x30/0x38 [ 37.467088] path_openat+0x2e4/0x1258 [ 37.470752] do_filp_open+0x80/0xf8 [ 37.474243] do_sys_openat2+0x200/0x298 [ 37.478080] do_sys_open+0x64/0xa8 [ 37.481483] __arm64_sys_openat+0x28/0x30 [ 37.485498] el0_svc_common.constprop.3+0x98/0x170 [ 37.490291] el0_svc_handler+0x20/0x28 [ 37.494044] el0_sync_handler+0x134/0x1a0 [ 37.498056] el0_sync+0x140/0x180 [ 37.501377] Code: 88037e62 35ffff83 17fffec8 f9800271 (885ffe60) [ 37.507474] ---[ end trace 38cceb5162e73ede ]--- [ 37.512095] note: systemd[1] exited with preempt_count 1 [ 37.517410] Kernel panic - not syncing: Attempted to kill init! exitcode=0x0000000b [ 37.525071] SMP: stopping secondary CPUs [ 37.529001] Kernel Offset: disabled [ 37.532492] CPU features: 0x00002,2000200c [ 37.536588] Memory Limit: none [ 37.539648] ---[ end Kernel panic - not syncing: Attempted to kill init! exitcode=0x0000000b ]---
Attachment:
traces.tar.xz
Description: application/xz
