[wpa_supplicant/WPA] request for clarification

Fri Jul 16 08:38:16 PDT 2010

Hi all

I'd like to ask some more questions regarding wpa_supplicant and WPA
authentication.

I'm using the wpa_supplicant 0.6.10, the source code cross compiled
from Debian sources. 

I'm trying to understand the WiFi WPA connection/association flow. And
I'm confused at some points.

One is the "blacklist". Please consider the following snippet:

1279286521.334725: Authentication with c0:3f:0e:49:6a:ca timed out.
1279286521.334790: CTRL_IFACE monitor send - hexdump(len=21): 2f 74 6d
70 2f 77 70 61 5f 63 74 72 6c 5f 32 39 32 36 2d 31 00
1279286521.334926: CTRL_IFACE monitor[0]: 111 - Connection refused
1279286521.334984: Added BSSID c0:3f:0e:49:6a:ca into blacklist
1279286521.335034: wpa_driver_wext_disassociate
1279286521.497794: No keys have been configured - skip key clearing
1279286521.497841: State: 4WAY_HANDSHAKE -> DISCONNECTED

I can understand that the authentication has timed out. But from the
other hand I don't know why the connection is refused and then
wpa_supplicant is putting the AP to the "blacklist". I use only one AP
to provide the services set (WiFi), so why connection is refused. I'm
using 4WAY_HANDSHAKE EAP authentication.

What is even more strange, afterwards I can get from logs:

1279286521.498757: Wireless event: cmd=0x8c02 len=27
1279286521.498803: WEXT: Custom wireless event: 'Conn Disassoc 00 08'
1279286521.498866: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
([UP][LOWER_UP]) 
1279286521.498915: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1279286521.498960: Wireless event: cmd=0x8b15 len=20 
1279286521.499003: Wireless event: new AP: 00:00:00:00:00:00
1279286521.499053: BSSID 00:00:00:00:00:00 blacklist count incremented
to 2 
1279286521.499108: CTRL-EVENT-DISCONNECTED - Disconnect event - remove
keys 
1279286521.499157: CTRL_IFACE monitor send - hexdump(len=21): 2f
74 6d 70 2f 77 70 61 5f 63 74 72 6c 5f 32 39 32 36 2d 31 00
1279286521.499281: CTRL_IFACE monitor[0]: 111 - Connection refused

And then the new "wireless event" emerge, which indicates, that the
new AP with MAC 00:00:00:00:00:00 has been found.This is even more
strange, since the wpa_supplicant or driver has refused connection
with the "correct" AP on behalf of the other, in the driver opinion
better AP, with MAC 00:00:00:00:00:00.  

Additionally, after some time the wpa_supplicant/driver is performing
scan again, and the AP is found without any problems, EAPOL
authentication is correctly performed and WiFi connection with the
"blacklisted" AP is set up.

Another thing, which I don't understand in the wpa_supplicant is the
routine following the "Trying to get current scan results first
without requesting a new scan to speed up initial association" debug
message. In the code (function wpa_supplicant_scan) this routine is
only called when the scan is performed for the first time. It seems
like a routine responsible for reading data cached in wifi driver
(since only the wpa_supplicant is killed and started again - the driver
is still inserted to the kernel) and then speeds up the association.

The debug output is rather long, but I beleive that pasting it "as is"
without reducing it, will be more clear in respect to the following
question.

1279291508.376031: Trying to get current scan results first without
requesting a new scan to speed up initial association
1279291508.405269: Received 579 bytes of scan results (3 BSSes)
1279291508.405357: New scan results available 
1279291508.405416: CTRL_IFACE monitor send - hexdump(len=21): 2f 74 6d
70 2f 77 70 61 5f 63 74 72 6c 5f 32 39 36 37 2d 31 00
1279291508.405612: Selecting BSS from priority group 0
1279291508.405681: Try to find WPA-enabled AP 
1279291508.405728: 0: c0:3f:0e:49:6a:ca ssid='linksys-g' wpa_ie_len=24
rsn_ie_len=0 caps=0x11 1279291508.405815:    selected based on WPA IE
1279291508.405862: selected WPA AP c0:3f:0e:49:6a:ca ssid='linksys-g'
1279291508.405924: Trying to associate with c0:3f:0e:49:6a:ca
(SSID='linksys-g' freq=2437 MHz) 
1279291508.405973: CTRL_IFACE monitor send - hexdump(len=21): 2f 74 6d
70 2f 77 70 61 5f 63 74 72 6c 5f 32 39 36 37 2d 31 00
1279291508.406138: Cancelling scan request 
1279291508.406192: WPA: clearing own WPA/RSN IE 1279291508.470200:
Automatic auth_alg selection: 0x1 
1279291508.500601: WPA: using IEEE 802.11i/D3.0 
1279291508.500666: WPA: Selected cipher suites: group 8 pairwise 8
key_mgmt 2 proto 1 
1279291508.500714: WPA: set AP WPA IE - hexdump(len=26): dd 18 00 50 f2
01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 0 c 00
1279291508.500790: WPA: clearing AP RSN IE 
1279291508.500835: WPA: using GTK TKIP 1279291508.500882: WPA: using
PTK TKIP 
1279291508.500930: WPA: using KEY_MGMT WPA-PSK
1279291508.500979: WPA: Set own WPA IE default - hexdump(len=24): dd 16
00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 5 0 f2 02
1279291508.501053: No keys have been configured - skip key clearing
1279291508.501098: wpa_driver_wext_set_drop_unencrypted
1279291508.530456: State: SCANNING -> ASSOCIATING 1279291508.530515:
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1279291508.530563: WEXT: Operstate: linkmode=-1, operstate=5
1279291508.530640: wpa_driver_wext_associate 1279291508.765085:
wpa_driver_wext_set_psk WPA_SUPPLICANT (set_SSID) [9]: linksys-g
1279291508.907272: Setting authentication timeout: 10 sec 0 usec
1279291508.907342: EAPOL: External notification - EAP success=0
1279291508.907399: EAPOL: External notification - EAP fail=0
1279291508.907446: EAPOL: External notification - portControl=Auto
1279291508.907446: EAPOL: External notification - portControl=Auto
1279291508.907562: EAPOL: disable timer tick
1279291508.907639: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
([UP][LOWER_UP]) 
1279291508.907693: RTM_NEWLINK, IFLA_IFNAME: Interface
'eth0' added 1279291508.907741: Wireless event: cmd=0x8c02 len=29
1279291508.907786: WEXT: Custom wireless event: 'Conn NoNetworks 03 00'
1279291508.907841: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
([UP][LOWER_UP]) 
1279291508.907889: RTM_NEWLINK, IFLA_IFNAME: Interface
'eth0' added 1279291508.907932: Wireless event: cmd=0x8b06 len=8
1279291508.907983: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
([UP][LOWER_UP]) 1279291508.908030: RTM_NEWLINK, IFLA_IFNAME: Interface
'eth0' added 1279291508.908073: Wireless event: cmd=0x8b04 len=12
1279291508.908213: RX ctrl_iface - hexdump_ascii(len=4):
     50 49 4e 47                                       PING
