Fwd: [BUG REPORT] usb: dwc3: rmmod blocks (g_multi)

Fwd: [BUG REPORT] usb: dwc3: rmmod blocks (g_multi)

[Martin Kepplinger]

[-- Attachment #1: Type: text/plain, Size: 8406 bytes --]

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@puri.sm>
To: Felipe Balbi <balbi@kernel.org>
CC: linux-usb@vger.kernel.org <linux-usb@vger.kernel.org>

hi,

(for the record, I've written before:
https://lore.kernel.org/linux-usb/38edc05e-680b-d881-49fc-e8230a93b2c8@puri.sm/
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 #2: traces.tar.xz --]
[-- Type: application/x-xz, Size: 12056 bytes --]