Discussion:
[ath9k-devel] EOMA68-A20 (allwinner sunxi a20) 4.7.0-rc2 ath9k_htc "ath9k_htc: Unable to allocate URBs" issue
lkcl .
2016-07-24 14:51:01 UTC
Permalink
hi folks, we're running a crowdfunding campaign live at the moment on
crowdsupply so it is a little more prominent than usual debugging
issues: ath9k_htc has the "unable to allocate urbs" issue which has
cropped up a number of times in the past, since 2013 and even 2010.

i'm plugging in a powered USB3 Hub into the OTG port (set up as a USB
Host). the OTG port is USB2. (i don't yet have access to a powered
USB2-only hub)


this is what i get:

[ 146.752856] usb 5-1.4: new high-speed USB device number 7 using musb-hdrc
[ 146.931295] usb 5-1.4: ath9k_htc: Firmware ath9k_htc/htc_7010-1.4.0.fw reques
ted
[ 146.938943] usbcore: registered new interface driver ath9k_htc
[ 147.051422] usb 5-1.4: ath9k_htc: Transferred FW: ath9k_htc/htc_7010-1.4.0.fw
, size: 72812
[ 147.060165] usb 5-1.4: ath9k_htc: Unable to allocate URBs
[ 147.066080] usb 5-1.4: ath9k_htc: USB layer deinitialized
[ 153.176102] usb 5-1.4: USB disconnect, device number 7

now, here's the really strange thing: this issue does *NOT* occur if
the ath9k_htc 9271 dongle is plugged in as the very first device (but
we get additional problems) here's the sequences that i've tried so
far:

* plug in TP-Link 9271 dongle: works fine
* plug in Logitech dual-endpoint (hybrid usb-hid keyboard and usb-hid trackpad):
keyboard works, TRACKPAD DOES NOT
* unplug either device and re-plug them back in, result is:

[ 804.942464] usb 5-1: new high-speed USB device number 58 using musb-hdrc
[ 805.482464] usb 5-1: new high-speed USB device number 59 using musb-hdrc
[ 806.022463] usb 5-1: new high-speed USB device number 60 using musb-hdrc
[ 806.602464] usb 5-1: new high-speed USB device number 61 using musb-hdrc
[ 807.182479] usb 5-1: new high-speed USB device number 62 using musb-hdrc

if the hub is then unplugged it is no longer recognised. plugging in
any usb device directly into the usb port is also no longer
recognised.


second sequence attempted:

* plug in Logitech dual-endpoint device: works fine
* plug in TP-Link 9271 dongle: Unable to allocate URBs
* unplug both devices, plug something (anything) back in: new
high-speed number 58 59 60 61 62 .... one every second

third sequence attempted:

* plug in Logitech dual-endpoint device: works fine
* plug in ASIX88xxx USB-ETH dongle: works fine
* plug in *SECOND* ASIX88xx USB-ETH dongle: works fine
* plug in TP-Link 9271: wark, wark


in essence, then, it would seem as if the TP-Link 9271 is
destabilising the usb bus infrastructure.

any additional information needed, please do let me know.

l.
lkcl .
2016-07-24 15:01:41 UTC
Permalink
oo that's interesting.. i had to unplug the ath9k_htc because these
kept streaming up-screen, here's the setup:

* plug in USB3 powered hub into OTG port (set up as USB2 Host)
* plug in USB2 *unpowered* hub into 1 of USB3 powered hub ports
* plug in two ASIX88xx dongles into USB3 powered hub ports
* plug in ath9k_htc tp-link 9271 dongle into *USB2 unpowered* hub port
* unplug 9271 to stop messages going mad



