Hello All,
we are experiencing USB issues with CDC/ACM and USB to Serial adapters connected to an Alfa Hornet-U board. This board is based on the Atheros 9331 chipset.
We are working with a very recent version of AA from trunk (33561)
The problem is very similar in nature to one reported for TP-LINK routers also based on the 9331 chipset. The interesting thing is that if a passive (non powered) USB 2.0 hub is used then CDC/ACM and USB to Serial adapters work fine.
Here is a full description of the problem and symptoms.
When working withe USB we notice that when plugging in CDC/ACM devices (i.e. satellite terminals or GSM dongles) the USB port works for a bit and then becomes unresponsive. Resetting the USB port by unplugging the cable and putting it back in gets the device back on line. However, none of the devices plugged into the port will work sufficiently long to send data. You can connect to them with a terminal emulator (cu in our case) and type AT commands but as soon as you do an ATDT and get a CONNECT and ppp data starts moving through the internetface the serial port 'hangs'.
The interesting thing is that we just noticed this... we have been working with the USB port extensively but always using a USB hub. The passive hub (i.e. not powered) has the CDC/ACM device plugged into it as well as a CMedia USB sound card. What is strange is that the Vitual serial port works perfectly. Data connections work without issue over the satellite phones in this configuration.
Googling the internet for this issue shows a few results. it seems that this is a fairly common problem with Atheros processors.
the tl-mr3040 is known to have this issue.
http://wiki.openwrt.org/toh/tp-link/tl-mr3040
if you look on the openwrt site and scroll down to the hardware description you will find the following.
USB Issue
A problem has been detected with the USB interface on the device. When connected to different models of serial adaptor, it functions for a few minutes then fails. This can be resolved by putting a passive hub in-line with the device. Voltage and current testing will be performed to identify why this behaviour occurs.
this device is based on the AR9331 as is the Hornet.
Also
http://www.mail-archive.com/openwrt-dev … 13693.html
if you look at the 5 entries in this list you will note that the AR9331 is not the only device that is having this issue.
this posting
http://www.mail-archive.com/openwrt-dev … 13690.html
suggest that the problem has to do with hardware voltage and other possible issues with the board implementation. a link is included to a hardware mod discussion that presents the issue with the Atherus based boards.
here is more detailed info on the USB problem we are having with CDC/ACM modems with the native serial port on the AP121U.
Here is a connection using a passive (non powered) 2.0 usb hub and an iridium phone. You will note that the connection works perfectly. Following that I will show logs for the same device connected directly to the Hornet-UB usb which fails.
------ USB HUB -- WORKING CONNECTION ----
This the kernel mesgs detecting the HUB
[ 483.150000] usb 1-1: USB disconnect, device number 3
Oct 16 17:39:12 Optimizer kern.info kernel: [ 483.150000] usb 1-1: USB disconnect, device number 3
[ 493.450000] usb 1-1: new high-speed USB device number 4 using ehci-platform
[ 493.600000] hub 1-1:1.0: USB hub found
[ 493.600000] hub 1-1:1.0: 4 ports detected
Oct 16 17:39:22 Optimizer kern.info kernel: [ 493.450000] usb 1-1: new high-speed USB device number 4 using ehci-platform
Oct 16 17:39:22 Optimizer kern.info kernel: [ 493.600000] hub 1-1:1.0: USB hub found
Oct 16 17:39:22 Optimizer kern.info kernel: [ 493.600000] hub 1-1:1.0: 4 ports detected
this is the kernel msgs for detecting the USB ACM device.
[ 528.330000] usb 1-1.2: new full-speed USB device number 5 using ehci-platform
[ 528.450000] cdc_acm 1-1.2:1.0: ttyACM0: USB ACM device
Oct 16 17:39:57 Optimizer kern.info kernel: [ 528.330000] usb 1-1.2: new full-speed USB device number 5 using ehci-platform
Oct 16 17:39:57 Optimizer kern.info kernel: [ 528.450000] cdc_acm 1-1.2:1.0: ttyACM0: USB ACM device
here is a successful PPP connection...
Oct 16 17:40:21 Optimizer daemon.notice pppd[2018]: pppd 2.4.5 started by root, uid 0
Oct 16 17:40:22 Optimizer local2.info chat[2028]: abort on (BUSY)
Oct 16 17:40:22 Optimizer local2.info chat[2028]: abort on (VOICE)
Oct 16 17:40:22 Optimizer local2.info chat[2028]: abort on (NO CARRIER)
Oct 16 17:40:22 Optimizer local2.info chat[2028]: abort on (NO DIALTONE)
Oct 16 17:40:22 Optimizer local2.info chat[2028]: abort on (NO DIAL TONE)
Oct 16 17:40:22 Optimizer local2.info chat[2028]: timeout set to 10 seconds
Oct 16 17:40:22 Optimizer local2.info chat[2028]: send (AT^M)
Oct 16 17:40:22 Optimizer local2.info chat[2028]: expect (OK)
Oct 16 17:40:22 Optimizer local2.info chat[2028]: ^M
Oct 16 17:40:22 Optimizer local2.info chat[2028]: OK
Oct 16 17:40:22 Optimizer local2.info chat[2028]: -- got it
Oct 16 17:40:22 Optimizer local2.info chat[2028]: send (AT&F^M)
Oct 16 17:40:22 Optimizer local2.info chat[2028]: expect (OK)
Oct 16 17:40:22 Optimizer local2.info chat[2028]: ^M
Oct 16 17:40:22 Optimizer local2.info chat[2028]: ^M
Oct 16 17:40:22 Optimizer local2.info chat[2028]: OK
Oct 16 17:40:22 Optimizer local2.info chat[2028]: -- got it
Oct 16 17:40:22 Optimizer local2.info chat[2028]: send (AT &F E0 V1 &D2 &C1 W2 S95=47 S0=0 +cbst=71,0,1^M)
Oct 16 17:40:23 Optimizer local2.info chat[2028]: timeout set to 60 seconds
Oct 16 17:40:23 Optimizer local2.info chat[2028]: expect (OK)
Oct 16 17:40:23 Optimizer local2.info chat[2028]: ^M
Oct 16 17:40:23 Optimizer local2.info chat[2028]: AT &F E0 V1 &D2 &C1 W2 S95=47 S0=0 +cbst=71,0,1^M^M
Oct 16 17:40:23 Optimizer local2.info chat[2028]: OK
Oct 16 17:40:23 Optimizer local2.info chat[2028]: -- got it
Oct 16 17:40:23 Optimizer local2.info chat[2028]: send (ATDT008816000025^M)
Oct 16 17:40:23 Optimizer local2.info chat[2028]: expect (CONNECT)
Oct 16 17:40:23 Optimizer local2.info chat[2028]: ^M
Oct 16 17:40:33 Optimizer local2.info chat[2028]: ^M
Oct 16 17:40:33 Optimizer local2.info chat[2028]: CARRIER 9600^M
Oct 16 17:40:33 Optimizer local2.info chat[2028]: ^M
Oct 16 17:40:33 Optimizer local2.info chat[2028]: PROTOCOL: IRLP^M
Oct 16 17:40:33 Optimizer local2.info chat[2028]: ^M
Oct 16 17:40:33 Optimizer local2.info chat[2028]: COMPRESSION: NONE^M
Oct 16 17:40:33 Optimizer local2.info chat[2028]: ^M
Oct 16 17:40:33 Optimizer local2.info chat[2028]: CONNECT
Oct 16 17:40:33 Optimizer local2.info chat[2028]: -- got it
Oct 16 17:40:33 Optimizer daemon.info pppd[2018]: Serial connection established.
Oct 16 17:40:33 Optimizer daemon.info pppd[2018]: Using interface ppp0
Oct 16 17:40:33 Optimizer daemon.notice pppd[2018]: Connect: ppp0 <--> /dev/ttyACM0
Oct 16 17:40:40 Optimizer daemon.info pppd[2018]: CHAP authentication succeeded
Oct 16 17:40:40 Optimizer daemon.notice pppd[2018]: CHAP authentication succeeded
Oct 16 17:40:46 Optimizer daemon.notice pppd[2018]: replacing old default route to eth1 [192.168.0.1]
Oct 16 17:40:46 Optimizer daemon.notice pppd[2018]: local IP address 192.168.21.75
Oct 16 17:40:46 Optimizer daemon.notice pppd[2018]: remote IP address 192.168.21.254
Oct 16 17:40:46 Optimizer daemon.notice pppd[2018]: primary DNS address 12.127.17.72
Oct 16 17:40:46 Optimizer daemon.notice pppd[2018]: secondary DNS address 204.97.212.10
Oct 16 17:40:48 Optimizer daemon.info pppd[2061]: CCP terminated by peer
Oct 16 17:40:48 Optimizer daemon.notice pppd[2061]: Compression disabled by peer.
Oct 16 17:40:56 Optimizer daemon.info pppd[2061]: Terminating on signal 15
Oct 16 17:40:56 Optimizer daemon.info pppd[2061]: Connect time 0.2 minutes.
Oct 16 17:40:56 Optimizer daemon.info pppd[2061]: Sent 12 bytes, received 12 bytes.
Oct 16 17:40:56 Optimizer daemon.notice pppd[2061]: restoring old default route to eth1 [192.168.0.1]
Oct 16 17:40:57 Optimizer daemon.notice pppd[2061]: Connection terminated.
Oct 16 17:40:58 Optimizer local2.info chat[2096]: abort on (BUSY)
Oct 16 17:40:58 Optimizer local2.info chat[2096]: abort on (VOICE)
Oct 16 17:40:58 Optimizer local2.info chat[2096]: abort on (NO CARRIER)
Oct 16 17:40:58 Optimizer local2.info chat[2096]: abort on (NO DIALTONE)
Oct 16 17:40:58 Optimizer local2.info chat[2096]: abort on (NO DIAL TONE)
Oct 16 17:40:58 Optimizer local2.info chat[2096]: timeout set to 10 seconds
Oct 16 17:40:58 Optimizer local2.info chat[2096]: send (+++^M)
Oct 16 17:40:58 Optimizer local2.info chat[2096]: expect (OK)
Oct 16 17:41:00 Optimizer local2.info chat[2096]: TUUUUUUUUUUUU^M
Oct 16 17:41:00 Optimizer local2.info chat[2096]: NO CARRIER
Oct 16 17:41:00 Optimizer local2.info chat[2096]: -- failed
Oct 16 17:41:00 Optimizer local2.info chat[2096]: Failed (NO CARRIER)
Oct 16 17:41:00 Optimizer daemon.warn pppd[2061]: disconnect script failed
Oct 16 17:41:01 Optimizer daemon.info pppd[2061]: Exit.
-----------
Logs for DCD/ACM device directly connected to the AP121U which fails...
----- DIRECT CONNECTION --- FAILS ---
USB device is plugged into the system.
[ 839.120000] usb 1-1: new full-speed USB device number 6 using ehci-platform
[ 839.290000] cdc_acm 1-1:1.0: ttyACM0: USB ACM device
Oct 16 17:45:08 Optimizer kern.info kernel: [ 839.120000] usb 1-1: new full-speed USB device number 6 using ehci-platform
Oct 16 17:45:08 Optimizer kern.info kernel: [ 839.290000] cdc_acm 1-1:1.0: ttyACM0: USB ACM device
the following commands are executed from the command line to make sure the device is working properly.
root@Optimizer:/sys/devices/platform/ehci-platform/usb1/1-1# echo 0 > authorized
root@Optimizer:/sys/devices/platform/ehci-platform/usb1/1-1# echo 1 > authorized
A PPPD session is started...
[ 881.310000] cdc_acm 1-1:1.0: ttyACM0: USB ACM device
[ 881.320000] usb 1-1: authorized to connect
Oct 16 17:45:50 Optimizer kern.info kernel: [ 881.310000] cdc_acm 1-1:1.0: ttyACM0: USB ACM device
Oct 16 17:45:50 Optimizer kern.info kernel: [ 881.320000] usb 1-1: authorized to connect
Oct 16 17:46:04 Optimizer daemon.notice pppd[2229]: pppd 2.4.5 started by root, uid 0
Oct 16 17:46:05 Optimizer local2.info chat[2240]: abort on (BUSY)
Oct 16 17:46:05 Optimizer local2.info chat[2240]: abort on (VOICE)
Oct 16 17:46:05 Optimizer local2.info chat[2240]: abort on (NO CARRIER)
Oct 16 17:46:05 Optimizer local2.info chat[2240]: abort on (NO DIALTONE)
Oct 16 17:46:05 Optimizer local2.info chat[2240]: abort on (NO DIAL TONE)
Oct 16 17:46:05 Optimizer local2.info chat[2240]: timeout set to 10 seconds
Oct 16 17:46:05 Optimizer local2.info chat[2240]: send (AT^M)
Oct 16 17:46:05 Optimizer local2.info chat[2240]: expect (OK)
Oct 16 17:46:05 Optimizer local2.info chat[2240]: ^M
Oct 16 17:46:05 Optimizer local2.info chat[2240]: OK
Oct 16 17:46:05 Optimizer local2.info chat[2240]: -- got it
Oct 16 17:46:05 Optimizer local2.info chat[2240]: send (AT&F^M)
Oct 16 17:46:05 Optimizer local2.info chat[2240]: expect (OK)
Oct 16 17:46:05 Optimizer local2.info chat[2240]: ^M
Oct 16 17:46:05 Optimizer local2.info chat[2240]: ^M
Oct 16 17:46:05 Optimizer local2.info chat[2240]: OK
Oct 16 17:46:05 Optimizer local2.info chat[2240]: -- got it
Oct 16 17:46:05 Optimizer local2.info chat[2240]: send (AT &F E0 V1 &D2 &C1 W2 S95=47 S0=0 +cbst=71,0,1^M)
Oct 16 17:46:06 Optimizer local2.info chat[2240]: timeout set to 60 seconds
Oct 16 17:46:06 Optimizer local2.info chat[2240]: expect (OK)
Oct 16 17:46:06 Optimizer local2.info chat[2240]: ^M
Oct 16 17:46:06 Optimizer local2.info chat[2240]: AT &F E0 V1 &D2 &C1 W2 S95=47 S0=0 +cbst=71,0,1^M^M
Oct 16 17:46:06 Optimizer local2.info chat[2240]: OK
Oct 16 17:46:06 Optimizer local2.info chat[2240]: -- got it
Oct 16 17:46:06 Optimizer local2.info chat[2240]: send (ATDT008816000025^M)
Oct 16 17:46:06 Optimizer local2.info chat[2240]: expect (CONNECT)
Oct 16 17:46:06 Optimizer local2.info chat[2240]: ^M
Oct 16 17:47:06 Optimizer local2.info chat[2240]: alarm
Oct 16 17:47:06 Optimizer local2.info chat[2240]: Failed
Oct 16 17:47:06 Optimizer daemon.err pppd[2229]: Connect script failed
Oct 16 17:47:22 Optimizer daemon.info pppd[2229]: Exit.
the connection script failed... never got the CONNECT... yet the call was made and time was accumulating on the phone... Basically data stopped flowing through the interface...
the following commands
root@Optimizer:/sys/devices/platform/ehci-platform/usb1/1-1# echo 0 > authorized
root@Optimizer:/sys/devices/platform/ehci-platform/usb1/1-1# echo 1 > authorized
now result in this error...
[ 996.220000] usb 1-1: can't re-read device descriptor for authorization: -145
Oct 16 17:47:45 Optimizer kern.err kernel: [ 996.220000] usb 1-1: can't re-read device descriptor for authorization: -145
so... the USB device is no longer responsive.
--------
Note that exactly the same happens when using a PL2303HX USB to serial adapter. So... it seems that whatever USB protocol is being used by all the serial adapters is at fault. We observe the same symptoms with any/all CDC/ACM and USB to Serial port adapters that we have tested.
However... when connected through a HUB everything works perfectly.
Any insight in to the problem would greatly be appreciated.
--luis
(Last edited by lsoltero on 16 Dec 2013, 23:16)