wpa_supplicant 0.7.3 slow to associate, 0.6.10 is ok

Tue Aug 14 02:02:12 PDT 2012

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?

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.shmoo.com/pipermail/hostap/attachments/20120814/686c0a04/attachment-0001.htm 