Libertas: Command 3 timed out issue

Tue Apr 21 06:27:41 EDT 2009

Dear ALL,

I'm trying to get a wifi card working on our ARM board with Libertas
driver in linux 2.6.25.
The card is USI WM-G-MR-09 based on Marvell 8686 chip.

The SD host controller of my board is working on 4 bit mode with SDIO
IRQ disabled and
the libertas driver is padded to transfer a multiple of 4 bytes in
if_sdio.c as here:
http://lists.infradead.org/pipermail/libertas-dev/2008-January/001189.html

(If i enabled SDIO IRQ in host driver, it seemed if_sdio_interrupt was
never be executed and
libertas driver hanged with endlessly sleeping and i don't know why.)

When i insmod libertas module, the driver failed in lbs_update_hw_spec function.
It got the repeatly "libertas: Command 3 timed out" from the output log.

The log is as follows:
-----------------------------------------------------------------
root at 172.31.42.15:~# cd /lib/modules
root at 172.31.42.15:/lib/modules#
root at 172.31.42.15:/lib/modules# echo 8 > /proc/sys/kernel/printk
root at 172.31.42.15:/lib/modules#
root at 172.31.42.15:/lib/modules# insmod libertas.ko libertas_debug=0xffffff
libertas enter: lbs_init_module():1460
libertas leave: lbs_init_module():1462
root at 172.31.42.15:/lib/modules#
root at 172.31.42.15:/lib/modules# insmod libertas_sdio.ko
libertas enter: if_sdio_init_module():1058
libertas_sdio: Libertas SDIO driver
libertas_sdio: Copyright Pierre Ossman
libertas enter: if_sdio_probe():864
libertas thread: class = 0x7, vendor = 0x2DF, device = 0x9103, model =
0xB, ioport = 0x10000
libertas enter: if_sdio_prog_firmware():659
libertas enter: if_sdio_prog_helper():413
libertas thread: waiting for helper to boot...
libertas leave: if_sdio_prog_helper():513, ret 0
libertas enter: if_sdio_prog_real():529
libertas thread: waiting for firmware to boot...
libertas leave: if_sdio_prog_real():649, ret 0
libertas leave: if_sdio_prog_firmware():685, ret 0
libertas enter: lbs_add_card():1081
libertas enter: lbs_init_adapter():993
libertas enter: lbs_allocate_cmd_buffer():1593
libertas enter: __lbs_cleanup_and_insert_cmd():1202
libertas leave: __lbs_cleanup_and_insert_cmd():1214
libertas enter: __lbs_cleanup_and_insert_cmd():1202
libertas leave: __lbs_cleanup_and_insert_cmd():1214
libertas enter: __lbs_cleanup_and_insert_cmd():1202
libertas leave: __lbs_cleanup_and_insert_cmd():1214
libertas enter: __lbs_cleanup_and_insert_cmd():1202
libertas leave: __lbs_cleanup_and_insert_cmd():1214
libertas enter: __lbs_cleanup_and_insert_cmd():1202
libertas leave: __lbs_cleanup_and_insert_cmd():1214
libertas enter: __lbs_cleanup_and_insert_cmd():1202
libertas leave: __lbs_cleanup_and_insert_cmd():1214
libertas enter: __lbs_cleanup_and_insert_cmd():1202
libertas leave: __lbs_cleanup_and_insert_cmd():1214
libertas enter: __lbs_cleanup_and_insert_cmd():1202
libertas leave: __lbs_cleanup_and_insert_cmd():1214
libertas enter: __lbs_cleanup_and_insert_cmd():1202
libertas leave: __lbs_cleanup_and_insert_cmd():1214
libertas enter: __lbs_cleanup_and_insert_cmd():1202
libertas leave: __lbs_cleanup_and_insert_cmd():1214
libertas leave: lbs_allocate_cmd_buffer():1621, ret 0
libertas leave: lbs_init_adapter():1052, ret 0
libertas thread: Starting main thread...
libertas enter: lbs_thread():667
libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=0
libertas leave: lbs_add_card():1147, priv c7eb4360
libertas enter: lbs_start_card():1198
libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0
libertas enter: lbs_setup_firmware():936
libertas enter: lbs_update_hw_spec():53
libertas enter: __lbs_cmd():2122
libertas enter: __lbs_cmd_async():2068
libertas enter: lbs_get_cmd_ctrl_node():1677
libertas leave: lbs_get_cmd_ctrl_node():1695
libertas host: PREP_CMD: command 0x0003
libertas enter: lbs_queue_cmd():1091
libertas host: QUEUE_CMD: inserted command 0x0003 into cmdpendingq
libertas leave: lbs_queue_cmd():1126
libertas leave: __lbs_cmd_async():2109, ret c7ea2c00
libertas thread: main-thread 222 (waking up): intcounter=0
currenttxskb=00000000 dnld_sent=0
libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=0
libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
libertas enter: lbs_execute_next_command():1747
libertas host: EXEC_NEXT_CMD: sending command 0x0003
libertas enter: lbs_submit_command():1139
libertas host: DNLD_CMD: command 0x0003, seq 2, size 46, jiffies 30506
libertas DNLD_CMD: 03 00 2e 00 02 00 00 00 00 00 00 00 00 00 00 00
libertas DNLD_CMD: ff ff ff ff ff ff 00 00 00 00 00 00 00 00 00 00
libertas DNLD_CMD: 00 00 00 00 00 00 00 00 00 00 00 00 00 00
libertas enter: if_sdio_host_to_card(type 1, bytes 46):703
libertas leave: if_sdio_host_to_card():775, ret 0
libertas enter: if_sdio_host_to_card_worker():355
libertas enter: if_sdio_interrupt():821
libertas thread: interrupt: 0x3
libertas enter: lbs_host_to_card_done():500
libertas leave: lbs_host_to_card_done():511
libertas enter: if_sdio_card_to_host():252
libertas thread: packet of type 0 and size 50 bytes
libertas thread: packet fragment (50 < 52)
libertas enter: if_sdio_handle_data():170
libertas enter: lbs_process_rxed_packet():154
libertas RX Data: Before chop rxpd: 00 00 00 00 01 00 00 00 00 00 00
00 03 00 00 00
libertas RX Data: Before chop rxpd: 80 00 00 00 2e 00 00 00 00 00 00
00 02 00 00 00
libertas RX Data: Before chop rxpd: 00 00 00 00 00 00 00 00 00 00 00 00 02 00
libertas rx: rx err: frame received with bad status
libertas: rxpd not ok
libertas leave: lbs_process_rxed_packet():257, ret 0
libertas leave: if_sdio_handle_data():196, ret 0
libertas leave: if_sdio_card_to_host():341, ret 0
libertas leave: if_sdio_interrupt():852, ret 0
libertas leave: if_sdio_host_to_card_worker():395
libertas cmd: DNLD_CMD: sent command 0x0003, jiffies 30523
libertas leave: lbs_submit_command():1174
libertas leave: lbs_execute_next_command():1884
libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=0
libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0

libertas enter (INT): command_timer_fn():971
libertas: Command 3 timed out
libertas leave (INT): command_timer_fn():985
libertas thread: main-thread 222 (waking up): intcounter=0
currenttxskb=00000000 dnld_sent=0
libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=0
libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
libertas: requeueing command 3 due to timeout (#1)
libertas enter: lbs_execute_next_command():1747
libertas host: EXEC_NEXT_CMD: sending command 0x0003
libertas enter: lbs_submit_command():1139
libertas host: DNLD_CMD: command 0x0003, seq 2, size 46, jiffies 31028
libertas DNLD_CMD: 03 00 2e 00 02 00 00 00 00 00 00 00 00 00 00 00
libertas DNLD_CMD: ff ff ff ff ff ff 00 00 00 00 00 00 00 00 00 00
libertas DNLD_CMD: 00 00 00 00 00 00 00 00 00 00 00 00 00 00
libertas enter: if_sdio_host_to_card(type 1, bytes 46):703
libertas leave: if_sdio_host_to_card():775, ret 0
libertas enter: if_sdio_host_to_card_worker():355
libertas enter: if_sdio_interrupt():821
libertas thread: interrupt: 0x3
libertas enter: lbs_host_to_card_done():500
libertas leave: lbs_host_to_card_done():511
libertas enter: if_sdio_card_to_host():252
libertas thread: packet of type 0 and size 50 bytes
libertas thread: packet fragment (50 < 52)
libertas enter: if_sdio_handle_data():170
libertas enter: lbs_process_rxed_packet():154
libertas RX Data: Before chop rxpd: 00 00 00 00 01 00 00 00 00 00 00
00 03 00 00 00
libertas RX Data: Before chop rxpd: 80 00 00 00 2e 00 00 00 00 00 00
00 02 00 00 00
libertas RX Data: Before chop rxpd: 00 00 00 00 00 00 00 00 00 00 00 00 02 00
libertas rx: rx err: frame received with bad status
libertas: rxpd not ok
libertas leave: lbs_process_rxed_packet():257, ret 0
libertas leave: if_sdio_handle_data():196, ret 0
libertas leave: if_sdio_card_to_host():341, ret 0
libertas leave: if_sdio_interrupt():852, ret 0
libertas leave: if_sdio_host_to_card_worker():395
libertas cmd: DNLD_CMD: sent command 0x0003, jiffies 31046
libertas leave: lbs_submit_command():1174
libertas leave: lbs_execute_next_command():1884
libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=0
libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0

……

libertas enter (INT): command_timer_fn():971
libertas: Command 3 timed out
libertas leave (INT): command_timer_fn():985
libertas thread: main-thread 222 (waking up): intcounter=0
currenttxskb=00000000 dnld_sent=0
libertas thread: main-thread 333: intcounter=0 currenttxskb=00000000 dnld_sent=0
libertas thread: main-thread 444: intcounter=0 currenttxskb=00000000 dnld_sent=0
libertas: Excessive timeouts submitting command 3
 <7>libertas enter: lbs_execute_next_command():1747
libertas leave: lbs_execute_next_command():1884
libertas thread: main-thread 111: intcounter=0 currenttxskb=00000000 dnld_sent=0
libertas thread: main-thread sleeping... Conn=1 IntC=0 PS_mode=0 PS_State=0
libertas: PREP_CMD: command 0x0003 failed: -110
libertas enter: __lbs_cleanup_and_insert_cmd():1202
libertas leave: __lbs_cleanup_and_insert_cmd():1214
libertas leave: __lbs_cmd():2145, ret -110
libertas leave: lbs_update_hw_spec():120
libertas leave: lbs_setup_firmware():958, ret -1
libertas leave: lbs_start_card():1253, ret -1
libertas leave: if_sdio_probe():982, ret -1
libertas_sdio: probe of mmc0:0001:1 failed with error -1
libertas leave: if_sdio_init_module():1065, ret 0
-----------------------------------------------------------------

After digging in the code, it seems that the libertas driver always
got a wrong status of the card in the processing of received packet of
CMD3
in lbs_process_rxed_packet function.

Any ideas?

Your comments will be highly appreciated.

Thanks

Regards
Dongas