[ 75.803214] ------------[ cut here ]------------
[ 75.807858] WARNING: CPU: 1 PID: 59 at drivers/usb/core/urb.c:449 usb_submit_
urb+0x1c4/0x49c
[ 75.816339] usb 5-1.4.2: BOGUS urb xfer, pipe 1 != type 3
[ 75.821739] Modules linked in: ath9k_htc ath9k_common ath9k_hw ath
[ 75.828019] CPU: 1 PID: 59 Comm: kworker/1:1 Tainted: G W 4.7.0-
rc7-dirty #25
[ 75.836270] Hardware name: Allwinner sun7i (A20) Family
[ 75.841495] Workqueue: events request_firmware_work_func
[ 75.846829] [<c010d818>] (unwind_backtrace) from [<c010a690>] (show_stack+0x1
0/0x14)
[ 75.854571] [<c010a690>] (show_stack) from [<c0359324>] (dump_stack+0x80/0xa0
)
[ 75.861794] [<c0359324>] (dump_stack) from [<c011aa50>] (__warn+0xd4/0x100)
[ 75.868754] [<c011aa50>] (__warn) from [<c011ab24>] (warn_slowpath_fmt+0x38/0
x48)
[ 75.876234] [<c011ab24>] (warn_slowpath_fmt) from [<c04a80c4>] (usb_submit_ur
b+0x1c4/0x49c)
[ 75.884611] [<c04a80c4>] (usb_submit_urb) from [<bf07ba24>] (hif_usb_send+0x1
58/0x30c [ath9k_htc])
[ 75.893586] [<bf07ba24>] (hif_usb_send [ath9k_htc]) from [<bf07a058>] (htc_is
sue_send.constprop.0+0x58/0x5c [ath9k_htc])
[ 75.904468] [<bf07a058>] (htc_issue_send.constprop.0 [ath9k_htc]) from [<bf07
cb58>] (ath9k_wmi_cmd+0x104/0x170 [ath9k_htc])
[ 75.915610] [<bf07cb58>] (ath9k_wmi_cmd [ath9k_htc]) from [<bf081c48>] (ath9k
_regread+0x3c/0x54 [ath9k_htc])
[ 75.925493] [<bf081c48>] (ath9k_regread [ath9k_htc]) from [<bf00da6c>] (ath9k
_hw_setpower+0xb4/0x444 [ath9k_hw])
[ 75.935710] [<bf00da6c>] (ath9k_hw_setpower [ath9k_hw]) from [<bf00f114>] (at
h9k_hw_init+0x3bc/0xb60 [ath9k_hw])
[ 75.945913] [<bf00f114>] (ath9k_hw_init [ath9k_hw]) from [<bf0822e0>] (ath9k_
htc_probe_device+0x2b0/0x868 [ath9k_htc])
[ 75.956622] [<bf0822e0>] (ath9k_htc_probe_device [ath9k_htc]) from [<bf07a7bc
] (ath9k_htc_hw_init+0x14/0x38 [ath9k_htc])
[ 75.967591] [<bf07a7bc>] (ath9k_htc_hw_init [ath9k_htc]) from [<bf07c2bc>] (a
th9k_hif_usb_firmware_cb+0x8c/0x198 [ath9k_htc])
[ 75.978895] [<bf07c2bc>] (ath9k_hif_usb_firmware_cb [ath9k_htc]) from [<c0421
748>] (request_firmware_work_func+0x30/0x58)
[ 75.989845] [<c0421748>] (request_firmware_work_func) from [<c012f930>] (proc
ess_one_work+0x134/0x33c)
[ 75.999143] [<c012f930>] (process_one_work) from [<c012fb9c>] (worker_thread+
0x2c/0x4e8)
[ 76.007227] [<c012fb9c>] (worker_thread) from [<c0134dac>] (kthread+0xd8/0xf4
)
[ 76.014448] [<c0134dac>] (kthread) from [<c0107778>] (ret_from_fork+0x14/0x3c
)
[ 76.021792] ---[ end trace 8813a228050623a2 ]---
[ 76.027545] ------------[ cut here ]------------
[ 76.032236] WARNING: CPU: 1 PID: 59 at drivers/usb/core/urb.c:449 usb_submit_
urb+0x1c4/0x49c
[ 76.040838] usb 5-1.4.2: BOGUS urb xfer, pipe 1 != type 3
[ 76.046367] Modules linked in: ath9k_htc ath9k_common ath9k_hw ath
[ 76.052647] CPU: 1 PID: 59 Comm: kworker/1:1 Tainted: G W 4.7.0-
rc7-dirty #25
[ 76.060908] Hardware name: Allwinner sun7i (A20) Family
[ 76.066151] Workqueue: events request_firmware_work_func
[ 76.071497] [<c010d818>] (unwind_backtrace) from [<c010a690>] (show_stack+0x1
0/0x14)
[ 76.079245] [<c010a690>] (show_stack) from [<c0359324>] (dump_stack+0x80/0xa0
)
[ 76.086468] [<c0359324>] (dump_stack) from [<c011aa50>] (__warn+0xd4/0x100)
[ 76.093427] [<c011aa50>] (__warn) from [<c011ab24>] (warn_slowpath_fmt+0x38/0
x48)
[ 76.100914] [<c011ab24>] (warn_slowpath_fmt) from [<c04a80c4>] (usb_submit_ur
b+0x1c4/0x49c)
[ 76.109300] [<c04a80c4>] (usb_submit_urb) from [<bf07ba24>] (hif_usb_send+0x1
58/0x30c [ath9k_htc])
[ 76.118278] [<bf07ba24>] (hif_usb_send [ath9k_htc]) from [<bf07a058>] (htc_is
sue_send.constprop.0+0x58/0x5c [ath9k_htc])
[ 76.129161] [<bf07a058>] (htc_issue_send.constprop.0 [ath9k_htc]) from [<bf07
cb58>] (ath9k_wmi_cmd+0x104/0x170 [ath9k_htc])
[ 76.140304] [<bf07cb58>] (ath9k_wmi_cmd [ath9k_htc]) from [<bf081f4c>] (ath9k
_reg_rmw+0x70/0x154 [ath9k_htc])
[ 76.150297] [<bf081f4c>] (ath9k_reg_rmw [ath9k_htc]) from [<bf00daac>] (ath9k
_hw_setpower+0xf4/0x444 [ath9k_hw])
[ 76.160514] [<bf00daac>] (ath9k_hw_setpower [ath9k_hw]) from [<bf00f114>] (at
h9k_hw_init+0x3bc/0xb60 [ath9k_hw])
[ 76.170720] [<bf00f114>] (ath9k_hw_init [ath9k_hw]) from [<bf0822e0>] (ath9k_
htc_probe_device+0x2b0/0x868 [ath9k_htc])
[ 76.181430] [<bf0822e0>] (ath9k_htc_probe_device [ath9k_htc]) from [<bf07a7bc
] (ath9k_htc_hw_init+0x14/0x38 [ath9k_htc])
[ 76.192399] [<bf07a7bc>] (ath9k_htc_hw_init [ath9k_htc]) from [<bf07c2bc>] (a
th9k_hif_usb_firmware_cb+0x8c/0x198 [ath9k_htc])
[ 76.203704] [<bf07c2bc>] (ath9k_hif_usb_firmware_cb [ath9k_htc]) from [<c0421
748>] (request_firmware_work_func+0x30/0x58)
[ 76.214653] [<c0421748>] (request_firmware_work_func) from [<c012f930>] (proc
ess_one_work+0x134/0x33c)
[ 76.223951] [<c012f930>] (process_one_work) from [<c012fb9c>] (worker_thread+
0x2c/0x4e8)
[ 76.232036] [<c012fb9c>] (worker_thread) from [<c0134dac>] (kthread+0xd8/0xf4
)
[ 76.239256] [<c0134dac>] (kthread) from [<c0107778>] (ret_from_fork+0x14/0x3c
)
[ 76.246552] ---[ end trace 8813a228050623a3 ]---
lkcl .
2016-07-24 15:14:03 UTC
Permalink
Post by lkcl .
oo that's interesting.. i had to unplug the ath9k_htc because these
same massive set of continuous streaming of BOGUS urb if:

