Bug 200559

Summary:	[ath] ath0: ath_rate_findrate: currates != sc_currates!
Product:	Base System	Reporter:	Gavin Atkinson <gavin>
Component:	wireless	Assignee:	freebsd-wireless (Nobody) <wireless>
Status:	New ---
Severity:	Affects Only Me
Priority:	---
Version:	CURRENT
Hardware:	Any
OS:	Any

Description Gavin Atkinson freebsd_committer

2015-06-01 00:01:45 UTC

I have a Lenovo Flex 10, which has an Atheros AR9565 bgn wifi card.  It is running head r283671.  Access point is an Aruba AP135.
I am seeing the message "ath0: ath_rate_findrate: currates != sc_currates!" printed on every packet transmitted.  However, this does not happen every tme I associate, I'd guess maybe 25% of the associations work fine.  Sometimes when I negotiate, I'll get the messages right from the start (i.e. while the device is DHCPing).  If that happens, the messages will continue from then on.  However, if I don't see the messages at the start, I won't see them at all for the duration of the association.  When the messages are not being printed the device works well, when the messages are being printed then data transfer speeds are poor.

I've included "ifconfig -v wlan0 list sta", "ifconfig -v wlan0" and /var/log/messages from having "wlandebug +rate" enabled in both the working and non-working case.  Between obtaining these two, all I did was "ifconfig wlan0 destroy; ifconfig wlan0 create wlandev ath0" - I did not reboot between them.  

pciconf -l:

ath0@pci0:1:0:0:	class=0x028000 card=0x302617aa chip=0x0036168c rev=0x01 hdr=0x00

dmesg:

ath0: <Qualcomm Atheros AR9565> mem 0xd0400000-0xd047ffff irq 16 at device 0.0 on pci1
ath0: WB335 2-ANT card detected
ar9300_attach: calling ar9300_hw_attach
ar9300_hw_attach: calling ar9300_eeprom_attach
ar9300_flash_map: unimplemented for now
Restoring Cal data from DRAM
Restoring Cal data from EEPROM
Restoring Cal data from Flash
Restoring Cal data from Flash
Restoring Cal data from OTP
ar9300_hw_attach: ar9300_eeprom_attach returned 0
ath0: [HT] enabling HT modes
ath0: [HT] enabling short-GI in 20MHz mode
ath0: [HT] 1 stream STBC receive enabled
ath0: [HT] 1 RX streams; 1 TX streams
ath0: AR9565 mac 704.1 RF5110 phy 0.0
ath0: 2GHz radio: 0x0000; 5GHz radio: 0x0000

While having issues:

root@flex10:~ # ifconfig -v wlan0 list sta
ADDR               AID CHAN RATE RSSI IDLE  TXSEQ  RXSEQ CAPS FLAG   
6c:f3:7f:63:e5:62    2    1  36M 12.5    0     39   8672 EPS  AQES+   SSID<sdkfjw> RATES<B2,B4,11,12,18,22,24,36> DSPARMS<1> ERP<0x0> XRATES<48,72,96,108> RSN<v1 mc:AES-CCMP uc:AES-CCMP km:8021X-PSK> WME<qosinfo 0x80 BE[aifsn 3 cwmin 4 cwmax 10 txop 0] BK[aifsn 7 cwmin 4 cwmax 10 txop 0] VO[aifsn 2 cwmin 3 cwmax 4 txop 94] VI[aifsn 2 cwmin 2 cwmax 3 txop 47]>

