kern/183259: [iwn] [4965] transmit seems to fail after a while

adrian chadd adrian at FreeBSD.org
Thu Oct 24 06:00:00 UTC 2013


>Number:         183259
>Category:       kern
>Synopsis:       [iwn] [4965] transmit seems to fail after a while
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    freebsd-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Thu Oct 24 06:00:00 UTC 2013
>Closed-Date:
>Last-Modified:
>Originator:     adrian chadd
>Release:        -HEAD
>Organization:
>Environment:
>Description:
Transmit seems to fail after a while.

Here's the output of tx_done whilst transmit is failing:

Oct 23 15:46:26 lucy kernel: iwn_tx_data: qid 0 idx 180 len 52 nsegs 2
Oct 23 15:46:26 lucy kernel: iwn4965_tx_done: qid 0 idx 180 retries 0 nkill 0 rate 8000 duration 0 status 8b

Oct 23 15:46:27 lucy kernel: iwn_tx_data: qid 0 idx 181 len 52 nsegs 2
Oct 23 15:46:27 lucy kernel: iwn4965_tx_done: qid 0 idx 181 retries 0 nkill 0 rate 8000 duration 0 status 8b

Oct 23 15:46:28 lucy kernel: iwn_tx_data: qid 0 idx 182 len 52 nsegs 2
Oct 23 15:46:28 lucy kernel: iwn4965_tx_done: qid 0 idx 182 retries 0 nkill 0 rate 8000 duration 0 status 8b

Oct 23 15:46:29 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] AMRR: current rate 15, txcnt=11, retrycnt=0

. note that AMRR thinks things are A-OK.

Oct 23 15:46:29 lucy kernel: iwn_tx_data: qid 0 idx 183 len 52 nsegs 2
Oct 23 15:46:29 lucy kernel: iwn4965_tx_done: qid 0 idx 183 retries 0 nkill 0 rate 8000 duration 0 status 8b
Oct 23 15:46:30 lucy kernel: iwn_tx_data: qid 0 idx 184 len 52 nsegs 2
Oct 23 15:46:30 lucy kernel: iwn4965_tx_done: qid 0 idx 184 retries 0 nkill 0 rate 8000 duration 0 status 8b
Oct 23 15:46:31 lucy kernel: iwn_tx_data: qid 0 idx 185 len 52 nsegs 2
Oct 23 15:46:31 lucy kernel: iwn4965_tx_done: qid 0 idx 185 retries 0 nkill 0 rate 8000 duration 0 status 8b
Oct 23 15:46:32 lucy kernel: iwn_tx_data: qid 0 idx 186 len 52 nsegs 2
Oct 23 15:46:32 lucy kernel: iwn4965_tx_done: qid 0 idx 186 retries 0 nkill 0 rate 8000 duration 0 status 8b

Oct 23 15:46:33 lucy kernel: iwn_tx_data: qid 0 idx 187 len 52 nsegs 2
Oct 23 15:46:33 lucy kernel: iwn4965_tx_done: qid 0 idx 187 retries 0 nkill 0 rate 8000 duration 0 status 8b

Oct 23 15:46:34 lucy kernel: iwn_tx_data: qid 0 idx 188 len 52 nsegs 2
Oct 23 15:46:34 lucy kernel: iwn4965_tx_done: qid 0 idx 188 retries 0 nkill 0 rate 8000 duration 0 status 8b
Oct 23 15:46:38 lucy kernel: iwn_tx_data: qid 0 idx 189 len 52 nsegs 2
Oct 23 15:46:38 lucy kernel: iwn4965_tx_done: qid 0 idx 189 retries 0 nkill 0 rate 8000 duration 0 status 8b
Oct 23 15:46:39 lucy kernel: iwn_tx_data: qid 0 idx 190 len 52 nsegs 2
Oct 23 15:46:39 lucy kernel: iwn4965_tx_done: qid 0 idx 190 retries 0 nkill 0 rate 8000 duration 0 status 8b

Oct 23 15:46:40 lucy kernel: iwn_tx_data: qid 0 idx 191 len 52 nsegs 2
Oct 23 15:46:40 lucy kernel: iwn4965_tx_done: qid 0 idx 191 retries 0 nkill 0 rate 8000 duration 0 status 8b

Oct 23 15:46:41 lucy kernel: iwn_tx_data: qid 0 idx 192 len 52 nsegs 2
Oct 23 15:46:41 lucy kernel: iwn4965_tx_done: qid 0 idx 192 retries 0 nkill 0 rate 8000 duration 0 status 8b

