Date: Fri, 27 Nov 2015 13:26:33 -0800 From: Adrian Chadd <adrian@freebsd.org> To: "freebsd-wireless@freebsd.org" <freebsd-wireless@freebsd.org> Subject: ath bug: currates != sc_currates! Message-ID: <CAJ-VmomT_JKeP8btzy%2B_9auT_XcjK0XKFR7bEpmWL1giP1Aezg@mail.gmail.com>
next in thread | raw e-mail | index | archive | help
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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?CAJ-VmomT_JKeP8btzy%2B_9auT_XcjK0XKFR7bEpmWL1giP1Aezg>