1279291508.909243: CTRL_IFACE monitor detached - hexdump(len=21): 2f 74
6d 70 2f 77 70 61 5f 63 74 72 6c 5f 32 39 36 37 2d 31 00
1279291510.049771: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
([UP][LOWER_UP]) 
1279291510.049840: RTM_NEWLINK, IFLA_IFNAME: Interface
'eth0' added 
1279291510.049888: Wireless event: cmd=0x8b15 len=20
1279291510.049931: Wireless event: new AP: c0:3f:0e:49:6a:ca
1279291510.049979: State: ASSOCIATING -> ASSOCIATED 1279291510.050024:
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
1279291510.050070: WEXT: Operstate: linkmode=-1, operstate=5
1279291510.067560: Associated to a new BSS: BSSID=c0:3f:0e:49:6a:ca
1279291510.067619: No keys have been configured - skip key clearing
1279291510.067673: Associated with c0:3f:0e:49:6a:ca 1279291510.067717:
WPA: Association event - clear replay counter 1279291510.067761: WPA:
Clear old PTK 
1279291510.067802: EAPOL: External notification - portEnabled=0 
1279291510.067851: EAPOL: External notification - portValid=0
1279291510.067898: EAPOL: External notification - EAP success=0
1279291510.067943: EAPOL: External notification - portEnabled=1
1279291510.067988: EAPOL: SUPP_PAE entering state CONNECTING
1279291510.068031: EAPOL: enable timer tick 
1279291510.068076: EAPOL: SUPP_BE entering state IDLE
1279291510.068129: Setting authentication timeout: 10 sec 0 usec
1279291510.068181: Cancelling scan request 1279291510.136123:
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
1279291510.136183: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1279291510.136229: Wireless event: cmd=0x8c03 len=20 
1279291510.136288: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
([UP][LOWER_UP]) 
1279291510.136337: RTM_NEWLINK, IFLA_IFNAME: Interface 'eth0' added
1279291510.136381: Wireless event: cmd=0x8c02 len=26
1279291510.136425: WEXT: Custom wireless event: 'Conn Success 00 00'
1279291510.325900: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
([UP][LOWER_UP]) 1279291510.325959: RTM_NEWLINK, IFLA_IFNAME: Interface
'eth0' added 
1279291510.326004: Wireless event: cmd=0x8b15 len=20
1279291510.326047: Wireless event: new AP: 00:00:00:00:00:00
1279291510.326103: Setting scan request: 0 sec 100000 usec
1279291510.326155: Added BSSID c0:3f:0e:49:6a:ca into blacklist
1279291510.326241: CTRL-EVENT-DISCONNECTED - Disconnect event - remove
keys 
1279291510.326291: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0
seq_len=0 key_len=0 
1279291510.343866: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0
seq_len=0 key_len=0 
1279291510.362623: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0
seq_len=0 key_len=0 
1279291510.380503: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0
seq_len=0 key_len=0 
1279291510.398201: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0
seq_len=0 key_len=0 
1279291510.416318: State: ASSOCIATED -> DISCONNECTED

First, I don't know what is the PING event. Is it send from wpa_cli to
"wake up" wpa_supplicant at proper intervals? Moreover after that ping,
the wpa_supplicant or driver is stalled for about 1s (up till
1279291510.049771). What may be the reason for this? Then the
WPA/EAPOL negotiation and authentication is successfully performed.
Unfortunately afterwards the problem with "AP: 00:00:00:00:00:00" and
"blacklist" shows up as described previously. 

Any idea/hint why it is going like that?

Additionally, I'd like to ask what is the difference between ap_scan=1
and ap_scan=2 ?

Any help will be appreciated :-)

-- 
Best regards,

Lukasz Majewski

Samsung Poland R&D Center
Platform Group