Help understanding failed 4-way handshake
Joshua ChaitinPollak
jpollak
Wed Nov 14 10:10:47 PST 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