USB disconnect/connect when restarting wlan interface.

Note. This is an update of the previous post, presenting new clues to the problem.

Hello,
we are investigating a new weird problem on our OMAP-L137 embedded target.
The problem is related to ARM core running Linux 2.6.37.

On our application, a wireless adapter is interfaced to OMAP-L137 USB1 port, and supported by a
run time loadable WLAN driver providing an “ra0” network interface: the driver itself is registered to the USB1 driver.

The WLAN driver, when the wireless adapter is out of radio range with respect to the radio counterpart (adhoc or infra/AP node),
must be [sic..!] software resetted every 90 s: this is done by means of IOCTL call to its driver,
mimicking the result of the Linux commands “ifconfig ra0 down”, “ifconfig ra0 up”.
The embedded target is a collection device, transferring data packets to a client through wireless TCP/IP.

The client can configure the device to store pending collection packets on a MMC bus driven SDHC Flash,
supported by an EXT4 File System, whenever the device is out of radio range, or simply to discard the pending packets.

It appears that when the Flash storage is enabled, on the long run the WLAN driver periodical software reset can fail,
because the USB driver detects a disconnection/reconnection; so the WLAN driver cannot address the WLAN adapter.
In particular the USB1 driver cannot safely terminate the reconnection stage because of lack of memory…

Here is the Linux console output.

[Mon Jul 15 14:32:27.839 2013] ERROR!!! RTMPSetTimer failed, Halt in Progress!<- Regular ifconfig ra0 down
[Mon Jul 15 14:32:28.167 2013] <NetSetup>Interface sync 77 [2/0]...                                ß ifconfig ra0 down completion
[Mon Jul 15 14:32:29.181 2013] (Efuse for 3062/3562/3572) Size=0x2d [2d0-2fc]   ß ifconfig ra0 up starts…
[Mon Jul 15 14:32:34.048 2013] usb 1-1: USB disconnect, address 2                                <- USB1 disconnects.
[Mon Jul 15 14:32:34.048 2013] #
[Mon Jul 15 14:32:34.063 2013] rtusb_disconnect: unregister usbnet usb-ohci.0-1
[Mon Jul 15 14:32:34.063 2013] RtmpOSNetDevDetach(): RtmpOSNetDeviceDetach(), dev->name=ra0!
[Mon Jul 15 14:32:34.079 2013] #
[Mon Jul 15 14:32:34.079 2013] RTUSB_VendorRequest failed(-19),TxFlags=0x0, ReqType=OUT, Req=0x2, Idx=0x404,pAd->Flags=0x100
[Mon Jul 15 14:32:34.095 2013]             Request Value=0x0072!
 [Mon Jul 15 14:32:34.188 2013] ERROR!!! NICInitializeAdapter failed, Status[=0x00000001]
