Station seems stuck in scanning

[Simon Falsig]

Hi,

Following up on a previous email ("Reasons for WLC_E_DEAUTH_IND / WLAN_REASON_PREV_AUTH_NOT_VALID when roaming"), I've now finally managed to reproduce the issue in a case where I have the wpa_supplicant log available also.

The problem is that a station seems to lose WiFi access on roaming, without being able to reconnect - from what I can see, after receiving a deauthentication from the access point that is roamed to, due to the "Previous authentication no longer valid" reason.

The setup is:
- Stations: Embedded Linux board, running Linux 4.4, wpa_supplicant v2.8, Broadcom WiFi with bcmdhd driver
- Access Points: Multiple Ubiquity AP-AC-Pro, running, from what I can see, hostapd v2.8 on an Atheros chipset
- WiFi with WPA2-PSK, 5GHz only, non-DFS channels

Looking at the wpa_supplicant log from the station in question, it looks like the system gets stuck in scanning:

wlan0: Event SCAN_STARTED (46) received
wlan0: Own scan request started a scan in 0.000052 seconds
dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
RTM_NEWLINK: ifi_index=7 ifname=wlan0 wext ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP])
nl80211: Ignored event (cmd=34) for foreign interface (ifindex 7 wdev 0x0)
nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0
wlan0: nl80211: New scan results available
nl80211: Scan probed for SSID ''
nl80211: Scan included frequencies: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472 5180 5200 5220 5240 5260 5280 5300 5320
wlan0: Event SCAN_RESULTS (3) received
wlan0: Scan completed in 1.719767 seconds
nl80211: Received scan results (0 BSSes)
wlan0: BSS: Start scan result update 53
BSS: last_scan_res_used=0/32
wlan0: New scan results available (own=1 ext=0)
wlan0: Radio work 'scan'@0x555b034f70 done in 1.722856 seconds
wlan0: radio_work_free('scan'@0x555b034f70): num_active_works --> 0
wlan0: No suitable network found
wlan0: Beginning of SSID list
wlan0: Add wildcard SSID to sched_scan
wlan0: add to filter ssid: vs-iid-warespace
WPS: Building WPS IE for Probe Request
WPS:  * Version (hardcoded 0x10)
WPS:  * Request Type
WPS:  * Config Methods (3108)
WPS:  * UUID-E
WPS:  * Primary Device Type
WPS:  * RF Bands (3)
WPS:  * Association State
WPS:  * Configuration Error (0)
WPS:  * Device Password ID (0)
WPS:  * Manufacturer
WPS:  * Model Name
WPS:  * Model Number
WPS:  * Device Name
WPS:  * Version2 (0x20)
P2P: * P2P IE header
P2P: * Capability dev=25 group=00
P2P: * Listen Channel: Regulatory Class 81 Channel 1
wlan0: Starting sched scan after 0 seconds (no timeout)
wlan0: nl80211: sched_scan request
nl80211: Sched scan requested (ret=0)
p2p-dev-wlan0: Updating scan results from sibling
nl80211: Received scan results (0 BSSes)
p2p-dev-wlan0: BSS: Start scan result update 42
BSS: last_scan_res_used=0/32
p2p-dev-wlan0: New scan results available (own=0 ext=0)
WPS: AP[0] 98:da:c4:c5:dc:74 type=0 tries=0 last_attempt=-1 sec ago blacklist=0
nl80211: Ignored event (cmd=75) for foreign interface (ifindex 7 wdev 0x0)
nl80211: Drv Event 75 (NL80211_CMD_START_SCHED_SCAN) received for wlan0
wlan0: nl80211: Sched scan started
dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
wlan0: Control interface command 'REASSOCIATE'
wlan0: Setting scan request: 0.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
wlan0: Setting scan request: 1.000000 sec
wlan0: Already scanning - Reschedule the incoming scan req
...

And then just continues like that. Note that the reassociate request is generated by one of our attempted workarounds, which continuously pings a server on the network, and issues a reassociate command through wpa_cli, if the server hasn't been pingable for 5 seconds. Probably not the most pretty thing to do, but it helps in some cases at least.

I logged into the station over a serial console, and issued an "ifdown wlan0 / ifup wlan0" combo, which made things work again.

Could this be a corner-case / race-condition in the interplay between wpa_supplicant and the kernel / driver / firmware / hardware that we use? 

I looked at http://lists.infradead.org/pipermail/hostap/2015-March/032247.html ("[PATCH] Fix scanning state when sched_scan is stopped explicitly"), which seems to not have been merged, but discusses some possible races in the scanning state. I know far too little about the complete stack to say if it's relevant at all though...

Any ideas about what else to look for or try?

Thanks in advance!
 - Simon