root@flex10:~ # ifconfig -v wlan0
wlan0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
	ether 28:e3:47:89:a8:11
	inet 192.168.1.90 netmask 0xffffff00 broadcast 192.168.1.255 
	nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
	media: IEEE 802.11 Wireless Ethernet OFDM/36Mbps mode 11ng
	status: associated
	ssid sdkfjw channel 1 (2412 MHz 11g ht/20) bssid 6c:f3:7f:63:e5:62
	regdomain 101 country DEBUG indoor ecm authmode WPA2/802.11i -wps
	-tsn privacy ON deftxkey UNDEF
	AES-CCM 2:128-bit powersavemode OFF powersavesleep 100 txpower 20
	txpowmax 50.0 -dotd rtsthreshold 2346 fragthreshold 2346 bmiss 7
	11a     ucast NONE    mgmt  6 Mb/s mcast  6 Mb/s maxretry 6
	11b     ucast NONE    mgmt  1 Mb/s mcast  1 Mb/s maxretry 6
	11g     ucast NONE    mgmt  1 Mb/s mcast  1 Mb/s maxretry 6
	turboA  ucast NONE    mgmt  6 Mb/s mcast  6 Mb/s maxretry 6
	turboG  ucast NONE    mgmt  1 Mb/s mcast  1 Mb/s maxretry 6
	sturbo  ucast NONE    mgmt  6 Mb/s mcast  6 Mb/s maxretry 6
	11na    ucast NONE    mgmt 12 MCS  mcast 12 MCS  maxretry 6
	11ng    ucast NONE    mgmt  2 MCS  mcast  2 MCS  maxretry 6
	half    ucast NONE    mgmt  3 Mb/s mcast  3 Mb/s maxretry 6
	quarter ucast NONE    mgmt  1 Mb/s mcast  1 Mb/s maxretry 6
	scanvalid 60 -bgscan bgscanintvl 300 bgscanidle 250
	roam:11a     rssi    7dBm rate 12 Mb/s
	roam:11b     rssi    7dBm rate  1 Mb/s
	roam:11g     rssi    7dBm rate  5 Mb/s
	roam:turboA  rssi    7dBm rate 12 Mb/s
	roam:turboG  rssi    7dBm rate 12 Mb/s
	roam:sturbo  rssi    7dBm rate 12 Mb/s
	roam:11na    rssi    7dBm  MCS  1    
	roam:11ng    rssi    7dBm  MCS  1    
	roam:half    rssi    7dBm rate  6 Mb/s
	roam:quarter rssi    7dBm rate  3 Mb/s
	-pureg protmode CTS ht htcompat ampdu ampdulimit 64k ampdudensity 16
	amsdu shortgi htprotmode RTSCTS -puren -smps -rifs wme burst -dwds
	roaming MANUAL bintval 100
	AC_BE cwmin  4 cwmax 10 aifs  3 txopLimit   0 -acm ack
	      cwmin  4 cwmax 10 aifs  3 txopLimit   0 -acm
	AC_BK cwmin  4 cwmax 10 aifs  7 txopLimit   0 -acm ack
	      cwmin  4 cwmax 10 aifs  7 txopLimit   0 -acm
	AC_VI cwmin  3 cwmax  4 aifs  2 txopLimit  94 -acm ack
	      cwmin  3 cwmax  4 aifs  2 txopLimit  94 -acm
	AC_VO cwmin  2 cwmax  3 aifs  2 txopLimit  47 -acm ack
	      cwmin  2 cwmax  3 aifs  2 txopLimit  47 -acm
	groups: wlan 

root@flex10:~ # wlandebug +rate
net.wlan.0.debug: 0x0 => 0x20<rate>