* USB2 unpowered hub is plugged into OTG Host
* USB3 powered hub is plugged into USB2 hub
* 9271 dongle (no other devices) is plugged into USB3 host

hmmm i suspect the unpowered Genesys Logic USB2 hub more than
anything, but the continuous list of messages isn't helping... :)

l.
Oleksij Rempel
2016-07-24 16:16:55 UTC
Permalink
In case of:
[ 147.060165] usb 5-1.4: ath9k_htc: Unable to allocate URBs
you are out of bandwidth limit of you usb root hub.

Any research in this direction are welcome.

In case of:
[ 75.816339] usb 5-1.4.2: BOGUS urb xfer, pipe 1 != type 3
the adapter was started in USB 1.0 mode (which is present, but never
tested - so, not supported.). Why it is in USB1 mode - no idea, but it
is already second time i have seen it.

Support for USB1 mode seems to be welcome too.
Post by lkcl .
oo that's interesting.. i had to unplug the ath9k_htc because these
* plug in USB3 powered hub into OTG port (set up as USB2 Host)
* plug in USB2 *unpowered* hub into 1 of USB3 powered hub ports
* plug in two ASIX88xx dongles into USB3 powered hub ports
* plug in ath9k_htc tp-link 9271 dongle into *USB2 unpowered* hub port
* unplug 9271 to stop messages going mad
[ 75.803214] ------------[ cut here ]------------
[ 75.807858] WARNING: CPU: 1 PID: 59 at drivers/usb/core/urb.c:449 usb_submit_
urb+0x1c4/0x49c
[ 75.816339] usb 5-1.4.2: BOGUS urb xfer, pipe 1 != type 3
[ 75.821739] Modules linked in: ath9k_htc ath9k_common ath9k_hw ath
[ 75.828019] CPU: 1 PID: 59 Comm: kworker/1:1 Tainted: G W 4.7.0-
rc7-dirty #25
[ 75.836270] Hardware name: Allwinner sun7i (A20) Family
[ 75.841495] Workqueue: events request_firmware_work_func
[ 75.846829] [<c010d818>] (unwind_backtrace) from [<c010a690>] (show_stack+0x1
0/0x14)
[ 75.854571] [<c010a690>] (show_stack) from [<c0359324>] (dump_stack+0x80/0xa0
)
[ 75.861794] [<c0359324>] (dump_stack) from [<c011aa50>] (__warn+0xd4/0x100)
[ 75.868754] [<c011aa50>] (__warn) from [<c011ab24>] (warn_slowpath_fmt+0x38/0
x48)
[ 75.876234] [<c011ab24>] (warn_slowpath_fmt) from [<c04a80c4>] (usb_submit_ur
b+0x1c4/0x49c)
[ 75.884611] [<c04a80c4>] (usb_submit_urb) from [<bf07ba24>] (hif_usb_send+0x1
58/0x30c [ath9k_htc])
[ 75.893586] [<bf07ba24>] (hif_usb_send [ath9k_htc]) from [<bf07a058>] (htc_is
sue_send.constprop.0+0x58/0x5c [ath9k_htc])
[ 75.904468] [<bf07a058>] (htc_issue_send.constprop.0 [ath9k_htc]) from [<bf07
cb58>] (ath9k_wmi_cmd+0x104/0x170 [ath9k_htc])
[ 75.915610] [<bf07cb58>] (ath9k_wmi_cmd [ath9k_htc]) from [<bf081c48>] (ath9k
_regread+0x3c/0x54 [ath9k_htc])
[ 75.925493] [<bf081c48>] (ath9k_regread [ath9k_htc]) from [<bf00da6c>] (ath9k
_hw_setpower+0xb4/0x444 [ath9k_hw])
[ 75.935710] [<bf00da6c>] (ath9k_hw_setpower [ath9k_hw]) from [<bf00f114>] (at
h9k_hw_init+0x3bc/0xb60 [ath9k_hw])
[ 75.945913] [<bf00f114>] (ath9k_hw_init [ath9k_hw]) from [<bf0822e0>] (ath9k_
htc_probe_device+0x2b0/0x868 [ath9k_htc])
[ 75.956622] [<bf0822e0>] (ath9k_htc_probe_device [ath9k_htc]) from [<bf07a7bc
] (ath9k_htc_hw_init+0x14/0x38 [ath9k_htc])
[ 75.967591] [<bf07a7bc>] (ath9k_htc_hw_init [ath9k_htc]) from [<bf07c2bc>] (a
th9k_hif_usb_firmware_cb+0x8c/0x198 [ath9k_htc])
[ 75.978895] [<bf07c2bc>] (ath9k_hif_usb_firmware_cb [ath9k_htc]) from [<c0421
748>] (request_firmware_work_func+0x30/0x58)
[ 75.989845] [<c0421748>] (request_firmware_work_func) from [<c012f930>] (proc
ess_one_work+0x134/0x33c)
[ 75.999143] [<c012f930>] (process_one_work) from [<c012fb9c>] (worker_thread+
0x2c/0x4e8)
[ 76.007227] [<c012fb9c>] (worker_thread) from [<c0134dac>] (kthread+0xd8/0xf4
)
[ 76.014448] [<c0134dac>] (kthread) from [<c0107778>] (ret_from_fork+0x14/0x3c
)
[ 76.021792] ---[ end trace 8813a228050623a2 ]---
[ 76.027545] ------------[ cut here ]------------
[ 76.032236] WARNING: CPU: 1 PID: 59 at drivers/usb/core/urb.c:449 usb_submit_
urb+0x1c4/0x49c
[ 76.040838] usb 5-1.4.2: BOGUS urb xfer, pipe 1 != type 3
[ 76.046367] Modules linked in: ath9k_htc ath9k_common ath9k_hw ath
[ 76.052647] CPU: 1 PID: 59 Comm: kworker/1:1 Tainted: G W 4.7.0-
rc7-dirty #25
[ 76.060908] Hardware name: Allwinner sun7i (A20) Family
[ 76.066151] Workqueue: events request_firmware_work_func
[ 76.071497] [<c010d818>] (unwind_backtrace) from [<c010a690>] (show_stack+0x1
0/0x14)
[ 76.079245] [<c010a690>] (show_stack) from [<c0359324>] (dump_stack+0x80/0xa0
)
[ 76.086468] [<c0359324>] (dump_stack) from [<c011aa50>] (__warn+0xd4/0x100)
[ 76.093427] [<c011aa50>] (__warn) from [<c011ab24>] (warn_slowpath_fmt+0x38/0
x48)
[ 76.100914] [<c011ab24>] (warn_slowpath_fmt) from [<c04a80c4>] (usb_submit_ur
b+0x1c4/0x49c)
[ 76.109300] [<c04a80c4>] (usb_submit_urb) from [<bf07ba24>] (hif_usb_send+0x1
58/0x30c [ath9k_htc])
[ 76.118278] [<bf07ba24>] (hif_usb_send [ath9k_htc]) from [<bf07a058>] (htc_is
sue_send.constprop.0+0x58/0x5c [ath9k_htc])
[ 76.129161] [<bf07a058>] (htc_issue_send.constprop.0 [ath9k_htc]) from [<bf07
cb58>] (ath9k_wmi_cmd+0x104/0x170 [ath9k_htc])
[ 76.140304] [<bf07cb58>] (ath9k_wmi_cmd [ath9k_htc]) from [<bf081f4c>] (ath9k
_reg_rmw+0x70/0x154 [ath9k_htc])
[ 76.150297] [<bf081f4c>] (ath9k_reg_rmw [ath9k_htc]) from [<bf00daac>] (ath9k
_hw_setpower+0xf4/0x444 [ath9k_hw])
[ 76.160514] [<bf00daac>] (ath9k_hw_setpower [ath9k_hw]) from [<bf00f114>] (at
h9k_hw_init+0x3bc/0xb60 [ath9k_hw])
[ 76.170720] [<bf00f114>] (ath9k_hw_init [ath9k_hw]) from [<bf0822e0>] (ath9k_
htc_probe_device+0x2b0/0x868 [ath9k_htc])
[ 76.181430] [<bf0822e0>] (ath9k_htc_probe_device [ath9k_htc]) from [<bf07a7bc
] (ath9k_htc_hw_init+0x14/0x38 [ath9k_htc])
[ 76.192399] [<bf07a7bc>] (ath9k_htc_hw_init [ath9k_htc]) from [<bf07c2bc>] (a
th9k_hif_usb_firmware_cb+0x8c/0x198 [ath9k_htc])
[ 76.203704] [<bf07c2bc>] (ath9k_hif_usb_firmware_cb [ath9k_htc]) from [<c0421
748>] (request_firmware_work_func+0x30/0x58)
[ 76.214653] [<c0421748>] (request_firmware_work_func) from [<c012f930>] (proc
ess_one_work+0x134/0x33c)
[ 76.223951] [<c012f930>] (process_one_work) from [<c012fb9c>] (worker_thread+
0x2c/0x4e8)
[ 76.232036] [<c012fb9c>] (worker_thread) from [<c0134dac>] (kthread+0xd8/0xf4
)
[ 76.239256] [<c0134dac>] (kthread) from [<c0107778>] (ret_from_fork+0x14/0x3c
)
[ 76.246552] ---[ end trace 8813a228050623a3 ]---
_______________________________________________
ath9k-devel mailing list
https://lists.ath9k.org/mailman/listinfo/ath9k-devel
--
Regards,
Oleksij
lkcl .
2016-07-24 18:24:12 UTC
Permalink
Post by lkcl .
[ 147.060165] usb 5-1.4: ath9k_htc: Unable to allocate URBs
you are out of bandwidth limit of you usb root hub.
*bandwidth* limit?!?! bizarre. but this is a USB3 hub plugged into
a USB2 port, and people plug these in directly into USB2 powered hubs
no problem with other devices (i just don't have one available right
now).
Post by lkcl .
Any research in this direction are welcome.
alright i'll take a look around.

