ath bug: currates != sc_currates!

Fri Nov 27 21:26:34 UTC 2015

Hiya,

I finally observed this bug in the wild. It's .. mildly annoying and
tricky to fix.

The ath driver has a single rate table associated with the main
hardware interface, because that's in a single mode. (ie, the NIC is
in 11a, 11bg, 11b, 11g, 11na, 11ng, etc mode.) Then associated
stations and such can negotiate a different set of rates - eg, an 11n
3x3 HT/40 AP can have stations that are non-11n (eg 11a or 11bg as
appropriate), or 1-stream HT/20, etc.) The rate control code looks at
the negotiated rates from net80211 and AND's them with what's in
sc->sc_currates.

Now, we used to have a crash in the past where the rate control code
would reference rate indexes way outside of the current table. I put
in a check (the subject of this message) which detects if the main
interface rate table has changed and if so, it just defaults to the
lowest rate and prints an error. That's worked fine so far but I never
sat down to figure out why.

So i've seen it happen in IBSS. it's very annoying. I'm sure the STA
side is somewhat the same.

What's happening is this:

* VAP is in IBSS mode, in SCAN state, looking for a peer
* upon each real channel change it'll flush the node list
* it is also learning neighbors based on beacons seen

So if you're scanning, you're fine. then this happens:

* VAP is in IBSS mode, and you hard-code the channel
* it does a SCAN, but it doesn't really change channel - it just
changes operating mode. yes, net80211 still sees it as a channel
change but for some reason it's not flushing the neighbor table each
tim
* So, it sees a new neighbor during scan, then it selects an operating
mode that isn't the same as the mode where it saw the neighbor, and it
.. well, now the node was setup with the old channel mode and the NIC
is in the new channel mode.

Here's some example debugging output. In this instance I created
wlan0, set it to channel 10:ht/20, disabled ht/40. The peer
(00:03:7f:10:42:81) is configured as an 11g interface. It eventually
gets configured as a 10:g rather than staying 10:ht/20, and that's
what's getting sc_currates happening.

Now, I don't yet know what the correct solution is.

Ideally if you change operating mode like this you'll flush out the
nodes, or at least you'll update the rate control settings. It's
tricky though because what we should do to be 100% clean w/ 11n is to
stop TX, anything in the software/hardware queues that didn't go out
needs to have the rate control recalculated, and then we start TX
again after the channel change/reset. (There's a similar requirement
for this with 20/40MHz dynamic channel width changing.) I could fix
the net80211 side to be smarter about choosing interface
configurations for IBSS (as yes, it can put the interface into ht/20
or ht/40 and still speak to an 11b/11bg IBSS node) but that just hides
the problem in ath(4).

So, grr!

-adrian

