wpa_supplicant 0.7.3 slow to associate, 0.6.10 is ok

Tue Aug 14 09:16:21 PDT 2012

On Tue, 2012-08-14 at 11:02 +0200, Adrien Decostre wrote:
> Dear all,
> 
> 
> >> Please send debug logs with timestamps (-dt on command line) from
> both
> >> 0.6.10 and 0.7.3.
> > See attachment. (in separate e-mails due to file size limit on ML)
> Since the logs provided by Koen have been bounced due to size limit on
> the mailing list, the most relevant parts of the logs are given below.
> These logs have been obtained with the ap_scan=1 (default).
> 
> 
> For wpa_supplicant.0.6.10, we see that a RTM_NEWLINK is 1st created
> and then the AP scan is started. The scan results are returned
> immediately.
> For wpa_supplicant.0.7.3, we see that the scanning is 1st started and
> then a RTM_NEWLINK is created. The scan results are returned about 8
> sec. later.
> Apparently, these 2 versions of wpa_supplicant do not initiates
> scanning in the same way for our configuration. 
> 
> 
> Would any one have an idea about the cause of this issue? 
> Has someone already seen similar behaviour? 

The point is, that shouldn't matter.

The logs indicate the driver is clearly refusing scan requests because
it is "busy" doing something else, probably already scanning.  But since
WEXT has no facility (and never will, since it's dead) to indicate any
of it's internal status operations, the supplicant never knows that.
Instead of hacking the supplicant up to work around deprecated kernel
driver APIs, it's fairly simple to modify the driver to handle this case
better, by not returning EBUSY to the supplicant's scan request, but
returning success instead (since a scan request is ongoing already, why
not? the supplicant will get the results when it's done anyway).

Next step would be to cache scan results in the driver, but you might be
able to get away without that for now.  Again, we've fixed all the
in-kernel drivers to do this, but since your driver is out-of-tree, it
hasn't been.

Dan

> 
> Thanks in advance for any help or information.
> 
> 
> Best regards
> 
> 
> Adrien
> 
> 
> wpa_supplicant.0.6.10 log:
> 146.301062: Initializing interface 'wlan0' conf
> '/etc/wpa_supplicant.config' driver 'default' ctrl_interface 'N/A'
> bridge 'N/A'
> 146.301625: Configuration file '/etc/wpa_supplicant.config' ->
> '/etc/wpa_supplicant.config'
> 146.301781: Reading configuration file '/etc/wpa_supplicant.config'
> 146.302656: ctrl_interface='/var/run/wpa_supplicant'
> 146.302843: ctrl_interface_group='root'
> 146.302968: Line: 3 - start of a new network block
> 146.303500: ssid - hexdump_ascii(len=16):
>      43 6c 69 63 6b 53 68 61 72 65 5f 6f 75 66 74 69   oufti_oufti
> 146.303968: scan_ssid=1 (0x1)
> 146.304125: proto: 0x2
> 146.304281: key_mgmt: 0x2
> 146.304593: pairwise: 0x10
> 146.304781: group: 0x10
> 146.304875: PSK - hexdump(len=32): [REMOVED]
> 146.306281: priority=20 (0x14)
> 146.306656: Priority group 20
> 146.306781:    id=0 ssid='oufti_oufti'
> 146.306875: Initializing interface (2) 'wlan0'
> 146.308906: Interface wlan0 set UP - waiting a second for the driver
> to complete initialization
> 147.309593: SIOCGIWRANGE: WE(compiled)=22 WE(source)=9 enc_capa=0x0
> 147.309843:   capabilities: key_mgmt 0x0 enc 0x3 flags 0x0
> 147.407750: WEXT: Operstate: linkmode=1, operstate=5
> 147.408593: Own MAC address: 00:23:a7:3a:12:61
> 147.408812: wpa_driver_wext_set_wpa
> 147.408968: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0
> seq_len=0 key_len=0
> 147.409250: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0
> seq_len=0 key_len=0
> 147.409437: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0
> seq_len=0 key_len=0
> 147.409625: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0
> seq_len=0 key_len=0
> 147.409812: wpa_driver_wext_set_countermeasures
> 147.409968: wpa_driver_wext_set_drop_unencrypted
> 147.440343: RSN: flushing PMKID list in the driver
> 147.441437: Setting scan request: 0 sec 100000 usec
> 147.441656: EAPOL: SUPP_PAE entering state DISCONNECTED
> 147.441750: EAPOL: KEY_RX entering state NO_KEY_RECEIVE
> 147.441875: EAPOL: SUPP_BE entering state INITIALIZE
> 147.441968: EAP: EAP entering state DISABLED
> 147.443250: ctrl_interface_group=0 (from group name 'root')
> 147.444500: Added interface wlan0
> 147.445187: RTM_NEWLINK: operstate=0 ifi_flags=0x11043
> ([UP][RUNNING][LOWER_UP])
> 147.445406: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
> 147.445625: RTM_NEWLINK: operstate=0 ifi_flags=0x11043
> ([UP][RUNNING][LOWER_UP])
> 147.445750: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
> 147.445843: Wireless event: cmd=0x8b06 len=8
> 147.446250: RTM_NEWLINK: operstate=0 ifi_flags=0x11043
> ([UP][RUNNING][LOWER_UP])
> 147.446437: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
> 147.446531: Wireless event: cmd=0x8b1a len=40
> 147.446656: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
> ([UP][LOWER_UP])
> 147.446843: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
> 147.541937: State: DISCONNECTED -> SCANNING
> 147.542125: Starting AP scan (specific SSID)
> 147.542281: Scan SSID - hexdump_ascii(len=16):
>      43 6c 69 63 6b 53 68 61 72 65 5f 6f 75 66 74 69   oufti_oufti
> 147.542593: Trying to get current scan results first without
> requesting a new scan to speed up initial association
> 147.542968: Received 768 bytes of scan results (6 BSSes)
> 147.543125: New scan results available
> 147.543281: Selecting BSS from priority group 20
> 147.543375: Try to find WPA-enabled AP
> 147.543437: 0: 00:0e:8e:3b:12:73 ssid='oufti_oufti' wpa_ie_len=0
> rsn_ie_len=20 caps=0x11
> 147.543656:    selected based on RSN IE
> 147.543750:    selected WPA AP 00:0e:8e:3b:12:73 ssid='oufti_oufti'
> 147.544000: Trying to associate with 00:0e:8e:3b:12:73
> (SSID='oufti_oufti' freq=2452 MHz)
> 147.544125: Cancelling scan request
> 147.544218: WPA: clearing own WPA/RSN IE
> 
> 
> log of wpa_supplicant.0.7.3 including the patch provided by Timo
> at http://lists.shmoo.com/pipermail/hostap/2012-June/026234.html (as
> Koen said previously, this solved the "ioctl[SIOCGIWSCAN]: Resource
> temporarily unavailable" issue):
> 6346.539343: Initializing interface 'wlan0' conf
> '/etc/wpa_supplicant.config' driver 'default' ctrl_interface 'N/A'
> bridge 'N/A'
> 6346.540125: Configuration file '/etc/wpa_supplicant.config' ->
> '/etc/wpa_supplicant.config'
> 6346.540500: Reading configuration file '/etc/wpa_supplicant.config'
> 6346.551500: ctrl_interface='/var/run/wpa_supplicant'
> 6346.551968: ctrl_interface_group='root'
> 6346.552156: Line: 3 - start of a new network block
> 6346.552437: ssid - hexdump_ascii(len=16):
>      43 6c 69 63 6b 53 68 61 72 65 5f 6f 75 66 74 69   oufti_oufti
> 6346.552843: scan_ssid=1 (0x1)
> 6346.553218: proto: 0x2
> 6346.553406: key_mgmt: 0x2
> 6346.553500: pairwise: 0x10
> 6346.553593: group: 0x10
> 6346.553750: PSK - hexdump(len=32): [REMOVED]
> 6346.554000: priority=20 (0x14)
> 6346.554593: Priority group 20
> 6346.554750:    id=0 ssid='oufti_oufti'
> 6346.557406: SIOCGIWRANGE: WE(compiled)=22 WE(source)=9 enc_capa=0x0
> 6346.557562:   capabilities: key_mgmt 0x0 enc 0x3 flags 0x0
> 6346.656250: netlink: Operstate: linkmode=1, operstate=5
> 6346.657343: Own MAC address: 00:23:a7:3a:12:61
> 6346.657531: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0
> seq_len=0 key_len=0
> 6346.657843: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0
> seq_len=0 key_len=0
> 6346.658062: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0
> seq_len=0 key_len=0
> 6346.658250: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0
> seq_len=0 key_len=0
> 6346.658468: wpa_driver_wext_set_countermeasures
> 6346.658593: RSN: flushing PMKID list in the driver
> 6346.658812: Setting scan request: 0 sec 100000 usec
> 6346.955250: EAPOL: SUPP_PAE entering state DISCONNECTED
> 6346.955750: EAPOL: Supplicant port status: Unauthorized
> 6346.955937: EAPOL: KEY_RX entering state NO_KEY_RECEIVE
> 6346.956000: EAPOL: SUPP_BE entering state INITIALIZE
> 6346.956187: EAP: EAP entering state DISABLED
> 6346.956250: EAPOL: Supplicant port status: Unauthorized
> 6346.956343: EAPOL: Supplicant port status: Unauthorized
> 6346.957375: ctrl_interface_group=0 (from group name 'root')
> 6346.958531: Added interface wlan0
> 6346.958937: State: DISCONNECTED -> SCANNING
> 6346.959062: Scan SSID - hexdump_ascii(len=16):
>      43 6c 69 63 6b 53 68 61 72 65 5f 6f 75 66 74 69   oufti_oufti
> 6346.959687: Starting AP scan for specific SSID(s)
> 6346.960312: Scan requested (ret=0) - scan timeout 10 seconds
> 6346.960750: RTM_NEWLINK: operstate=0 ifi_flags=0x11043
> ([UP][RUNNING][LOWER_UP])
> 6346.960968: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
> 6346.961125: RTM_NEWLINK: operstate=0 ifi_flags=0x11043
> ([UP][RUNNING][LOWER_UP])
> 6346.961250: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
> 6346.961343: Wireless event: cmd=0x8b06 len=8
> 6346.961468: RTM_NEWLINK: operstate=0 ifi_flags=0x11043
> ([UP][RUNNING][LOWER_UP])
> 6346.961625: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
> 6346.961718: Wireless event: cmd=0x8b1a len=40
> 6346.961843: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
> ([UP][LOWER_UP])
> 6346.961968: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
> 6347.957468: EAPOL: disable timer tick
> 6347.957687: EAPOL: Supplicant port status: Unauthorized
> 6355.381531: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
> ([UP][LOWER_UP])
> 6355.381781: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
> 6355.381875: Wireless event: cmd=0x8b19 len=8
> 6355.382312: Received 652 bytes of scan results (5 BSSes)
> 6355.382593: BSS: Start scan result update 1
> 6355.382718: BSS: Add new id 0 BSSID 00:0e:8e:3b:12:73 SSID
> 'oufti_oufti'
> 6355.382937: BSS: Add new id 1 BSSID c0:c1:c0:32:44:80 SSID
> 'CiscoG2436'
> 6355.383187: BSS: Add new id 2 BSSID 00:0e:8e:3b:10:4c SSID
> 'oufti-1143ALFA30'
> 6355.383406: BSS: Add new id 3 BSSID c0:c1:c0:32:34:84 SSID 'oufti
> Cisco'
> 6355.383593: BSS: Add new id 4 BSSID 00:0e:8e:3a:47:c1 SSID
> 'oufti_test_beaconint_100'
> 6355.383812: New scan results available
> 6355.383937: Selecting BSS from priority group 20
> 6355.384093: Try to find WPA-enabled AP
> 6355.384187: 0: 00:0e:8e:3b:12:73 ssid='oufti_oufti' wpa_ie_len=0
> rsn_ie_len=20 caps=0x11
> 6355.384406:    selected based on RSN IE
> 6355.384531:    selected WPA AP 00:0e:8e:3b:12:73 ssid='oufti_oufti'
> 6355.384843: Trying to associate with 00:0e:8e:3b:12:73
> (SSID='oufti_oufti' freq=2452 MHz)
> 6355.385000: FT: Stored MDIE and FTIE from (Re)Association Response -
> hexdump(len=0):
> 6355.385156: Cancelling scan request
> 
> _______________________________________________
> HostAP mailing list
> HostAP at lists.shmoo.com
> http://lists.shmoo.com/mailman/listinfo/hostap