FW: [wpa_supplicant] Most WPA AP:s dont get to WPA_4WAY_HANDSHAKE state when wrong PSK is supplied

[Paul Stewart]

That's both not quite enough and a little inconsistent with the
premise of your original post.  Your log is showing that indeed the
supplicant entered the 4WAY_HANDSHAKE state, that it received the 1/4
and has transmitted the 2/4.  What would be most interesting is what
happens right after that -- the cause for your disconnect.  One
possible case is that after receiving the 2/4 the AP sends down a
DEAUTH/DISASSOC, and the timing is such that wpa_supplicant had not
yet gotten around to sending the 4WAY_HANDSHAKE state change over
DBus.  What DBus interface are you using?  The new DBus interface can
swallow state changes if they happen fast enough.

However all of the above is speculation.  Another 20 lines of logfile
and we can get to the bottom of it.

--
Paul

On Mon, Dec 13, 2010 at 8:34 AM, Olsson, Ola1
<Ola1.Olsson at sonyericsson.com> wrote:
> Thanks for caring. I have made it as small as possible. Just tell me if you want the whole logs. I will provide them in that case:
>
> Bad PSK on a bad AP
>
> D/wpa_supplicant( ?888): Wireless event: cmd=0x8b15 len=20
> D/wpa_supplicant( ?888): Wireless event: new AP: 00:00:00:00:00:00
> D/wpa_supplicant( ?888): BSSID 00:11:5c:35:1c:73 blacklist count incremented to 2
> I/wpa_supplicant( ?888): CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
> D/wpa_supplicant( ?888): wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
> D/wpa_supplicant( ?888): wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
> D/wpa_supplicant( ?888): wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
> D/wpa_supplicant( ?888): wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
> D/wpa_supplicant( ?888): wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
> D/wpa_supplicant( ?888): State: ASSOCIATING -> DISCONNECTED
>
>
> Bad PSK on a good AP (Dlink DIR-635)
> D/wpa_supplicant( ?888): Wireless event: cmd=0x8b15 len=20
> D/wpa_supplicant( ?888): Wireless event: new AP: 00:0c:e3:6b:8e:cd
> D/wpa_supplicant( ?888): Association info event
> D/wpa_supplicant( ?888): WPA: clearing AP WPA IE
> D/wpa_supplicant( ?888): WPA: clearing AP RSN IE
> D/wpa_supplicant( ?888): State: ASSOCIATING -> ASSOCIATED
> I/wpa_supplicant( ?888): CTRL-EVENT-STATE-CHANGE id=1 state=4 BSSID=00:0c:e3:6b:8e:cd
> D/wpa_supplicant( ?888): wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
> D/wpa_supplicant( ?888): WEXT: Operstate: linkmode=-1, operstate=5
> D/wpa_supplicant( ?888): Associated to a new BSS: BSSID=00:0c:e3:6b:8e:cd
> D/wpa_supplicant( ?888): No keys have been configured - skip key clearing
> I/wpa_supplicant( ?888): Associated with 00:0c:e3:6b:8e:cd
> D/wpa_supplicant( ?888): WPA: Association event - clear replay counter
> D/wpa_supplicant( ?888): WPA: Clear old PTK
> D/wpa_supplicant( ?888): EAPOL: External notification - portEnabled=0
> D/wpa_supplicant( ?888): EAPOL: External notification - portValid=0
> D/wpa_supplicant( ?888): EAPOL: External notification - EAP success=0
> D/wpa_supplicant( ?888): EAPOL: External notification - portEnabled=1
> D/wpa_supplicant( ?888): EAPOL: SUPP_PAE entering state CONNECTING
> D/wpa_supplicant( ?888): EAPOL: enable timer tick
> D/wpa_supplicant( ?888): EAPOL: SUPP_BE entering state IDLE
> D/wpa_supplicant( ?888): Setting authentication timeout: 10 sec 0 usec
> D/wpa_supplicant( ?888): Cancelling scan request
> D/wpa_supplicant( ?888): RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
> D/wpa_supplicant( ?888): RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
> D/wpa_supplicant( ?888): Wireless event: cmd=0x8c02 len=164
> D/wpa_supplicant( ?888): CMD: GET_NETWORK 0 password
> D/wpa_supplicant( ?888): CTRL_IFACE: GET_NETWORK id=0 name='password'
> D/wpa_supplicant( ?888): CTRL_IFACE: Failed to get network variable 'password'
> D/wpa_supplicant( ?888): RX EAPOL from 00:0c:e3:6b:8e:cd
> D/wpa_supplicant( ?888): Setting authentication timeout: 10 sec 0 usec
> D/wpa_supplicant( ?888): IEEE 802.1X RX: version=2 type=3 length=95
> D/wpa_supplicant( ?888): ? EAPOL-Key type=2
> D/wpa_supplicant( ?888): ? key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
> D/wpa_supplicant( ?888): ? key_length=16 key_data_length=0
> D/wpa_supplicant( ?888): State: ASSOCIATED -> 4WAY_HANDSHAKE
> I/wpa_supplicant( ?888): CTRL-EVENT-STATE-CHANGE id=1 state=5 BSSID=00:00:00:00:00:00
> D/wpa_supplicant( ?888): WPA: RX message 1 of 4-Way Handshake from 00:0c:e3:6b:8e:cd (ver=2)
> D/wpa_supplicant( ?888): WPA: PTK derivation - A1=6c:23:b9:e3:b3:f9 A2=00:0c:e3:6b:8e:cd
> D/wpa_supplicant( ?888): WPA: Sending EAPOL-Key 2/4
> .
> .
> .
>
> -----Original Message-----
> From: Helmut Schaa [mailto:helmut.schaa at googlemail.com]
> Sent: den 12 december 2010 11:44
> To: hostap at lists.shmoo.com
> Cc: Olsson, Ola1; 'Paul Stewart'; Jouni Malinen
> Subject: Re: FW: [wpa_supplicant] Most WPA AP:s dont get to WPA_4WAY_HANDSHAKE state when wrong PSK is supplied
>
> Am Sonntag, 12. Dezember 2010 schrieb Olsson, Ola1:
>> I am not actually not sure, i have not yet been able to get the sniffer
>> logs from the scenario but from the supplicant logs I get into
>> driver_wext_event_wireless SIOCGIWAP. Here, there are two ways for the
>> code to go, either to send an EVENT_ASSOCIATE or and EVENT_DISASSOC.
>> Everytime the wrong psk is given, we end up in EVENT_DISASSOC because
>> the is_zero_ether_addr() is true, otherwise we end up in EVENT_ASSOC.
>
> Mind to provide the wpa_supplicant log (with -ddt)?
>
> Helmut
>