wlan0: WPA: using KEY_MGMT WPA-NONE
WPA: Set own WPA IE default - hexdump(len=24): dd 16 00 50 f2 01 01 00
00 50 f2 04 01 00 00 50 f2 00 01 00 00 50 f2 00
bsd_set_key: alg=3 addr=0x0 key_idx=0 set_tx=1 seq_len=6 key_len=16
wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x8b keyix 0
wlan0: ieee80211_crypto_setkey: AES-CCM keyix 0 flags 0x10b mac
ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16
wlan0: State: SCANNING -> ASSOCIATING
wpa_driver_bsd_associate: ssid 'CACHEBOY_IBSS_ENCRYPT' wpa ie len 24
pairwise 1 group 16 key mgmt 16
wpa_driver_bsd_set_drop_unencrypted: enabled=1
bsd_set_opt_ie: set WPA+RSN ie (len 24)
wpa_driver_bsd_associate: set PRIVACY 1
wlan0: start running, 0 vaps running
wlan0: ieee80211_start_locked: up parent ath0
ath0: ath_update_chainmasks: TX chainmask is now 0x1, RX is now 0x1
ath0: ath_init: imask=0xe0000863
wlan0: start running, 1 vaps running
wlan0: ieee80211_new_state_locked: INIT -> SCAN (nrunning 0 nscanning 0)
wlan0: ieee80211_newstate_cb: INIT -> INIT arg 0
wlan0: adhoc_newstate: INIT -> INIT (0)
wlan0: ieee80211_newstate_cb: INIT -> SCAN arg 0
wlan0: adhoc_newstate: INIT -> SCAN (0)
ath0: ath_node_alloc: c4:93:00:00:3c:c9: an 0xc1077000
wlan0: ieee80211_alloc_node 0xc1077000<c4:93:00:00:3c:c9> in station table
wlan0: node_reclaim: remove 0xc1070000<c4:93:00:00:3c:c9> from station
table, refcnt 1
ath0: ath_setslottime: chan 2457 MHz flags 0x480 long slot, 20 usec
wlan0: ieee80211_new_state_locked: SCAN -> RUN (nrunning 0 nscanning 0)
ath0: ath_node_free: c4:93:00:00:3c:c9: an 0xc1070000
ath0: ath_node_cleanup: c4:93:00:00:3c:c9: an 0xc1070000
ath0: ath_tx_node_flush: c4:93:00:00:3c:c9: flush; is_powersave=0,
stack_psq=0, tim=0, swq_depth=0, clrdmask=1, leak_count=0
ath0: ath_chan_set: 10 (2457 MHz, flags 0x480)
wlan0: ieee80211_add_neighbor: mac<00:03:7f:10:42:81>
ath0: ath_node_alloc: 00:03:7f:10:42:81: an 0xc1070000
wlan0: ieee80211_alloc_node 0xc1070000<00:03:7f:10:42:81> in station table
ath0: ath_newassoc: 00:03:7f:10:42:81: reassoc; isnew=1, is_powersave=0
wlan0: [00:03:7f:10:42:81] ath_rate_ctl_reset: size 1600 rate/tt 1 Mb
/14016 2 Mb /7464 5 Mb /3355 11 Mb /2181 12 Mb /1480 18 Mb /1124 24 Mb
/940 36 Mb /764 48 Mb /672 54 Mb /644
ath0: ath_edma_tx_drain: called
ath0: ath_stoptxdma: tx queue [9] 0x12b3000, link 0
ath0: ath_tx_stopdma: tx queue [0] 0x42724904, active=0, hwpending=0,
flags 0x00000000, link 0, holdingbf=0
ath0: ath_tx_stopdma: tx queue [1] 0x1205f00, active=0, hwpending=0,
flags 0x00000000, link 0, holdingbf=0
ath0: ath_tx_stopdma: tx queue [2] 0x251041c0, active=0, hwpending=0,
flags 0x00000000, link 0, holdingbf=0
ath0: ath_tx_stopdma: tx queue [3] 0x10f8700, active=0, hwpending=0,
flags 0x00000000, link 0, holdingbf=0
ath0: ath_tx_stopdma: tx queue [8] 0x106c6a5c, active=0, hwpending=0,
flags 0x00000000, link 0, holdingbf=0
ath0: ath_edma_tx_drain: called
ath0: ath_stoptxdma: tx queue [9] 0x12b3000, link 0
ath0: ath_tx_stopdma: tx queue [0] 0x42724904, active=0, hwpending=0,
flags 0x00000000, link 0, holdingbf=0
ath0: ath_tx_stopdma: tx queue [1] 0x1205f00, active=0, hwpending=0,
flags 0x00000000, link 0, holdingbf=0
ath0: ath_tx_stopdma: tx queue [2] 0x251041c0, active=0, hwpending=0,
flags 0x00000000, link 0, holdingbf=0
ath0: ath_tx_stopdma: tx queue [3] 0x10f8700, active=0, hwpending=0,
flags 0x00000000, link 0, holdingbf=0
ath0: ath_tx_stopdma: tx queue [8] 0x106c6a5c, active=0, hwpending=0,
flags 0x00000000, link 0, holdingbf=0
ath0: ath_update_chainmasks: TX chainmask is now 0x1, RX is now 0x1
ath0: ath_txq_update: Q1 qflags 0xf aifs 2 cwmin 15 cwmax 1023 burstTime 2048
ath0: ath_txq_update: Q0 qflags 0xf aifs 7 cwmin 15 cwmax 1023 burstTime 0
ath0: ath_txq_update: Q2 qflags 0xf aifs 2 cwmin 7 cwmax 15 burstTime 3008
ath0: ath_txq_update: Q3 qflags 0xf aifs 2 cwmin 3 cwmax 7 burstTime 1504
wlan0: ieee80211_newstate_cb: SCAN -> RUN arg -1
wlan0: adhoc_newstate: SCAN -> RUN (-1)
ath0: ath_beacon_alloc: bf_m=0x82603500, bf_node=0xc107e000
ath0: ath_node_free: c4:93:00:00:3c:c9: an 0xc107e000
ath0: ath_node_cleanup: c4:93:00:00:3c:c9: an 0xc107e000
ath0: ath_tx_node_flush: c4:93:00:00:3c:c9: flush; is_powersave=0,
stack_psq=0, tim=0, swq_depth=0, clrdmask=1, leak_count=0
ath0: ath_txq_update: Q1 qflags 0xf aifs 2 cwmin 15 cwmax 1023 burstTime 2048
ath0: ath_txq_update: Q0 qflags 0xf aifs 7 cwmin 15 cwmax 1023 burstTime 0
ath0: ath_txq_update: Q2 qflags 0xf aifs 2 cwmin 7 cwmax 15 burstTime 3008
ath0: ath_txq_update: Q3 qflags 0xf aifs 2 cwmin 3 cwmax 7 burstTime 1504
wlan0: ieee80211_ibss_merge: new bssid 16:cb:5a:b2:52:4d: short
preamble, long slot time
wlan0: node_reclaim: remove 0xc1077000<c4:93:00:00:3c:c9> from station
table, refcnt 1
ath0: ath_setslottime: chan 2457 MHz flags 0x480 long slot, 20 usec
wlan0: ieee80211_new_state_locked: RUN -> RUN (nrunning 0 nscanning 0)

