Problem bringing up module...
Dave Kroetsch
dave at aeryon.com
Thu Mar 13 17:53:51 EDT 2008
Dan Williams wrote:
> My thought here was that since the recent cmd/response mixup fixes
> aren't in wireless-2.6, the data from the logs running wireless-2.6
> isn't going to be reliable. Best to repeat with wireless-testing and
> see what the output there is for the failed command, and then we havea
> much better chance of tracking the issue down via the logs.
Alrighty,
So following Dan's advice, I've updated to the wireless-testing tree,
and I have the same problem. The logs are attached below:
[ 40.290000] libertas enter: lbs_init_module():1471
[ 40.290000] libertas leave: lbs_init_module():1473
[ 40.310000] libertas_cs enter: if_cs_init():953
[ 40.310000] libertas_cs enter: if_cs_probe():754
[ 40.310000] pr: COR
[ 40.360000] libertas_cs cs: irq 54, io 0xc3880000-0xc388007f
[ 40.360000] libertas_cs enter: if_cs_prog_helper():447
[ 40.490000] libertas_cs cs: helper size 2132
[ 40.500000] libertas_cs leave: if_cs_prog_helper():524, ret 0
[ 40.500000] libertas_cs enter: if_cs_prog_real():537
[ 40.710000] libertas_cs cs: fw size 94944
[ 41.060000] libertas_cs leave: if_cs_prog_real():610, ret 0
[ 41.060000] libertas enter: lbs_add_card():1092
[ 41.060000] libertas enter: lbs_init_adapter():1004
[ 41.060000] libertas enter: lbs_allocate_cmd_buffer():1584
[ 41.060000] libertas enter: __lbs_cleanup_and_insert_cmd():1210
[ 41.060000] libertas leave: __lbs_cleanup_and_insert_cmd():1222
[ 41.060000] libertas enter: __lbs_cleanup_and_insert_cmd():1210
[ 41.060000] libertas leave: __lbs_cleanup_and_insert_cmd():1222
[ 41.060000] libertas enter: __lbs_cleanup_and_insert_cmd():1210
[ 41.060000] libertas leave: __lbs_cleanup_and_insert_cmd():1222
[ 41.070000] libertas enter: __lbs_cleanup_and_insert_cmd():1210
[ 41.070000] libertas leave: __lbs_cleanup_and_insert_cmd():1222
[ 41.070000] libertas enter: __lbs_cleanup_and_insert_cmd():1210
[ 41.070000] libertas leave: __lbs_cleanup_and_insert_cmd():1222
[ 41.070000] libertas enter: __lbs_cleanup_and_insert_cmd():1210
[ 41.070000] libertas leave: __lbs_cleanup_and_insert_cmd():1222
[ 41.070000] libertas enter: __lbs_cleanup_and_insert_cmd():1210
[ 41.070000] libertas leave: __lbs_cleanup_and_insert_cmd():1222
[ 41.080000] libertas enter: __lbs_cleanup_and_insert_cmd():1210
[ 41.080000] libertas leave: __lbs_cleanup_and_insert_cmd():1222
[ 41.080000] libertas enter: __lbs_cleanup_and_insert_cmd():1210
[ 41.080000] libertas leave: __lbs_cleanup_and_insert_cmd():1222
[ 41.080000] libertas enter: __lbs_cleanup_and_insert_cmd():1210
[ 41.080000] libertas leave: __lbs_cleanup_and_insert_cmd():1222
[ 41.080000] libertas leave: lbs_allocate_cmd_buffer():1612, ret 0
[ 41.080000] libertas leave: lbs_init_adapter():1063, ret 0
[ 41.080000] libertas thread: Starting main thread...
[ 41.080000] libertas enter: lbs_thread():666
[ 41.080000] libertas thread: main-thread 111: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 41.080000] libertas thread: main-thread sleeping... Conn=1 IntC=0
PS_mode=0 PS_State=0
[ 41.080000] libertas leave: lbs_add_card():1158, priv c27003a0
[ 41.080000] libertas_cs enter: if_cs_enable_ints():238
[ 41.080000] libertas enter: lbs_start_card():1209
[ 41.080000] libertas enter: lbs_setup_firmware():935
[ 41.080000] libertas enter: lbs_update_hw_spec():53
[ 41.080000] libertas enter: __lbs_cmd():2104
[ 41.080000] libertas enter: __lbs_cmd_async():2050
[ 41.080000] libertas enter: lbs_get_cmd_ctrl_node():1668
[ 41.080000] libertas leave: lbs_get_cmd_ctrl_node():1686
[ 41.080000] libertas host: PREP_CMD: command 0x0003
[ 41.080000] libertas enter: lbs_queue_cmd():1119
[ 41.080000] libertas host: QUEUE_CMD: inserted command 0x0003 into
cmdpendingq
[ 41.080000] libertas leave: lbs_queue_cmd():1154
[ 41.080000] libertas thread: main-thread 222 (waking up):
intcounter=0 currenttxskb=00000000 dnld_sent=0
[ 41.080000] libertas thread: main-thread 333: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 41.080000] libertas thread: main-thread 444: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 41.080000] libertas enter: lbs_execute_next_command():1738
[ 41.080000] libertas host: EXEC_NEXT_CMD: sending command 0x0003
[ 41.080000] libertas enter: lbs_submit_command():1167
[ 41.080000] libertas cmd: DNLD_CMD: command 0x0003, seq 2, size 46,
jiffies 4294941404
[ 41.080000] libertas_cs enter: if_cs_host_to_card(type 1, bytes 46):628
[ 41.080000] libertas_cs enter: if_cs_send_cmd():294
[ 41.080000] libertas_cs leave: if_cs_send_cmd():325, ret 0
[ 41.080000] libertas_cs leave: if_cs_host_to_card():644, ret 0
[ 41.080000] libertas leave: lbs_submit_command():1200
[ 41.080000] libertas leave: lbs_execute_next_command():1873
[ 41.080000] libertas_cs enter (INT): if_cs_interrupt():253
[ 41.080000] libertas enter (INT): lbs_interrupt():1457
[ 41.080000] libertas thread (INT): lbs_interrupt: intcounter=0
[ 41.080000] libertas leave (INT): lbs_interrupt():1465
[ 41.080000] libertas thread: main-thread 111: intcounter=1
currenttxskb=00000000 dnld_sent=2
[ 41.080000] libertas thread: main-thread 222 (waking up):
intcounter=1 currenttxskb=00000000 dnld_sent=2
[ 41.080000] libertas thread: main-thread 333: intcounter=1
currenttxskb=00000000 dnld_sent=2
[ 41.080000] libertas_cs enter: if_cs_get_int_status():656
[ 41.080000] libertas_cs enter: if_cs_receive_cmdres():361
[ 41.080000] libertas_cs leave: if_cs_receive_cmdres():386, ret 0,
len 46
[ 41.080000] libertas_cs leave: if_cs_get_int_status():692, ret 0,
ireg 0xd, hisregcpy 0x0
[ 41.080000] libertas thread: main-thread 444: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 41.080000] libertas thread: main-thread: cmd response ready
[ 41.080000] libertas enter: lbs_process_rx_command():488
[ 41.080000] libertas cmd: CMD_RESP: response 0x8003, seq 32771,
size 46, jiffies 4294941404
[ 41.080000] libertas: Received CMD_RESP with invalid sequence 32771
(expected 2)
[ 41.090000] libertas leave: lbs_process_rx_command():638, ret -1
[ 41.090000] libertas thread: main-thread 111: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 41.090000] libertas thread: main-thread sleeping... Conn=1 IntC=0
PS_mode=0 PS_State=0
[ 41.090000] libertas leave: __lbs_cmd_async():2091, ret c2b0c000
[ 46.080000] libertas enter (INT): command_timer_fn():970
[ 46.080000] libertas: Command 3 timed out
[ 46.080000] libertas leave (INT): command_timer_fn():984
[ 46.080000] libertas thread: main-thread 222 (waking up):
intcounter=0 currenttxskb=00000000 dnld_sent=0
[ 46.080000] libertas thread: main-thread 333: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 46.080000] libertas thread: main-thread 444: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 46.080000] libertas: requeueing command 3 due to timeout (#1)
[ 46.090000] libertas enter: lbs_execute_next_command():1738
[ 46.090000] libertas host: EXEC_NEXT_CMD: sending command 0x0003
[ 46.090000] libertas enter: lbs_submit_command():1167
[ 46.090000] libertas cmd: DNLD_CMD: command 0x0003, seq 2, size 46,
jiffies 4294941905
[ 46.090000] libertas_cs enter: if_cs_host_to_card(type 1, bytes 46):628
[ 46.090000] libertas_cs enter: if_cs_send_cmd():294
[ 46.090000] libertas_cs leave: if_cs_send_cmd():325, ret 0
[ 46.090000] libertas_cs leave: if_cs_host_to_card():644, ret 0
[ 46.090000] libertas leave: lbs_submit_command():1200
[ 46.090000] libertas leave: lbs_execute_next_command():1873
[ 46.090000] libertas_cs enter (INT): if_cs_interrupt():253
[ 46.090000] libertas enter (INT): lbs_interrupt():1457
[ 46.090000] libertas thread (INT): lbs_interrupt: intcounter=0
[ 46.090000] libertas leave (INT): lbs_interrupt():1465
[ 46.090000] libertas thread: main-thread 111: intcounter=1
currenttxskb=00000000 dnld_sent=2
[ 46.090000] libertas thread: main-thread 222 (waking up):
intcounter=1 currenttxskb=00000000 dnld_sent=2
[ 46.090000] libertas thread: main-thread 333: intcounter=1
currenttxskb=00000000 dnld_sent=2
[ 46.090000] libertas_cs enter: if_cs_get_int_status():656
[ 46.090000] libertas_cs enter: if_cs_receive_cmdres():361
[ 46.090000] libertas_cs leave: if_cs_receive_cmdres():386, ret 0,
len 46
[ 46.090000] libertas_cs leave: if_cs_get_int_status():692, ret 0,
ireg 0xd, hisregcpy 0x5
[ 46.090000] libertas thread: main-thread 444: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 46.090000] libertas thread: main-thread: cmd response ready
[ 46.090000] libertas enter: lbs_process_rx_command():488
[ 46.090000] libertas cmd: CMD_RESP: response 0x8003, seq 32771,
size 46, jiffies 4294941905
[ 46.090000] libertas: Received CMD_RESP with invalid sequence 32771
(expected 2)
[ 46.090000] libertas leave: lbs_process_rx_command():638, ret -1
[ 46.090000] libertas thread: main-thread 111: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 46.090000] libertas thread: main-thread sleeping... Conn=1 IntC=0
PS_mode=0 PS_State=0
[ 51.090000] libertas enter (INT): command_timer_fn():970
[ 51.090000] libertas: Command 3 timed out
[ 51.090000] libertas leave (INT): command_timer_fn():984
[ 51.090000] libertas thread: main-thread 222 (waking up):
intcounter=0 currenttxskb=00000000 dnld_sent=0
[ 51.090000] libertas thread: main-thread 333: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 51.090000] libertas thread: main-thread 444: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 51.090000] libertas: requeueing command 3 due to timeout (#2)
[ 51.100000] libertas enter: lbs_execute_next_command():1738
[ 51.100000] libertas host: EXEC_NEXT_CMD: sending command 0x0003
[ 51.100000] libertas enter: lbs_submit_command():1167
[ 51.100000] libertas cmd: DNLD_CMD: command 0x0003, seq 2, size 46,
jiffies 4294942406
[ 51.100000] libertas_cs enter: if_cs_host_to_card(type 1, bytes 46):628
[ 51.100000] libertas_cs enter: if_cs_send_cmd():294
[ 51.100000] libertas_cs leave: if_cs_send_cmd():325, ret 0
[ 51.100000] libertas_cs leave: if_cs_host_to_card():644, ret 0
[ 51.100000] libertas leave: lbs_submit_command():1200
[ 51.100000] libertas leave: lbs_execute_next_command():1873
[ 51.100000] libertas thread: main-thread 111: intcounter=0
currenttxskb=00000000 dnld_sent=2
[ 51.100000] libertas_cs enter (INT): if_cs_interrupt():253
[ 51.100000] libertas enter (INT): lbs_interrupt():1457
[ 51.100000] libertas thread (INT): lbs_interrupt: intcounter=0
[ 51.100000] libertas leave (INT): lbs_interrupt():1465
[ 51.100000] libertas thread: main-thread 222 (waking up):
intcounter=1 currenttxskb=00000000 dnld_sent=2
[ 51.100000] libertas thread: main-thread 333: intcounter=1
currenttxskb=00000000 dnld_sent=2
[ 51.100000] libertas_cs enter: if_cs_get_int_status():656
[ 51.100000] libertas_cs enter: if_cs_receive_cmdres():361
[ 51.100000] libertas_cs leave: if_cs_receive_cmdres():386, ret 0,
len 46
[ 51.100000] libertas_cs leave: if_cs_get_int_status():692, ret 0,
ireg 0xd, hisregcpy 0x5
[ 51.100000] libertas thread: main-thread 444: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 51.100000] libertas thread: main-thread: cmd response ready
[ 51.100000] libertas enter: lbs_process_rx_command():488
[ 51.100000] libertas cmd: CMD_RESP: response 0x8003, seq 32771,
size 46, jiffies 4294942406
[ 51.100000] libertas: Received CMD_RESP with invalid sequence 32771
(expected 2)
[ 51.100000] libertas leave: lbs_process_rx_command():638, ret -1
[ 51.100000] libertas thread: main-thread 111: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 51.100000] libertas thread: main-thread sleeping... Conn=1 IntC=0
PS_mode=0 PS_State=0
[ 56.100000] libertas enter (INT): command_timer_fn():970
[ 56.100000] libertas: Command 3 timed out
[ 56.100000] libertas leave (INT): command_timer_fn():984
[ 56.100000] libertas thread: main-thread 222 (waking up):
intcounter=0 currenttxskb=00000000 dnld_sent=0
[ 56.100000] libertas thread: main-thread 333: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 56.100000] libertas thread: main-thread 444: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 56.100000] libertas: requeueing command 3 due to timeout (#3)
[ 56.110000] libertas enter: lbs_execute_next_command():1738
[ 56.110000] libertas host: EXEC_NEXT_CMD: sending command 0x0003
[ 56.110000] libertas enter: lbs_submit_command():1167
[ 56.110000] libertas cmd: DNLD_CMD: command 0x0003, seq 2, size 46,
jiffies 4294942907
[ 56.110000] libertas_cs enter: if_cs_host_to_card(type 1, bytes 46):628
[ 56.110000] libertas_cs enter: if_cs_send_cmd():294
[ 56.110000] libertas_cs leave: if_cs_send_cmd():325, ret 0
[ 56.110000] libertas_cs leave: if_cs_host_to_card():644, ret 0
[ 56.110000] libertas leave: lbs_submit_command():1200
[ 56.110000] libertas leave: lbs_execute_next_command():1873
[ 56.110000] libertas_cs enter (INT): if_cs_interrupt():253
[ 56.110000] libertas enter (INT): lbs_interrupt():1457
[ 56.110000] libertas thread (INT): lbs_interrupt: intcounter=0
[ 56.110000] libertas leave (INT): lbs_interrupt():1465
[ 56.110000] libertas thread: main-thread 111: intcounter=1
currenttxskb=00000000 dnld_sent=2
[ 56.110000] libertas thread: main-thread 222 (waking up):
intcounter=1 currenttxskb=00000000 dnld_sent=2
[ 56.110000] libertas thread: main-thread 333: intcounter=1
currenttxskb=00000000 dnld_sent=2
[ 56.110000] libertas_cs enter: if_cs_get_int_status():656
[ 56.110000] libertas_cs enter: if_cs_receive_cmdres():361
[ 56.110000] libertas_cs leave: if_cs_receive_cmdres():386, ret 0,
len 46
[ 56.110000] libertas_cs leave: if_cs_get_int_status():692, ret 0,
ireg 0xd, hisregcpy 0x5
[ 56.110000] libertas thread: main-thread 444: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 56.110000] libertas thread: main-thread: cmd response ready
[ 56.110000] libertas enter: lbs_process_rx_command():488
[ 56.110000] libertas cmd: CMD_RESP: response 0x8003, seq 32771,
size 46, jiffies 4294942907
[ 56.110000] libertas: Received CMD_RESP with invalid sequence 32771
(expected 2)
[ 56.110000] libertas leave: lbs_process_rx_command():638, ret -1
[ 56.110000] libertas thread: main-thread 111: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 56.110000] libertas thread: main-thread sleeping... Conn=1 IntC=0
PS_mode=0 PS_State=0
[ 61.110000] libertas enter (INT): command_timer_fn():970
[ 61.110000] libertas: Command 3 timed out
[ 61.110000] libertas leave (INT): command_timer_fn():984
[ 61.110000] libertas thread: main-thread 222 (waking up):
intcounter=0 currenttxskb=00000000 dnld_sent=0
[ 61.110000] libertas thread: main-thread 333: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 61.110000] libertas thread: main-thread 444: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 61.110000] libertas: requeueing command 3 due to timeout (#4)
[ 61.120000] libertas enter: lbs_execute_next_command():1738
[ 61.120000] libertas host: EXEC_NEXT_CMD: sending command 0x0003
[ 61.120000] libertas enter: lbs_submit_command():1167
[ 61.120000] libertas cmd: DNLD_CMD: command 0x0003, seq 2, size 46,
jiffies 4294943408
[ 61.120000] libertas_cs enter: if_cs_host_to_card(type 1, bytes 46):628
[ 61.120000] libertas_cs enter: if_cs_send_cmd():294
[ 61.120000] libertas_cs leave: if_cs_send_cmd():325, ret 0
[ 61.120000] libertas_cs leave: if_cs_host_to_card():644, ret 0
[ 61.120000] libertas leave: lbs_submit_command():1200
[ 61.120000] libertas leave: lbs_execute_next_command():1873
[ 61.120000] libertas_cs enter (INT): if_cs_interrupt():253
[ 61.120000] libertas enter (INT): lbs_interrupt():1457
[ 61.120000] libertas thread (INT): lbs_interrupt: intcounter=0
[ 61.120000] libertas leave (INT): lbs_interrupt():1465
[ 61.120000] libertas thread: main-thread 111: intcounter=1
currenttxskb=00000000 dnld_sent=2
[ 61.120000] libertas thread: main-thread 222 (waking up):
intcounter=1 currenttxskb=00000000 dnld_sent=2
[ 61.120000] libertas thread: main-thread 333: intcounter=1
currenttxskb=00000000 dnld_sent=2
[ 61.120000] libertas_cs enter: if_cs_get_int_status():656
[ 61.120000] libertas_cs enter: if_cs_receive_cmdres():361
[ 61.120000] libertas_cs leave: if_cs_receive_cmdres():386, ret 0,
len 46
[ 61.120000] libertas_cs leave: if_cs_get_int_status():692, ret 0,
ireg 0xd, hisregcpy 0x5
[ 61.120000] libertas thread: main-thread 444: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 61.120000] libertas thread: main-thread: cmd response ready
[ 61.120000] libertas enter: lbs_process_rx_command():488
[ 61.120000] libertas cmd: CMD_RESP: response 0x8003, seq 32771,
size 46, jiffies 4294943408
[ 61.120000] libertas: Received CMD_RESP with invalid sequence 32771
(expected 2)
[ 61.120000] libertas leave: lbs_process_rx_command():638, ret -1
[ 61.120000] libertas thread: main-thread 111: intcounter=0
currenttxskb=00000000 dnld_sent=0
[ 61.120000] libertas thread: main-thread sleeping... Conn=1 IntC=0
PS_mode=0 PS_State=0
<SNIP>
Any theories would be appreciated...
Dave
More information about the libertas-dev
mailing list