No automatic reconnection after AP was down

[Dan Williams]

On Tue, 2014-09-16 at 11:33 +0200, Bojan Prtvar wrote:
> Hi,
> 
> We have a test case where our device should automatically reconnect to
> AP after AP's reset.
> Most of the time this works as expected and in such cases these are the
> dumps from wpa_supplicant:
> 
>  RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
>  RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
>  nl80211: if_removed already cleared - ignore event
>  nl80211: Event message available
>  nl80211: New sched scan results available
>  wlan0: Event SCAN_RESULTS (3) received
>  nl80211: Received scan results (1 BSSes)
>  nl80211: Survey data missing
>  wlan0: BSS: Start scan result update 60
>  wlan0: BSS: Add new id 36 BSSID f8:d1:11:a6:1b:b0 SSID 'marvell_5GHz'
>  CTRL_IFACE monitor send - hexdump(len=40): 2f 64 61 74 61 2f 6d 69 73
> 63 2f 77 69 66 69 2f 73 6f 63 6b 65 74 73 2f 77 70 61 5f 63 74 72 6c ...
>  BSS: last_scan_res_used=1/32 last_scan_full=1
>  wlan0: New scan results available
>  CTRL_IFACE monitor send - hexdump(len=40): 2f 64 61 74 61 2f 6d 69 73
> 63 2f 77 69 66 69 2f 73 6f 63 6b 65 74 73 2f 77 70 61 5f 63 74 72 6c ...
>  CTRL_IFACE monitor send - hexdump(len=40): 2f 64 61 74 61 2f 6d 69 73
> 63 2f 77 69 66 69 2f 73 6f 63 6b 65 74 73 2f 77 70 61 5f 63 74 72 6c ...
>  WPS: AP f8:d1:11:a6:1b:b0 type 0 added
>  WPS: AP[0] c0:d9:62:8e:9f:1c type=0 tries=0 last_attempt=-1 sec ago
> blacklist=0
>  WPS: AP[1] ac:22:0b:7c:bc:b4 type=0 tries=0 last_attempt=-1 sec ago
> blacklist=0
>  WPS: AP[2] f8:d1:11:a6:1b:b0 type=0 tries=0 last_attempt=-1 sec ago
> blacklist=0
>  wlan0: Selecting BSS from priority group 1
>  wlan0: 0: f8:d1:11:a6:1b:b0 ssid='marvell_5GHz' wpa_ie_len=26
> rsn_ie_len=24 caps=0x511 level=-30 wps
>  wlan0:    selected based on RSN IE
>  wlan0:    selected BSS f8:d1:11:a6:1b:b0 ssid='marvell_5GHz'
>  wlan0: Request association: reassociate: 0  selected:
> f8:d1:11:a6:1b:b0  bssid: 00:00:00:00:00:00  pending: 00:00:00:00:00:00 
> wpa_state: SCANNING
>  wlan0: Trying to associate with f8:d1:11:a6:1b:b0 (SSID='marvell_5GHz'
> freq=5180 MHz)
>  
>  But sometimes reconnection does not happen and we get the fallowing:
>  
>  RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
>  RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
>  nl80211: if_removed already cleared - ignore event
>  nl80211: Event message available
>  nl80211: New sched scan results available
>  wlan0: Event SCAN_RESULTS (3) received
>  nl80211: Received scan results (1 BSSes)
>  nl80211: Survey data missing
>  wlan0: BSS: Start scan result update 8
>  BSS: last_scan_res_used=1/32 last_scan_full=1
>  wlan0: New scan results available
>  CTRL_IFACE monitor send - hexdump(len=40): 2f 64 61 74 61 2f 6d 69 73
> 63 2f 77 69 66 69 2f 73 6f 63 6b 65 74 73 2f 77 70 61 5f 63 74 72 6c ...
>  CTRL_IFACE monitor send - hexdump(len=40): 2f 64 61 74 61 2f 6d 69 73
> 63 2f 77 69 66 69 2f 73 6f 63 6b 65 74 73 2f 77 70 61 5f 63 74 72 6c ...
>  WPS: AP[0] c0:d9:62:8e:9f:1c type=0 tries=0 last_attempt=-1 sec ago
> blacklist=0
>  WPS: AP[1] ac:22:0b:7c:bc:b4 type=0 tries=0 last_attempt=-1 sec ago
> blacklist=0
>  wlan0: Selecting BSS from priority group 1
>  wlan0: 0: f8:d1:11:a6:1b:b0 ssid='marvell_5GHz' wpa_ie_len=0
> rsn_ie_len=0 caps=0x501 level=-23
>  wlan0:    skip - no WPA/RSN proto match
>  wlan0: No suitable network found

The AP that's been selected is not broadcasting any WPA or RSN
information elements, so that AP is not WPA/RSN capable.  But since your
configuration requires WPA or RSN, there is a mismatch and you cannot
connect to the AP.

This is probably an AP bug: it should not broadcasting beacons with the
wrong information, before it has completely set itself up.  Here, it
seems to be starting up and sending out a beacon without any encryption
indication, and then later (well, a second or two or three) it probably
changes the information elements to specify WPA or RSN.  If this AP is
actually a hotspot that you've created yourself, then the driver/hostap
should be fixed.

wpa_supplicant does have some code to handle this, so if the AP does
change it's beacon I would expect the supplicant to notice and
eventually connect.  What does "iw wlan0 scan dump" show on your machine
for marvell_5GHz when this problem happens?

Dan

>  wlan0: Already sched scanning
>  wlan0: Checking for other virtual interfaces sharing same radio
> (mwiphy0) in event_scan_results
>  p2p0: Updating scan results from sibling
>  Not Updating scan results on interface p2p0 from sibling wlan0
> 
> The issue seams harder to reproduce when we increase log level to debug.
> Our wpa_supplicant version is v2.0-devel-4.2.2.
> Is it possible to conclude based on these log is this an wpa_suppilicant
> issue or lower layers are responsible?
> Any pointer would be appreciated.