[Mon Jul 15 14:32:34.297 2013] !!! rt28xx Initialized fail !!!
[Mon Jul 15 14:32:34.407 2013] ---> RTMPFreeTxRxRingMemory
[Mon Jul 15 14:32:34.422 2013] <--- RTMPFreeTxRxRingMemory
[Mon Jul 15 14:32:34.438 2013]  RTUSB disconnect successfully
[Mon Jul 15 14:32:34.765 2013] usb 1-1: new full speed USB device using ohci and address 3  <- USB1 reconnection starts.
[Mon Jul 15 14:32:34.984 2013] usb 1-1: New USB device found, idVendor=148f, idProduct=3070
[Mon Jul 15 14:32:34.999 2013] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[Mon Jul 15 14:32:35.015 2013] usb 1-1: Product: 802.11 n WLAN
[Mon Jul 15 14:32:35.015 2013] usb 1-1: Manufacturer: Ralink
[Mon Jul 15 14:32:35.046 2013] usb 1-1: SerialNumber: 1.0
[Mon Jul 15 14:32:35.124 2013]
[Mon Jul 15 14:32:35.124 2013]
[Mon Jul 15 14:32:35.124 2013] === pAd = c2674000, size = 517448 ===
[Mon Jul 15 14:32:35.124 2013]
[Mon Jul 15 14:32:35.155 2013] khubd: page allocation failure. order:5, mode:0x20
[Mon Jul 15 14:32:35.155 2013] [<c002c624>] (unwind_backtrace+0x0/0xec) from [<c007fe8c>] (__alloc_pages_nodemask+0x4b8/0x510)
[Mon Jul 15 14:32:35.249 2013] [<c007fe8c>] (__alloc_pages_nodemask+0x4b8/0x510) from [<c002ce80>] (__dma_alloc+0xa8/0x284)
[Mon Jul 15 14:32:35.280 2013] [<c002ce80>] (__dma_alloc+0xa8/0x284) from [<c002d0d0>] (dma_alloc_coherent+0x50/0x5c)
[Mon Jul 15 14:32:35.311 2013] [<c002d0d0>] (dma_alloc_coherent+0x50/0x5c) from [<bf083648>] (RTMPAllocUsbBulkBufStruct+0x60/0xa8 [rt3070sta])
[Mon Jul 15 14:32:35.343 2013] [<bf083648>] (RTMPAllocUsbBulkBufStruct+0x60/0xa8 [rt3070sta]) from [<bf083cc4>] (RTMPAllocTxRxRingMemory+0x6c/0x218 [rt3070sta])
[Mon Jul 15 14:32:35.389 2013] [<bf083cc4>] (RTMPAllocTxRxRingMemory+0x6c/0x218 [rt3070sta]) from [<bf045084>] (RTMPAllocAdapterBlock+0x1cc/0x2f0 [rt3070sta])
[Mon Jul 15 14:32:35.436 2013] [<bf045084>] (RTMPAllocAdapterBlock+0x1cc/0x2f0 [rt3070sta]) from [<bf08f1a0>] (rtusb_probe+0x84/0x314 [rt3070sta])
[Mon Jul 15 14:32:35.499 2013] [<bf08f1a0>] (rtusb_probe+0x84/0x314 [rt3070sta]) from [<c0206e38>] (usb_probe_interface+0xc4/0x104)
[Mon Jul 15 14:32:35.545 2013] [<c0206e38>] (usb_probe_interface+0xc4/0x104) from [<c01d560c>] (driver_probe_device+0xb0/0x16c)
[Mon Jul 15 14:32:35.561 2013] [<c01d560c>] (driver_probe_device+0xb0/0x16c) from [<c01d4b8c>] (bus_for_each_drv+0x44/0x80)
[Mon Jul 15 14:32:35.608 2013] [<c01d4b8c>] (bus_for_each_drv+0x44/0x80) from [<c01d5800>] (device_attach+0x50/0x68)
[Mon Jul 15 14:32:35.639 2013] [<c01d5800>] (device_attach+0x50/0x68) from [<c01d4a04>] (bus_probe_device+0x24/0x44)
[Mon Jul 15 14:32:35.639 2013] [<c01d4a04>] (bus_probe_device+0x24/0x44) from [<c01d3588>] (device_add+0x308/0x474)
[Mon Jul 15 14:32:35.748 2013] [<c01d3588>] (device_add+0x308/0x474) from [<c02061d4>] (usb_set_configuration+0x514/0x5ac)
[Mon Jul 15 14:32:35.779 2013] [<c02061d4>] (usb_set_configuration+0x514/0x5ac) from [<c020c7b0>] (generic_probe+0x4c/0x80)
[Mon Jul 15 14:32:35.811 2013] [<c020c7b0>] (generic_probe+0x4c/0x80) from [<c0206488>] (usb_probe_device+0x18/0x1c)
[Mon Jul 15 14:32:35.811 2013] [<c0206488>] (usb_probe_device+0x18/0x1c) from [<c01d560c>] (driver_probe_device+0xb0/0x16c)
[Mon Jul 15 14:32:35.842 2013] [<c01d560c>] (driver_probe_device+0xb0/0x16c) from [<c01d4b8c>] (bus_for_each_drv+0x44/0x80)
[Mon Jul 15 14:32:35.873 2013] [<c01d4b8c>] (bus_for_each_drv+0x44/0x80) from [<c01d5800>] (device_attach+0x50/0x68)
[Mon Jul 15 14:32:35.904 2013] [<c01d5800>] (device_attach+0x50/0x68) from [<c01d4a04>] (bus_probe_device+0x24/0x44)
[Mon Jul 15 14:32:35.920 2013] [<c01d4a04>] (bus_probe_device+0x24/0x44) from [<c01d3588>] (device_add+0x308/0x474)
[Mon Jul 15 14:32:35.935 2013] [<c01d3588>] (device_add+0x308/0x474) from [<c01ffd70>] (usb_new_device+0xd0/0x12c)
[Mon Jul 15 14:32:35.935 2013] [<c01ffd70>] (usb_new_device+0xd0/0x12c) from [<c0200f48>] (hub_thread+0x86c/0xca4)
[Mon Jul 15 14:32:35.951 2013] [<c0200f48>] (hub_thread+0x86c/0xca4) from [<c0053eb4>] (kthread+0x84/0x8c)
[Mon Jul 15 14:32:35.967 2013] [<c0053eb4>] (kthread+0x84/0x8c) from [<c0027fc0>] (kernel_thread_exit+0x0/0x8)
[Mon Jul 15 14:32:35.982 2013] Mem-info:
[Mon Jul 15 14:32:35.982 2013] DMA per-cpu:
[Mon Jul 15 14:32:35.982 2013] CPU    0: hi:    0, btch:   1 usd:   0
[Mon Jul 15 14:32:35.982 2013] active_anon:826 inactive_anon:2 isolated_anon:0
[Mon Jul 15 14:32:35.982 2013]  active_file:636 inactive_file:2172 isolated_file:0
[Mon Jul 15 14:32:35.998 2013]  unevictable:0 dirty:50 writeback:0 unstable:0
[Mon Jul 15 14:32:35.998 2013]  free:457 slab_reclaimable:118 slab_unreclaimable:333
[Mon Jul 15 14:32:35.998 2013]  mapped:248 shmem:6 pagetables:44 bounce:0
[Mon Jul 15 14:32:36.013 2013] DMA free:1828kB min:696kB low:868kB high:1044kB active_anon:3304kB inactive_anon:8kB active_file:2544kB inactive_file:8688kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:30480kB mlocked:0kB dirty:200kB writeback:0kB mapped:992kB shmem:24kB slab_reclaimable:472kB slab_unreclaimable:1332kB kernel_stack:464kB pagetables:176kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[Mon Jul 15 14:32:36.185 2013] lowmem_reserve[]: 0 0 0
[Mon Jul 15 14:32:36.185 2013] DMA: 9*4kB 8*8kB 30*16kB 13*32kB 6*64kB 2*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1636kB
[Mon Jul 15 14:32:36.247 2013] 2884 total pagecache pages
[Mon Jul 15 14:32:36.294 2013] 7680 pages of RAM
[Mon Jul 15 14:32:36.294 2013] 454 free pages
[Mon Jul 15 14:32:36.388 2013] 1111 reserved pages
[Mon Jul 15 14:32:36.388 2013] 352 slab pages
[Mon Jul 15 14:32:36.388 2013] 3561 pages shared
[Mon Jul 15 14:32:36.403 2013] 0 pages swap cached
[Mon Jul 15 14:32:36.403 2013] <-- ERROR in Alloc Bulk buffer for HTTxContext!
[Mon Jul 15 14:32:36.419 2013] ---> RTMPFreeTxRxRingMemory
[Mon Jul 15 14:32:36.419 2013] <--- RTMPFreeTxRxRingMemory
[Mon Jul 15 14:32:36.419 2013] ERROR!!! Failed to allocate memory - TxRxRing
[Mon Jul 15 14:32:36.435 2013] <-- RTMPAllocAdapterBlock, Status=3
[Mon Jul 15 14:32:36.435 2013] rt2870: probe of 1-1:1.0 failed with error -1                     <- failed USB1 disconnection ends.
[Mon Jul 15 14:32:39.929 2013] <NetSetup>Sync done [3/-1].                                            <- failed ifconfig ra0 up  completion. 
Please note that the USB1-1 disconnection/reconnection event is tipically triggered by the mechanical
disconnection/reconnection of the module ; or just simply by the disabling of USB1 connector Vcc line. 