Oct 23 15:46:42 lucy kernel: iwn_tx_data: qid 0 idx 193 len 52 nsegs 2
Oct 23 15:46:42 lucy kernel: iwn4965_tx_done: qid 0 idx 193 retries 0 nkill 0 rate 8000 duration 0 status 8b
Oct 23 15:46:43 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] AMRR: current rate 15, txcnt=11, retrycnt=0
Oct 23 15:46:43 lucy kernel: iwn_tx_data: qid 0 idx 194 len 52 nsegs 2
Oct 23 15:46:43 lucy kernel: iwn4965_tx_done: qid 0 idx 194 retries 0 nkill 0 rate 8000 duration 0 status 8b
Oct 23 15:46:44 lucy kernel: iwn_tx_data: qid 0 idx 195 len 52 nsegs 2
Oct 23 15:46:44 lucy kernel: iwn4965_tx_done: qid 0 idx 195 retries 0 nkill 0 rate 8000 duration 0 status 8b
Oct 23 15:46:46 lucy kernel: iwn_tx_data: qid 0 idx 196 len 52 nsegs 2
Oct 23 15:46:46 lucy kernel: iwn4965_tx_done: qid 0 idx 196 retries 0 nkill 0 rate 8000 duration 0 status 8b
Oct 23 15:46:46 lucy kernel: iwn_tx_data: qid 0 idx 197 len 52 nsegs 2
Oct 23 15:46:46 lucy kernel: iwn4965_tx_done: qid 0 idx 197 retries 0 nkill 0 rate 8000 duration 0 status 8b

Oct 23 15:46:47 lucy kernel: iwn_tx_data: qid 0 idx 198 len 52 nsegs 2
Oct 23 15:46:47 lucy kernel: iwn4965_tx_done: qid 0 idx 198 retries 0 nkill 0 rate 8000 duration 0 status 8b
Oct 23 15:46:48 lucy kernel: iwn_tx_data: qid 0 idx 199 len 52 nsegs 2
Oct 23 15:46:48 lucy kernel: iwn4965_tx_done: qid 0 idx 199 retries 0 nkill 0 rate 8000 duration 0 status 8b
Oct 23 15:46:49 lucy kernel: iwn_tx_data: qid 0 idx 200 len 52 nsegs 2
Oct 23 15:46:49 lucy kernel: iwn4965_tx_done: qid 0 idx 200 retries 0 nkill 0 rate 8000 duration 0 status 8b
^C
adrian at lucy:~/work/freebsd/ath/head/src/sys/modules]> tail -f /var/log/all.log
Oct 23 15:49:00 lucy kernel: wlan0: [00:1f:3b:27:ae:88] amrr_node_init: non-11n node
Oct 23 15:49:00 lucy kernel: wlan0: [00:1f:3b:27:ae:88] AMRR: nrates=0, initial rate 0
Oct 23 15:49:00 lucy kernel: iwn4965_tx_done: qid 3 idx 9 retries 0 nkill 0 rate 420a duration 746 status 3201
Oct 23 15:49:00 lucy kernel: wlan0: link state changed to DOWN
Oct 23 15:49:00 lucy dhclient[2501]: My address (192.168.1.11) was deleted, dhclient exiting
Oct 23 15:49:00 lucy kernel: Oct 23 15:49:00 lucy dhclient[2501]: My address (192.168.1.11) was deleted, dhclient exiting
Oct 23 15:49:00 lucy dhclient[2461]: connection closed
Oct 23 15:49:00 lucy kernel: Oct 23 15:49:00 lucy dhclient[2461]: connection closed
Oct 23 15:49:00 lucy dhclient[2461]: exiting.
Oct 23 15:49:00 lucy kernel: Oct 23 15:49:00 lucy dhclient[2461]: exiting.
Oct 23 15:49:03 lucy kernel: temperature 318K/45C