Jun  1 00:05:37 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (190 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:37 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (158 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:39 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!
Jun  1 00:05:39 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (158 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:39 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!
Jun  1 00:05:39 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:40 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!
Jun  1 00:05:40 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:41 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!
Jun  1 00:05:41 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:41 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!
Jun  1 00:05:41 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:41 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!
Jun  1 00:05:41 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:41 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!
Jun  1 00:05:41 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:41 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!
Jun  1 00:05:41 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:42 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!
Jun  1 00:05:42 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:42 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!
Jun  1 00:05:42 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:42 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!
Jun  1 00:05:42 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:43 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!
Jun  1 00:05:43 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (118 bytes) OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
Jun  1 00:05:43 flex10 kernel: ath0: ath_rate_findrate: currates != sc_currates!



When working file:

gavin@flex10:~ % ifconfig -v wlan0 list sta
ADDR               AID CHAN RATE RSSI IDLE  TXSEQ  RXSEQ CAPS FLAG   
6c:f3:7f:63:e5:62    2    1  65M 21.5    0     44   3776 EPS  AQEHTRS SSID<sdkfjw> RATES<B2,B4,11,22,12,18,24,36> DSPARMS<1> TIM<050400010000> ERP<0x0> XRATES<48,72,96,108> RSN<v1 mc:AES-CCMP uc:AES-CCMP km:8021X-PSK> HTCAP<cap 0x19ed param 0x1f mcsset[0-23] extcap 0x0 txbf 0x0 antenna 0x0> HTINFO<ctl 1, 0,1b,0,0 basicmcs[]> WME<qosinfo 0x80 BE[aifsn 3 cwmin 4 cwmax 10 txop 0] BK[aifsn 7 cwmin 4 cwmax 10 txop 0] VO[aifsn 2 cwmin 3 cwmax 4 txop 94] VI[aifsn 2 cwmin 2 cwmax 3 txop 47]> VEN<dd07000b8601040813>

gavin@flex10:~ % ifconfig -v wlan0
wlan0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
	ether 28:e3:47:89:a8:11
	inet 192.168.1.90 netmask 0xffffff00 broadcast 192.168.1.255 
	nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
	media: IEEE 802.11 Wireless Ethernet MCS mode 11ng
	status: associated
	ssid sdkfjw channel 1 (2412 MHz 11g ht/20) bssid 6c:f3:7f:63:e5:62
	regdomain 101 country DEBUG indoor ecm authmode WPA2/802.11i -wps
	-tsn privacy ON deftxkey UNDEF
	AES-CCM 2:128-bit powersavemode OFF powersavesleep 100 txpower 20
	txpowmax 50.0 -dotd rtsthreshold 2346 fragthreshold 2346 bmiss 7
	11a     ucast NONE    mgmt  6 Mb/s mcast  6 Mb/s maxretry 6
	11b     ucast NONE    mgmt  1 Mb/s mcast  1 Mb/s maxretry 6
	11g     ucast NONE    mgmt  1 Mb/s mcast  1 Mb/s maxretry 6
	turboA  ucast NONE    mgmt  6 Mb/s mcast  6 Mb/s maxretry 6
	turboG  ucast NONE    mgmt  1 Mb/s mcast  1 Mb/s maxretry 6
	sturbo  ucast NONE    mgmt  6 Mb/s mcast  6 Mb/s maxretry 6
	11na    ucast NONE    mgmt 12 MCS  mcast 12 MCS  maxretry 6
	11ng    ucast NONE    mgmt  2 MCS  mcast  2 MCS  maxretry 6
	half    ucast NONE    mgmt  3 Mb/s mcast  3 Mb/s maxretry 6
	quarter ucast NONE    mgmt  1 Mb/s mcast  1 Mb/s maxretry 6
	scanvalid 60 -bgscan bgscanintvl 300 bgscanidle 250
	roam:11a     rssi    7dBm rate 12 Mb/s
	roam:11b     rssi    7dBm rate  1 Mb/s
	roam:11g     rssi    7dBm rate  5 Mb/s
	roam:turboA  rssi    7dBm rate 12 Mb/s
	roam:turboG  rssi    7dBm rate 12 Mb/s
	roam:sturbo  rssi    7dBm rate 12 Mb/s
	roam:11na    rssi    7dBm  MCS  1    
	roam:11ng    rssi    7dBm  MCS  1    
	roam:half    rssi    7dBm rate  6 Mb/s
	roam:quarter rssi    7dBm rate  3 Mb/s
	-pureg protmode CTS ht htcompat ampdu ampdulimit 64k ampdudensity 16
	amsdu shortgi htprotmode RTSCTS -puren -smps -rifs wme burst -dwds
	roaming MANUAL bintval 100
	AC_BE cwmin  4 cwmax 10 aifs  3 txopLimit   0 -acm ack
	      cwmin  4 cwmax 10 aifs  3 txopLimit   0 -acm
	AC_BK cwmin  4 cwmax 10 aifs  7 txopLimit   0 -acm ack
	      cwmin  4 cwmax 10 aifs  7 txopLimit   0 -acm
	AC_VI cwmin  3 cwmax  4 aifs  2 txopLimit  94 -acm ack
	      cwmin  3 cwmax  4 aifs  2 txopLimit  94 -acm
	AC_VO cwmin  2 cwmax  3 aifs  2 txopLimit  47 -acm ack
	      cwmin  2 cwmax  3 aifs  2 txopLimit  47 -acm
	groups: wlan 

wlandebug +rate:

Jun  1 00:00:43 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (190 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:43 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (158 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:43 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (82 bytes) OK rate/short/long 7 MCS/1/1 nframes/nbad [1/0]
Jun  1 00:00:51 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_findrate: min_switch 2147408540 > ticks_since_switch 2147400921..
Jun  1 00:00:51 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:51 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:52 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:52 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] att 505 sample_tt 444 size 250 sample rate 6 MCS current rate 7 MCS
Jun  1 00:00:52 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 6 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:52 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] update_stats: size 250 OK sample rate 6 MCS tries (0/1) tt 440 avg_tt (514/440) nfrm 1 nbad 0
Jun  1 00:00:52 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:52 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:53 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_findrate: min_switch 2147409800 > ticks_since_switch 2147409540..
Jun  1 00:00:53 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:53 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:53 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (158 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:53 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (158 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:54 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_findrate: min_switch 2147411099 > ticks_since_switch 2147410800..
Jun  1 00:00:54 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:54 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:54 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:54 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:55 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:55 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:55 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_findrate: min_switch 2147412123 > ticks_since_switch 2147412099..
Jun  1 00:00:55 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:55 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:55 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:55 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:55 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:56 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:56 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (142 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]
Jun  1 00:00:56 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_findrate: min_switch 2147413227 > ticks_since_switch 2147413123..
Jun  1 00:00:56 flex10 kernel: wlan0: [6c:f3:7f:63:e5:62] ath_rate_tx_complete: size 250 (158 bytes) OK rate/short/long 7 MCS/0/1 nframes/nbad [1/0]

Thanks,

Gavin