WPA PSK - AUTH, ASSOC, 4-Way Handshake

Thu Sep 9 00:29:08 PDT 2004

On Wed, Sep 08, 2004 at 11:45:11PM -0700, Jouni Malinen wrote:
> On Thu, Sep 09, 2004 at 01:56:57AM -0400, Luis R. Rodriguez wrote:
> 
> > Can someone tell me at what point the AUTH and ASSOC wireless
> > events are caught when a STA is associating to an AP using wpa_supplicant?
> > Is the AUTH sent, and in reponse the 4-way handshake occur? And then you
> > get an ASSOC at the 4th step of the handshake? Or does both of these
> > occur (AUTH, and ASSOC) occur prior to the 4-way handshake?
> 
> If by AUTH you mean IEEE 802.11 authentication, the last option wuld be
> correct. In other words:
> 

This is where I am with prism54 wpa_supplicant:

> 0) Scan results, wpa_supplicants configures driver

Check

> 1) IEEE 802.11 authentication (wpa_supplicant doesn't really care about
>    this)
> 2) IEEE 802.11 association (New Access Point)

I'm not seeing any of these sent caught by iwevent. I actually also do
not see these on your iwevent log too, but I checked and noticed hostap
src does not send a custom wireless event in the AUTH/ASSOC 802.11
event.

Here is what I usually see in my iwevent log when associating to a
non-WPA AP:

11:06:42.099028    eth0     Custom driver event:Authenticate request to 00:09:5B:9A:D8:62  : ACCEPTED  (00)
11:06:42.116797    eth0     Custom driver event:Associate request to 00:09:5B:9A:D8:62  : ACCEPTED  (00)
11:06:44.001712    eth0     New Access Point/Cell address:00:09:5B:9A:D8:62

Here is what I'm seeing once I turn wpa_supplicant on:

11:06:56.806540    eth0     Custom driver event:Received a beacon from an unkown AP to 00:09:5B:D4:C0:E0  (00)
11:06:59.897279    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:00.058512    eth0     ESSID:"asdf"
11:07:00.166238    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:00.269905    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:08.071873    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:08.071970    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:08.072022    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:08.072072    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:08.174560    eth0     ESSID:"asdf"
11:07:09.103046    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:09.205553    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:09.307959    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:16.194520    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:16.194617    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:16.194669    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)
11:07:16.194719    eth0     Custom driver event:Received a probe from client to 00:09:5B:D4:C0:E0  (00)

This is where I'm at. 

<-- snip -->

Also, bellow I comment on what I'm seeing.

> Configuration file '/etc/wpa_supplicant.conf' -> '/etc/wpa_supplicant.conf'
> Reading configuration file '/etc/wpa_supplicant.conf'
> ctrl_interface='/var/run/wpa_supplicant'
> ctrl_interface_group=10 (from group name 'wheel')
> Priority group 10
>    id=0 ssid='jkm private'
> EAPOL: SUPP_PAE entering state DISCONNECTED
> EAPOL: KEY_RX entering state NO_KEY_RECEIVE
> EAPOL: SUPP_BE entering state INITIALIZE
> EAP: EAP entering state DISABLED
> EAPOL: External notification - portEnabled=0
> EAPOL: External notification - portValid=0
> Own MAC address: 00:06:25:11:57:6c
> wpa_driver_wext_set_wpa
> SIOCGIWRANGE: WE(compiled)=18 WE(source)=18 enc_capa=0xf
> wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
> wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
> wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
> wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
> wpa_driver_wext_set_countermeasures
> wpa_driver_wext_set_drop_unencrypted
> Setting scan request: 0 sec 100000 usec
> Wireless event: cmd=0x8b15 len=20
> Wireless event: new AP: 00:00:00:00:00:00
> EAPOL: External notification - portEnabled=0
> EAPOL: External notification - portValid=0
> Disconnect event - remove keys
> wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
> wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
> wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
> wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
> wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
> Starting AP scan (specific SSID)
> Scan SSID - hexdump_ascii(len=11):
>      6a 6b 6d 20 70 72 69 76 61 74 65                  jkm private     
> Wireless event: cmd=0x8b19 len=12
> Received 236 bytes of scan results (1 BSSes)
> Scan results: 1
> Selecting BSS from priority group 10
> 0: 00:09:5b:95:e0:4e ssid='jkm private' wpa_ie_len=26 rsn_ie_len=0
>    selected
> Trying to associate with 00:09:5b:95:e0:4e (SSID='jkm private' freq=2412 MHz)
> Cancelling scan request
> Automatic auth_alg selection: 0x1
> WPA: using IEEE 802.11i/D3.0
> WPA: using GTK CCMP
> WPA: using PTK CCMP
> WPA: using KEY_MGMT WPA-PSK
> WPA: Own WPA IE - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 04 01 00 00 50 f2 04 01 00 00 50 f2 02

I get this line and then:

WPA: Own WPA IE - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
Setting authentication timeout: 5 sec 0 usec
EAPOL: External notification - EAP success=0
EAPOL: External notification - EAP fail=0
EAPOL: External notification - portControl=Auto
Wireless event: cmd=0x8c02 len=74
Custom wireless event: 'Received a beacon from an unkown AP to 00:09:5B:D4:C0:E0  (00)'
Wireless event: cmd=0x8c02 len=67
Custom wireless event: 'Received a probe from client to 00:09:5B:D4:C0:E0  (00)'
Wireless event: cmd=0x8b1a len=16
Wireless event: cmd=0x8c02 len=67
Custom wireless event: 'Received a probe from client to 00:09:5B:D4:C0:E0  (00)'
Wireless event: cmd=0x8c02 len=67
Custom wireless event: 'Received a probe from client to 00:09:5B:D4:C0:E0  (00)'
Wireless event: cmd=0x8c02 len=67
Custom wireless event: 'Received a probe from client to 00:09:5B:D4:C0:E0  (00)'
Authentication with 00:00:00:00:00:00 timed out.

It seems evident to me AUTH/ASSOC in MLME extended mode are not being
sent out. I am not sure why and am trying to figure it out.
Suggestions/comments are welcomed.

	Luis

-- 
GnuPG Key fingerprint = 113F B290 C6D2 0251 4D84  A34A 6ADD 4937 E20A 525E