. and here's where I re-started wpa_supplicant. Things work fine now.

Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 1 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 6 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 11 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 7 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 13 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 52 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 56 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 60 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 64 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 36 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 40 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 44 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 48 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 2 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 3 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 4 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 5 status 1
Oct 23 15:49:03 lucy kernel: iwn_notif_intr: scanning channel 8 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 9 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 10 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 12 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 149 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 153 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 157 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 161 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 100 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 104 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 108 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 112 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 116 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 120 status 1
Oct 23 15:49:04 lucy kernel: iwn_notif_intr: scanning channel 124 status 1
Oct 23 15:49:04 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] amrr_node_init: non-11n node
Oct 23 15:49:04 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] AMRR: nrates=0, initial rate 0
Oct 23 15:49:04 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] amrr_node_init: 11n node
Oct 23 15:49:04 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] AMRR: nrates=16, initial rate 128
Oct 23 15:49:04 lucy kernel: iwn_tx_data_raw: qid 3 idx 0 len 6 nsegs 1
Oct 23 15:49:04 lucy kernel: iwn4965_tx_done: qid 3 idx 0 retries 0 nkill 0 rate 420a duration 778 status 3201
Oct 23 15:49:04 lucy kernel: iwn_tx_data_raw: qid 3 idx 1 len 93 nsegs 1
Oct 23 15:49:04 lucy kernel: iwn4965_tx_done: qid 3 idx 1 retries 0 nkill 0 rate 420a duration 1474 status 3201
Oct 23 15:49:04 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] amrr_node_init: 11n node
Oct 23 15:49:04 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] AMRR: nrates=16, initial rate 128
Oct 23 15:49:04 lucy kernel: wlan0: link state changed to UP
Oct 23 15:49:04 lucy kernel: iwn_tx_data_raw: qid 3 idx 2 len 9 nsegs 1
Oct 23 15:49:04 lucy kernel: temperature 319K/46C
Oct 23 15:49:04 lucy kernel: iwn4965_tx_done: qid 3 idx 2 retries 0 nkill 0 rate 420a duration 802 status 3201
Oct 23 15:49:04 lucy kernel: iwn_tx_data: qid 3 idx 3 len 129 nsegs 2
Oct 23 15:49:04 lucy kernel: iwn4965_tx_done: qid 3 idx 3 retries 0 nkill 0 rate 4103 duration 138 status 3201
Oct 23 15:49:04 lucy kernel: iwn_tx_data: qid 3 idx 4 len 107 nsegs 2
Oct 23 15:49:04 lucy kernel: iwn4965_tx_done: qid 3 idx 4 retries 0 nkill 0 rate 4103 duration 130 status 3201
Oct 23 15:49:06 lucy kernel: iwn_tx_data: qid 0 idx 0 len 52 nsegs 2
Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 0 idx 0 retries 0 nkill 0 rate 4103 duration 114 status 201
Oct 23 15:49:06 lucy kernel: iwn_tx_data_raw: qid 3 idx 5 len 9 nsegs 1
Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 3 idx 5 retries 0 nkill 0 rate 420a duration 802 status 3201
Oct 23 15:49:06 lucy kernel: iwn_tx_data: qid 0 idx 1 len 108 nsegs 1
Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 0 idx 1 retries 0 nkill 0 rate 4103 duration 130 status 201
Oct 23 15:49:06 lucy kernel: iwn_tx_data: qid 0 idx 2 len 108 nsegs 1
Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 0 idx 2 retries 0 nkill 0 rate 4103 duration 130 status 201
Oct 23 15:49:06 lucy kernel: iwn_tx_data: qid 0 idx 3 len 108 nsegs 1
Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 0 idx 3 retries 0 nkill 0 rate 4103 duration 130 status 201
Oct 23 15:49:06 lucy kernel: iwn_tx_data: qid 0 idx 4 len 108 nsegs 1
Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 0 idx 4 retries 0 nkill 0 rate 4103 duration 130 status 201
Oct 23 15:49:06 lucy kernel: iwn_tx_data: qid 0 idx 5 len 108 nsegs 1
Oct 23 15:49:06 lucy kernel: iwn4965_tx_done: qid 0 idx 5 retries 0 nkill 0 rate 4103 duration 130 status 201
Oct 23 15:49:07 lucy kernel: iwn_tx_data: qid 0 idx 6 len 108 nsegs 1
Oct 23 15:49:07 lucy kernel: iwn4965_tx_done: qid 0 idx 6 retries 0 nkill 0 rate 4103 duration 130 status 201
Oct 23 15:49:07 lucy kernel: wlan0: [f8:e4:fb:1a:49:79] AMRR: current rate 15, txcnt=11, retrycnt=0
Oct 23 15:49:07 lucy kernel: iwn_tx_data: qid 0 idx 7 len 108 nsegs 1
Oct 23 15:49:07 lucy kernel: iwn4965_tx_done: qid 0 idx 7 retries 0 nkill 0 rate 4103 duration 130 status 201
Oct 23 15:49:07 lucy kernel: iwn_tx_data: qid 0 idx 8 len 108 nsegs 1
Oct 23 15:49:07 lucy kernel: iwn4965_tx_done: qid 0 idx 8 retries 0 nkill 0 rate 4103 duration 130 status 201
Oct 23 15:49:07 lucy kernel: iwn_tx_data: qid 0 idx 9 len 108 nsegs 1
Oct 23 15:49:07 lucy kernel: iwn4965_tx_done: qid 0 idx 9 retries 0 nkill 0 rate 4103 duration 130 status 201
Oct 23 15:49:11 lucy kernel: iwn_tx_data: qid 0 idx 10 len 52 nsegs 1
Oct 23 15:49:11 lucy kernel: iwn4965_tx_done: qid 0 idx 10 retries 0 nkill 0 rate 4103 duration 114 status 201
Oct 23 15:49:23 lucy kernel: temperature 322K/49C

>How-To-Repeat:
not sure yet. I just left things idle for a while.

* Intel 4965, -HEAD iwn/net80211 running on stable/9
* connecting to an 11n 2-stream network, speaking WPA/WPA2

I'm not yet sure what those particular flags and status mean; but the rate looks suspicious. It's likely I should add some transmit setup logic to see if I'm initialising things wrong.

Also, I think I'm initialising the MRR stuff wrong. When I updated the rate control code to return 11n rates instead of legacy only (and having the driver 'fake' 11n rates in return) the MRR stuff still uses ridx; and ridx always does a legacy rate table lookup. So, look at how that's done in iwn_tx_data() (and iwn_tx_data_raw()) in case I've screwed it up somehow.

>Fix:


>Release-Note:
>Audit-Trail:
>Unformatted:


More information about the freebsd-bugs mailing list