l.
Oleksij Rempel
2016-07-24 19:18:34 UTC
Permalink
Post by lkcl .
Post by lkcl .
[ 147.060165] usb 5-1.4: ath9k_htc: Unable to allocate URBs
you are out of bandwidth limit of you usb root hub.
can you please grub the output of this file in error case, and send it.
cat /sys/kernel/debug/usb/devices > devices.txt
Post by lkcl .
*bandwidth* limit?!?! bizarre. but this is a USB3 hub plugged into
a USB2 port, and people plug these in directly into USB2 powered hubs
no problem with other devices (i just don't have one available right
now).
Post by lkcl .
Any research in this direction are welcome.
alright i'll take a look around.
l.
--
Regards,
Oleksij
lkcl .
2016-07-24 19:38:17 UTC
Permalink
Post by Oleksij Rempel
Post by lkcl .
[ 147.060165] usb 5-1.4: ath9k_htc: Unable to allocate URBs
you are out of bandwidth limit of you usb root hub.
can you please grub the output of this file in error case, and send it.
do you mean "grab"? :)
Post by Oleksij Rempel
cat /sys/kernel/debug/usb/devices > devices.txt
what options do i enable in the kernel to get /sys/kernel/debug/usb appear?
Oleksij Rempel
2016-07-24 19:40:30 UTC
Permalink
Post by lkcl .
Post by Oleksij Rempel
Post by lkcl .
[ 147.060165] usb 5-1.4: ath9k_htc: Unable to allocate URBs
you are out of bandwidth limit of you usb root hub.
can you please grub the output of this file in error case, and send it.
do you mean "grab"? :)
yea .. :)
Post by lkcl .
Post by Oleksij Rempel
cat /sys/kernel/debug/usb/devices > devices.txt
what options do i enable in the kernel to get /sys/kernel/debug/usb appear?
mount -t debugfs none /sys/kernel/debug/
--
Regards,
Oleksij
lkcl .
2016-07-24 19:58:49 UTC
Permalink
this is with the USB3 hub plugged in, logitech and TP-150 into that.
Post by Oleksij Rempel
mount -t debugfs none /sys/kernel/debug/
lkcl .
2016-07-25 05:37:23 UTC
Permalink
On Mon, Jul 25, 2016 at 6:07 AM, fixed-term.Oleksij.Rempel
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256
hm... take my words back
i reviewed the code, "ath9k_htc: Unable to allocate URBs" may come if
there is not enough RAM or it is too fragmented. Some other reasons
can be too, but current code is not verbose enough to provide mode
information.
eenterestiiing... and this is on a system with 1gb RAM, embedded
system, where i'd started up a full desktop environment.

okay so i should put in a few more printk's at various points, stop
xfce4, and generally try narrowing things down a bit.

l.

Loading...