The USB/WLAN driver failure rate is random, but tipically more than 100 cycles reset are safely performed.
Please note that the Linux application goes on safely storing pending data to SDHC Flash: only the wireless
communication is spoilt.

When the Flash storage is not enabled, (i.e. no substantial MMC bus activity is performed by the EXT4 driver),
the periodical WLAN driver software reset goes on unhindered.
Same result for “fake” storage enabled collections, where however disk fwrite/fsync calls are removed. 

The question is: can such failure be caused by an hardware fault ?

Please note that on our board:
USB1 lines/power supply appear to be clean.
MMC lines are kept apart from USB1 lines.
Strangely the problem is much more frequent on OMAP-L137 rev. D release.

In conclusion:
I wonder if the problem can rely on some pending problems related to the USB1 and MMC controllers integrated on OMAP-L137:
the Errata doc “Literature Number: SPRZ291G/October 2008–Revised September 2012” does not mention it.

Any help on such problem is deeply appreciated.

Thank you for your attention.

I found that SD Flash is driven [ MMC_CLK) @ 49 MHz.

On 

TMS320C674x/OMAP-L1x Processor
Multimedia Card (MMC)/
Secure Digital (SD) Card Controller
User's Guide

Literature Number: SPRUFM2B August 2010

I find that 

1.2 Features

The MMC/SD card controller has the following features:
• 20 MHz maximum clock to MMC
• 25 MHz maximum clock to SD

However I find on 

1.5 Industry Standard(s) Compliance Statement
The MMC/SD card controller supports the following industry standards (with the exception noted below):
• MMC (Multimedia Card) Specification v4.0
• SD (Secure Digital) Physical Layer Specification v1.1
• SDIO (Secure Digital Input Output) Specification v2.0

But SD (Secure Digital) Physical Layer Specification v1.1 actually supports high speed mode, allowing MMC_CLK to be raised up to 50 MHz.

So 

1)what is the actual max MMC_CLK rate the MMC/SD controller on OMAP-L137 can grant ?

2)Could an out of specification MMC_CLK rate lead to a "contention" with the USB bus, provoking its reset ?

Thank you for your attention.