<div dir="ltr"><div><div>Hello!<br><br></div>I have a question that hopefully you can help me with. We run wpa_supplicant 1.x and Linux 2.6.39 in a somewhat dense Cisco-based WLAN. There are lots of clients and they spend a lot of time roaming between access points. Intermittently, the client gets into a state where wpa_supplicant has received an RSSI_LOW event, and has selected a BSSID that has better coverage. The client gets to <a href="http://lxr.free-electrons.com/ident?i=ieee80211_send_probe_req">ieee80211_send_probe_req</a>() [1], and the BSSID that it has selected fails to respond to broadcast probes.:<br>
<br>Dec 11 01:54:36 wpa_supplicant[477]: wlan0: Event SIGNAL_CHANGE (28) received<br>Dec 11 01:54:36 wpa_supplicant[477]: nl80211: Event message available<br>Dec 11 01:54:36 wpa_supplicant[477]: nl80211: Connection quality monitor event: RSSI low<br>
Dec 11 01:54:36 wpa_supplicant[477]: nl80211: Signal: -79 dBm txrate: 48000<br>Dec 11 01:54:36 wpa_supplicant[477]: nl80211: Noise: -101 dBm<br>Dec 11 01:54:36 wpa_supplicant[477]: wlan0: Event SIGNAL_CHANGE (28) received<br>
Dec 11 01:54:36 kernel: wlan0: direct probe to c (try 2/3)<br>Dec 11 01:54:37 kernel: wlan0: direct probe to dead:beef (try 3/3)<br>Dec 11 01:54:37 wpa_supplicant[477]: nl80211: Event message available<br>Dec 11 01:54:37 kernel: wlan0: direct probe to dead:beef timed out<br>
Dec 11 01:54:37 wpa_supplicant[477]: nl80211: MLME event 37; timeout with dead:beef<br><br>Dec 11 01:54:37 wpa_supplicant[477]: wlan0: Event AUTH_TIMED_OUT (14) received<br>Dec 11 01:54:37 wpa_supplicant[477]: wlan0: SME: Authentication timed out<br>
Dec 11 01:54:37 wpa_supplicant[477]: wlan0: Setting scan request: 5 sec 0 usec<br>Dec 11 01:54:37 wpa_supplicant[477]: wlan0: State: AUTHENTICATING -> DISCONNECTED at 1355190877.307<br><br>Dec 11 01:54:37 wpa_supplicant[477]: wpa_driver_nl80211_set_operstate: operstate 1->0 (DORMANT)<br>
Dec 11 01:54:37 wpa_supplicant[477]: netlink: Operstate: linkmode=-1, operstate=5<br>Dec 11 01:54:37 wpa_supplicant[477]: EAPOL: External notification - portEnabled=0<br><br>Dec 11 01:54:37 wpa_supplicant[477]: EAPOL: SUPP_PAE entering state DISCONNECTED<br>
Dec 11 01:54:37 wpa_supplicant[477]: EAPOL: Supplicant port status: Unauthorized<br>Dec 11 01:54:37 wpa_supplicant[477]: EAPOL: SUPP_BE entering state INITIALIZE<br>Dec 11 01:54:37 wpa_supplicant[477]: EAPOL: Supplicant port status: Unauthorized<br>
Dec 11 01:54:37 wpa_supplicant[477]: EAPOL: External notification - portValid=0<br>Dec 11 01:54:37 wpa_supplicant[477]: EAPOL: Supplicant port status: Unauthorized<br>Dec 11 01:54:37 wpa_supplicant[477]: EAPOL: External notification - EAP success=0<br>
Dec 11 01:54:37 wpa_supplicant[477]: EAPOL: Supplicant port status: Unauthorized<br>Dec 11 01:54:37 wpa_supplicant[477]: RTM_NEWLINK: operstate=0 ifi_flags=0x11023 ([UP][LOWER_UP])<br>Dec 11 01:54:37 wpa_supplicant[477]: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added<br>
Dec 11 01:54:37 wpa_supplicant[477]: nl80211: if_removed already cleared - ignore event<br>Dec 11 01:54:38 wpa_supplicant[477]: CTRL_IFACE: GET_NETWORK id=0 name='ssid'<br>Dec 11 01:54:41 wpa_supplicant[477]: CTRL_IFACE: GET_NETWORK id=0 name='ssid'<br>
Dec 11 01:54:42 wpa_supplicant[477]: wlan0: State: DISCONNECTED -> SCANNING at 1355190882.309<br>Dec 11 01:54:42 wpa_supplicant[477]: ap_scan 1 Conf ssid redacted prev_scan_ssid=WILDCARD_SSID_SCAN<br>Dec 11 01:54:42 wpa_supplicant[477]: wlan0: Starting AP scan for wildcard SSID<br>
Dec 11 01:54:42 wpa_supplicant[477]: nl80211: Scan frequency 5180 MHz<br>Dec 11 01:54:42 wpa_supplicant[477]: nl80211: Scan frequency 5200 MHz<br>Dec 11 01:54:42 wpa_supplicant[477]: nl80211: Scan frequency 5220 MHz<br>Dec 11 01:54:42 wpa_supplicant[477]: nl80211: Scan frequency 5240 MHz<br>
Dec 11 01:54:42 wpa_supplicant[477]: nl80211: Scan frequency 5745 MHz<br>Dec 11 01:54:42 wpa_supplicant[477]: nl80211: Scan frequency 5765 MHz<br><br>Dec 11 01:54:42 wpa_supplicant[477]: nl80211: Scan frequency 5785 MHz<br>
Dec 11 01:54:42 wpa_supplicant[477]: nl80211: Scan frequency 5805 MHz<br>Dec 11 01:54:42 wpa_supplicant[477]: nl80211: Scan frequency 5825 MHz<br>Dec 11 01:54:42 kernel: nl80211_trigger_scan scan<br>Dec 11 01:54:42 kernel: starting software scan<br>
Dec 11 01:54:42 wpa_supplicant[477]: Scan requested (ret=0) - scan timeout 30 seconds<br>Dec 11 01:54:42 wpa_supplicant[477]: nl80211: Event message available<br>Dec 11 01:54:42 wpa_supplicant[477]: nl80211: Scan trigger<br>
Dec 11 01:54:43 wpa_supplicant[477]: CTRL_IFACE: GET_NETWORK id=0 name='ssid'<br>Dec 11 01:54:44 wpa_supplicant[477]: nl80211: Event message available<br>Dec 11 01:54:44 wpa_supplicant[477]: nl80211: New scan results available<br>
Dec 11 01:54:44 wpa_supplicant[477]: wlan0: Event SCAN_RESULTS (3) received<br>Dec 11 01:54:44 wpa_supplicant[477]: nl80211: Associated on 5180 MHz<br>Dec 11 01:54:44 wpa_supplicant[477]: nl80211: Associated with dead:beef<br>
Dec 11 01:54:44 wpa_supplicant[477]: nl80211: Received scan results (161 BSSes)<br>Dec 11 01:54:44 wpa_supplicant[477]: nl80211: Scan results indicate BSS status with dead:beef as associated<br>Dec 11 01:54:44 wpa_supplicant[477]: nl80211: Local state (not associated) does not match with BSS state<br>
Dec 11 01:54:44 wpa_supplicant[477]: nl80211: Clear possible state mismatch (dead:beef)<br>Dec 11 01:54:44 kernel: wlan0: deauthenticating from dead:beef by local choice (reason=2)<br>Dec 11 01:54:44 kernel: cfg80211: Calling CRDA for country: US<br>
Dec 11 01:54:44 wpa_supplicant[477]: Sorted scan results<br>Dec 11 01:54:44 wpa_supplicant[477]: dead:beef freq=5240 qual=0 noise=0 level=-68 flags=0xb<br><br></div><div><processing all 161 BSSes . snipped><br></div>
<div><br>Dec 11 01:54:45 wpa_supplicant[477]: Add randomness: count=2223 entropy=18<br>Dec 11 01:54:45 wpa_supplicant[477]: random pool - hexdump(len=128): [REMOVED]<br>Dec 11 01:54:45 wpa_supplicant[477]: random_mix_pool - hexdump(len=8): [REMOVED]<br>
Dec 11 01:54:45 wpa_supplicant[477]: random_mix_pool - hexdump(len=5): [REMOVED]<br>Dec 11 01:54:45 wpa_supplicant[477]: random pool - hexdump(len=128): [REMOVED]<br>Dec 11 01:54:45 wpa_supplicant[477]: Add randomness: count=2224 entropy=19<br>
Dec 11 01:54:45 wpa_supplicant[477]: random pool - hexdump(len=128): [REMOVED]<br>Dec 11 01:54:45 wpa_supplicant[477]: random_mix_pool - hexdump(len=8): [REMOVED]<br>Dec 11 01:54:45 wpa_supplicant[477]: random_mix_pool - hexdump(len=5): [REMOVED]<br>
Dec 11 01:54:45 wpa_supplicant[477]: random pool - hexdump(len=128): [REMOVED]<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: New scan results available<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: Selecting BSS from priority group 5<br>
Dec 11 01:54:45 wpa_supplicant[477]: wlan0: 0: dead:beef ssid='redacted' wpa_ie_len=0 rsn_ie_len=20 caps=0x111 level=-68<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: skip - SSID mismatch<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: 1: dead:beef ssid='redacted' wpa_ie_len=0 rsn_ie_len=20 caps=0x111 level=-69<br>
Dec 11 01:54:45 wpa_supplicant[477]: wlan0: skip - SSID mismatch<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: 2: dead:beef ssid='redacted' wpa_ie_len=0 rsn_ie_len=20 caps=0x111 level=-69<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: selected based on RSN IE<br>
Dec 11 01:54:45 wpa_supplicant[477]: wlan0: selected BSS dead:beef ssid='redacted'<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: Request association: reassociate: 0 selected: dead:beef bssid: 00:00:00:00:00:00 pending: 00:00:00:00:00:00 wpa_state: SCANNING<br>
Dec 11 01:54:45 wpa_supplicant[477]: wlan0: Automatic auth_alg selection: 0x1<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: RSN: using IEEE 802.11i/D9.0<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: WPA: Selected cipher suites: group 16 pairwise 16 key_mgmt 2 proto 2<br>
Dec 11 01:54:45 wpa_supplicant[477]: wlan0: WPA: clearing AP WPA IE<br>Dec 11 01:54:45 wpa_supplicant[477]: WPA: set AP RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 28 00<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: WPA: using GTK CCMP<br>
Dec 11 01:54:45 wpa_supplicant[477]: wlan0: WPA: using PTK CCMP<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: WPA: using KEY_MGMT WPA-PSK<br>Dec 11 01:54:45 wpa_supplicant[477]: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00<br>
Dec 11 01:54:45 wpa_supplicant[477]: FT: Stored MDIE and FTIE from (Re)Association Response - hexdump(len=0):<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: Cancelling scan request<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: SME: Trying to authenticate with dead:beef (SSID='redacted' freq=5240 MHz)<br>
Dec 11 01:54:45 wpa_supplicant[477]: wlan0: No keys have been configured - skip key clearing<br>Dec 11 01:54:45 wpa_supplicant[477]: wlan0: State: SCANNING -> AUTHENTICATING at 1355190885.209<br>Dec 11 01:54:45 wpa_supplicant[477]: EAPOL: External notification - EAP success=0<br>
Dec 11 01:54:45 wpa_supplicant[477]: EAPOL: Supplicant port status: Unauthorized<br>Dec 11 01:54:45 wpa_supplicant[477]: EAPOL: External notification - EAP fail=0<br>Dec 11 01:54:45 wpa_supplicant[477]: EAPOL: Supplicant port status: Unauthorized<br>
Dec 11 01:54:45 wpa_supplicant[477]: EAPOL: External notification - portControl=Auto<br>Dec 11 01:54:45 wpa_supplicant[477]: EAPOL: Supplicant port status: Unauthorized<br>Dec 11 01:54:45 wpa_supplicant[477]: nl80211: Authenticate (ifindex=3)<br>
Dec 11 01:54:45 wpa_supplicant[477]: * bssid=dead:beef<br>Dec 11 01:54:45 wpa_supplicant[477]: * freq=5240<br>Dec 11 01:54:45 wpa_supplicant[477]: * IEs - hexdump(len=0): [NULL]<br>Dec 11 01:54:45 wpa_supplicant[477]: * Auth Type 0<br>
Dec 11 01:54:45 kernel: wlan0: authenticate with dead:beef (try 1)<br>Dec 11 01:54:45 kernel: wlan0: authenticated<br>Dec 11 01:54:45 wpa_supplicant[477]: nl80211: Authentication request send successfully<br><br><br></div>
<div>In the 802.11 capture data, we see clearly that the client is sending valid Probe Requests, and the access point is failing to respond, though the same access point is responding to other clients. We have the vendor engaged to answer the question of why the access point is not responding. <br>
<br></div><div>Obviously, the access point is in the client's scan list and is not dead, and should be responding. While discussions with the vendor are underway though, I have a question about the way that wpa_supplicant responds to this scenario. <br>
<br></div><div>What appears to happen after the MLME layer issues the times-out, is that the supplicant then kicks off a scan and disconnects. In our dense environment, this scan takes seconds to complete, and breaks our clients. In the case where these failures happen, the client already has a very full scan list that contains a lot of very solid roam choices. Is there some way that I can cause the supplicant to attempt the next BSS on the list rather than invoking a whole new scan?<br>
</div><div><br></div><div>Thanks in advance for your input!<br><br></div><div>Cheers,<br><br></div><div>--<br></div>Matt<br><br>[1] - <a href="http://lxr.free-electrons.com/source/net/mac80211/mlme.c#L2725">http://lxr.free-electrons.com/source/net/mac80211/mlme.c#L2725</a> <br>
</div>