wlan0: ieee80211_ref_node (ieee80211_send_proberesp:2727)
0xc1070000<00:03:7f:10:42:81> refcnt 4
wlan0: ieee80211_ref_node (ieee80211_send_proberesp:2727)
0xc1070000<00:03:7f:10:42:81> refcnt 5
wlan0: [00:03:7f:10:42:81] ath_rate_tx_complete: size 250 (158 bytes)
FAIL rate/short/long 1 Mb /0/5 nframes/nbad [1/1]
wlan0: [00:03:7f:10:42:81] ath_rate_tx_complete: size 250 (158 bytes)
FAIL rate/short/long 1 Mb /0/5 nframes/nbad [1/1]
ping 192.168.169.wlan0: ieee80211_ref_node
(ieee80211_send_proberesp:2727) 0xc1070000<00:03:7f:10:42:81> refcnt 4
1wlan0: [00:03:7f:10:42:81] ath_rate_tx_complete: size 250 (158 bytes)
FAIL rate/short/long 1 Mb /0/5 nframes/nbad [1/1]
# ping 192.168.169.10
PING 192.168.169.10 (192.168.169.10): 56 data bytes
ath0: ath_rate_findrate: currates != sc_currates!
wlan0: [00:03:7f:10:42:81] ath_rate_tx_complete: size 250 (138 bytes)
OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
64 bytes from 192.168.169.10: icmp_seq=0 ttl=64 time=25.827 ms
ath0: ath_rate_findrate: currates != sc_currates!
wlan0: [00:03:7f:10:42:81] ath_rate_tx_complete: size 250 (138 bytes)
OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
64 bytes from 192.168.169.10: icmp_seq=1 ttl=64 time=14.466 ms
ath0: ath_rate_findrate: currates != sc_currates!
wlan0: [00:03:7f:10:42:81] ath_rate_tx_complete: size 250 (138 bytes)
OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
64 bytes from 192.168.169.10: icmp_seq=2 ttl=64 time=14.847 ms
ath0: ath_rate_findrate: currates != sc_currates!
wlan0: [00:03:7f:10:42:81] ath_rate_tx_complete: size 250 (138 bytes)
OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
64 bytes from 192.168.169.10: icmp_seq=3 ttl=64 time=14.893 ms
ath0: ath_rate_findrate: currates != sc_currates!
wlan0: [00:03:7f:10:42:81] ath_rate_tx_complete: size 250 (138 bytes)
OK rate/short/long 1 Mb /0/1 nframes/nbad [1/0]
64 bytes from 192.168.169.10: icmp_seq=4 ttl=64 time=15.846 ms