Help understanding failed 4-way handshake

Joshua ChaitinPollak jpollak at kivasystems.com
Wed Nov 14 13:10:47 EST 2007


Hello,

I have a mobile device that is using madwifi 0.9.3 and wpa_supplicant
0.5.7. I'm using -dwext and ap_scan=2, connecting to a WPA2 wireless lan
with around 10 APs.

Sometimes when the mobile unit moves out of range of one AP and into
range of another, the 4-way handshake fails. At this point, I'm just
trying to understand why. 

Eventually, after about 30 seconds, and 6 attempts, we get a successful
association, but I'd like to know why the first 5 attempts fail.

Any help deciphering the logs would be appreciated.

Thanks,

Josh


Here is what I see (this is just the 1st failed attempt):

Feb  4 01:15:00 wpa: State: DISCONNECTED -> SCANNING 
Feb  4 01:15:00 wpa: Trying to associate with SSID 'XXXXX' 
Feb  4 01:15:00 wpa: Cancelling scan request 
Feb  4 01:15:00 wpa: WPA: clearing own WPA/RSN IE 
Feb  4 01:15:00 wpa: Automatic auth_alg selection: 0x1 
Feb  4 01:15:00 wpa: WPA: No WPA/RSN IE available from association info 
Feb  4 01:15:00 wpa: WPA: Set cipher suites based on configuration 
Feb  4 01:15:00 wpa: WPA: Selected cipher suites: group 30 pairwise 24
key_mgmt 2 proto 2 
Feb  4 01:15:00 wpa: WPA: clearing AP WPA IE 
Feb  4 01:15:00 wpa: WPA: clearing AP RSN IE 
Feb  4 01:15:00 wpa: WPA: using GTK CCMP 
Feb  4 01:15:00 wpa: WPA: using PTK CCMP 
Feb  4 01:15:00 wpa: WPA: using KEY_MGMT WPA-PSK 
Feb  4 01:15:00 wpa: WPA: Set own WPA IE default - hexdump(len=22): 30
14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 
Feb  4 01:15:00 wpa: No keys have been configured - skip key clearing 
Feb  4 01:15:00 wpa: wpa_driver_wext_set_drop_unencrypted 
Feb  4 01:15:00 wpa: State: SCANNING -> ASSOCIATING 
Feb  4 01:15:00 wpa: wpa_driver_wext_set_operstate: operstate 0->0
(DORMANT) 
Feb  4 01:15:00 wpa: WEXT: Operstate: linkmode=-1, operstate=5 
Feb  4 01:15:00 wpa: wpa_driver_wext_associate 
Feb  4 01:15:00 wpa: Setting authentication timeout: 60 sec 0 usec 
Feb  4 01:15:00 wpa: EAPOL: External notification - EAP success=0 
Feb  4 01:15:00 wpa: EAPOL: External notification - EAP fail=0 
Feb  4 01:15:00 wpa: EAPOL: External notification - portControl=Auto 
Feb  4 01:15:00 wpa: RTM_NEWLINK: operstate=0 ifi_flags=0x1023 ([UP]) 
Feb  4 01:15:00 wpa: Wireless event: cmd=0x8b06 len=8 
Feb  4 01:15:00 wpa: RTM_NEWLINK: operstate=0 ifi_flags=0x1023 ([UP]) 
Feb  4 01:15:00 wpa: Wireless event: cmd=0x8b1a len=15 
Feb  4 01:15:00 wpa: RX EAPOL from 00:a0:f8:ec:f3:6a 
Feb  4 01:15:00 wpa: IEEE 802.1X RX: version=1 type=3 length=117 
Feb  4 01:15:00 wpa:   EAPOL-Key type=2 
Feb  4 01:15:00 wpa:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise
Ack) 
Feb  4 01:15:00 wpa:   key_length=16 key_data_length=22 
Feb  4 01:15:00 wpa:   replay_counter - hexdump(len=8): 00 00 00 00 00
00 00 01 
Feb  4 01:15:00 wpa:   key_nonce - hexdump(len=32): c1 6a 9c 22 b2 27 ab
fe 6b 10 61 6e 62 45 b6 76 c6 d0 f4 73 5d 45 0a 13 8c 27 93 e5 40 0c 04
64 
Feb  4 01:15:00 wpa:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 
Feb  4 01:15:00 wpa:   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00
00 
Feb  4 01:15:00 wpa:   key_id (reserved) - hexdump(len=8): 00 00 00 00
00 00 00 00 
Feb  4 01:15:00 wpa:   key_mic - hexdump(len=16): 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 
Feb  4 01:15:00 wpa: WPA: EAPOL-Key Replay Counter did not increase -
dropping packet 
Feb  4 01:15:00 wpa: RTM_NEWLINK: operstate=0 ifi_flags=0x1023 ([UP]) 
Feb  4 01:15:00 wpa: Wireless event: cmd=0x8b19 len=8 
Feb  4 01:15:00 wpa: Scan results did not fit - trying larger buffer
(8192 bytes) 
Feb  4 01:15:00 wpa: Scan results did not fit - trying larger buffer
(16384 bytes) 
Feb  4 01:15:00 wpa: Received 13699 bytes of scan results (61 BSSes) 
Feb  4 01:15:00 wpa: Scan results: 61 
Feb  4 01:15:00 wpa: RTM_NEWLINK: operstate=0 ifi_flags=0x11023
([UP][LOWER_UP]) 
Feb  4 01:15:00 wpa: Wireless event: cmd=0x8b15 len=20 
Feb  4 01:15:00 wpa: Wireless event: new AP: 00:a0:f8:ec:f3:be 
Feb  4 01:15:00 wpa: State: ASSOCIATING -> ASSOCIATED 
Feb  4 01:15:00 wpa: wpa_driver_wext_set_operstate: operstate 0->0
(DORMANT) 
Feb  4 01:15:00 wpa: WEXT: Operstate: linkmode=-1, operstate=5 
Feb  4 01:15:00 wpa: Associated to a new BSS: BSSID=00:a0:f8:ec:f3:be 
Feb  4 01:15:00 wpa: No keys have been configured - skip key clearing 
Feb  4 01:15:00 wpa: Network configuration found for the current AP 
Feb  4 01:15:00 wpa: WPA: Using WPA IE from AssocReq to set cipher
suites 
Feb  4 01:15:00 wpa: WPA: Selected cipher suites: group 16 pairwise 16
key_mgmt 2 proto 2 
Feb  4 01:15:00 wpa: WPA: clearing AP WPA IE 
Feb  4 01:15:00 wpa: WPA: clearing AP RSN IE 
Feb  4 01:15:00 wpa: WPA: using GTK CCMP 
Feb  4 01:15:00 wpa: WPA: using PTK CCMP 
Feb  4 01:15:00 wpa: WPA: using KEY_MGMT WPA-PSK 
Feb  4 01:15:00 wpa: WPA: Set own WPA IE default - hexdump(len=22): 30
14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 
Feb  4 01:15:00 wpa: EAPOL: External notification - EAP success=0 
Feb  4 01:15:00 wpa: EAPOL: External notification - EAP fail=0 
Feb  4 01:15:00 wpa: EAPOL: External notification - portControl=Auto 
Feb  4 01:15:00 wpa: Associated with 00:a0:f8:ec:f3:be 
Feb  4 01:15:00 wpa: WPA: Association event - clear replay counter 
Feb  4 01:15:00 wpa: EAPOL: External notification - portEnabled=0 
Feb  4 01:15:00 wpa: EAPOL: External notification - portValid=0 
Feb  4 01:15:00 wpa: EAPOL: External notification - EAP success=0 
Feb  4 01:15:00 wpa: EAPOL: External notification - portEnabled=1 
Feb  4 01:15:00 wpa: EAPOL: SUPP_PAE entering state CONNECTING 
Feb  4 01:15:00 wpa: EAPOL: SUPP_BE entering state IDLE 
Feb  4 01:15:00 wpa: Setting authentication timeout: 10 sec 0 usec 
Feb  4 01:15:00 wpa: Cancelling scan request 
Feb  4 01:15:00 wpa: RTM_NEWLINK: operstate=0 ifi_flags=0x11023
([UP][LOWER_UP]) 
Feb  4 01:15:00 wpa: RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added 
Feb  4 01:15:00 wpa: RX EAPOL from 00:a0:f8:ec:f3:be 
Feb  4 01:15:00 wpa: Setting authentication timeout: 10 sec 0 usec 
Feb  4 01:15:00 wpa: IEEE 802.1X RX: version=1 type=3 length=117 
Feb  4 01:15:00 wpa:   EAPOL-Key type=2 
Feb  4 01:15:00 wpa:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise
Ack) 
Feb  4 01:15:00 wpa:   key_length=16 key_data_length=22 
Feb  4 01:15:00 wpa:   replay_counter - hexdump(len=8): 00 00 00 00 00
00 00 01 
Feb  4 01:15:06 wpa:   key_nonce - hexdump(len=32): d0 66 0c ed b9 0c 8d
3d 8e 73 88 9d be ce 74 25 e0 bf d4 9d bb a7 5a ad 20 dd 2a 36 a0 dd 48
43 
Feb  4 01:15:06 wpa:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 
Feb  4 01:15:06 wpa:   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00
00 
Feb  4 01:15:06 wpa:   key_id (reserved) - hexdump(len=8): 00 00 00 00
00 00 00 00 
Feb  4 01:15:06 wpa:   key_mic - hexdump(len=16): 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 
Feb  4 01:15:06 wpa: State: ASSOCIATED -> 4WAY_HANDSHAKE 
Feb  4 01:15:06 wpa: WPA: RX message 1 of 4-Way Handshake from
00:a0:f8:ec:f3:be (ver=2) 
Feb  4 01:15:06 wpa: RSN: msg 1/4 key data - hexdump(len=22): dd 14 00
0f ac 04 64 32 bd 3c 13 25 b7 04 f6 0f 6a 6a 66 0d 6a aa 
Feb  4 01:15:06 wpa: RSN: PMKID from Authenticator - hexdump(len=16): 64
32 bd 3c 13 25 b7 04 f6 0f 6a 6a 66 0d 6a aa 
Feb  4 01:15:06 wpa: RSN: no matching PMKID found 
Feb  4 01:15:06 wpa: WPA: Renewed SNonce - hexdump(len=32): 44 b1 f9 ed
a2 12 3d 3a 1c da 0d 5e 23 39 78 de c2 92 2d 50 63 ef 25 78 4f 05 ec ef
0e 12 d4 62 
Feb  4 01:15:06 wpa: WPA: PMK - hexdump(len=32): [REMOVED] 
Feb  4 01:15:06 wpa: WPA: PTK - hexdump(len=64): [REMOVED] 
Feb  4 01:15:06 wpa: WPA: WPA IE for msg 2/4 - hexdump(len=22): 30 14 01
00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 
Feb  4 01:15:06 wpa: WPA: Sending EAPOL-Key 2/4 
Feb  4 01:15:06 wpa: EAPOL: startWhen --> 0 
Feb  4 01:15:06 wpa: EAPOL: SUPP_PAE entering state CONNECTING 
Feb  4 01:15:06 wpa: EAPOL: txStart 
Feb  4 01:15:06 wpa: WPA: drop TX EAPOL in non-IEEE 802.1X mode (type=1
len=0) 
Feb  4 01:15:06 wpa: RTM_NEWLINK: operstate=0 ifi_flags=0x1023 ([UP]) 
Feb  4 01:15:06 wpa: Wireless event: cmd=0x8b15 len=20 
Feb  4 01:15:06 wpa: Wireless event: new AP: 00:00:00:00:00:00 
Feb  4 01:15:06 wpa: WPA: 4-Way Handshake failed - pre-shared key may be
incorrect 
Feb  4 01:15:06 wpa: Setting scan request: 0 sec 100000 usec 
Feb  4 01:15:06 wpa: Added BSSID 00:a0:f8:ec:f3:be into blacklist 
Feb  4 01:15:06 wpa: CTRL-EVENT-DISCONNECTED - Disconnect event - remove
keys 
Feb  4 01:15:06 wpa: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0
seq_len=0 key_len=0 
Feb  4 01:15:06 wpa: wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0
seq_len=0 key_len=0 
Feb  4 01:15:06 wpa: wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0
seq_len=0 key_len=0 
Feb  4 01:15:06 wpa: wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0
seq_len=0 key_len=0 
Feb  4 01:15:06 wpa: wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0
seq_len=0 key_len=0 
Feb  4 01:15:06 wpa: State: 4WAY_HANDSHAKE -> DISCONNECTED 
Feb  4 01:15:06 wpa: wpa_driver_wext_set_operstate: operstate 0->0
(DORMANT) 
Feb  4 01:15:06 wpa: WEXT: Operstate: linkmode=-1, operstate=5 
Feb  4 01:15:06 wpa: EAPOL: External notification - portEnabled=0 
Feb  4 01:15:06 wpa: EAPOL: SUPP_PAE entering state DISCONNECTED 
Feb  4 01:15:06 wpa: EAPOL: SUPP_BE entering state INITIALIZE 
Feb  4 01:15:06 wpa: EAPOL: External notification - portValid=0 
Feb  4 01:15:06 wpa: EAPOL: External notification - EAP success=0 
Feb  4 01:15:06 wpa: RTM_NEWLINK: operstate=0 ifi_flags=0x1023 ([UP]) 
Feb  4 01:15:06 wpa: RTM_NEWLINK, IFLA_IFNAME: Interface 'ath0' added 
Feb  4 01:15:06 wpa: State: DISCONNECTED -> SCANNING 
Feb  4 01:15:06 wpa: Trying to associate with SSID 'XXXXX' 




More information about the HostAP mailing list