Libertas: Command 3 timed out issue

Wed Apr 22 19:39:14 EDT 2009

Hi Dongas,

Something is interesting in your log.

> 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

This is the CMD (ID=0x0003, Size=0x002e, SeqNum=0x0002, Result=0x0000) sent to firmware:

32 00 (length, 0x2e + 4 bytes for header)
01 00 (type)
03 00 2e 00 02 00 00 00 00 00 00 00 00 00 00 00
ff ff ff ff ff ff 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00

> 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

Look at the "RX Data" printed in your if_sdio_card_to_host():

00 00 00 00, 01 00 00 00, 00 00 00 00, 03 00 00 00
80 00 00 00, 2e 00 00 00, 00 00 00 00, 02 00 00 00
00 00 00 00, 00 00 00 00, 00 00 00 00, 02 00

If I take only the first byte of each 4-byte group I will get:

00 01 00 03
80 2e 00 02
00 00 00 02

Does it look like a command response?
No? Let's look at it this way:

?? 00 (length)
01 00 (type)
03 80 2e 00 02 00 00 00 02 ...

Where is the first byte of the header?

> libertas thread: packet of type 0 and size 50 bytes

Here it is, 50 (0x32)!

32 00 (length)
01 00 (type)
03 80 2e 00 02 00 00 00 02 ...

Now, does it look like the CMD RESP (ID=0x8003, Size=0x002e, SeqNum=0x0002, Result=0x0000)?

32 00 (size, 0x2e + 4 bytes for header)
01 00 (type)
03 80 2e 00 02 00 00 00 02 ?? ?? ?? ?? ?? ?? ??
?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ??
?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ??

You may want to print out more "RX Data" in your if_sdio_card_to_host() to find out what the "??" bytes are.

Bing

-----Original Message-----
From: libertas-dev-bounces at lists.infradead.org [mailto:libertas-dev-bounces at lists.infradead.org] On Behalf Of dongas
Sent: Tuesday, April 21, 2009 3:28 AM
To: libertas-dev at lists.infradead.org
Cc: benson dong
Subject: Libertas: Command 3 timed out issue

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

_______________________________________________
libertas-dev mailing list
libertas-dev at lists.infradead.org
http://lists.infradead.org/mailman/listinfo/libertas-dev