WPA2 connection issue on embedded ARM system
Dirk Behme
dirk.behme
Wed Nov 18 23:56:35 PST 2009
Dan Williams wrote:
> On Tue, 2009-11-17 at 22:17 +0200, Chuck Tuffli wrote:
>>> -----Original Message-----
>>> From: hostap-bounces at lists.shmoo.com
>>> [mailto:hostap-bounces at lists.shmoo.com] On Behalf Of Dirk Behme
>>> Sent: Tuesday, November 17, 2009 8:32 AM
>>> To: Holger Schurig; hostap at lists.shmoo.com
>>> Subject: Re: WPA2 connection issue on embedded ARM system
>> ...
>>> Anybody with any idea how to further debug this? Could this
>>> be a wrong 'psk' in wpa_supplicant.conf? I double checked it
>>> two times, though...
>> Dirk -
>>
>> It doesn't look like the supplicant has even gotten to the stage (a.k.a
>> 4-way handshake) when the PSK is relevant. You might need to use a
>> wireless sniffer (e.g. wireshark) to figure out what is not working at
>> this early stage.
>
> Except that the supplicant 5 second timeout is way too short, and the
> reason it's picking the 5 second timeout for association is wrong as
> well. Try increasing the interval in the supplicant a bit longer just
> to debug the issue. Try this patch here:
>
> http://cvs.fedoraproject.org/viewvc/F-12/wpa_supplicant/wpa_supplicant-assoc-timeout.patch?view=markup
Some news:
- I got a wpa_supplicant with this patch from Chuck. Thanks for this!
Just to be on the safe side:
# md5sum /usr/sbin/wpa_supplicant
d7bca5c0aa3582c52c754926cef1963a /usr/sbin/wpa_supplicant
- I verified my /etc/network/interfaces and wpa_supplicant.conf on an
other board. It's correct and able to connect.
- On the board we are talking about, there seems to be an issue with
fw 9.70.3p36. "iwlist wlan0 scan" doesn't see anything with p36, while
fw 9.70.3p24 gets result below (so everything below is with p24). On
the other board, which successfully connects, p36 does work, though.
- With Chuck's wpa_supplicant and fw 9.70.3p24 I now get output below
[1]. Seems to be the same like with the shorter timeout?
- For reference the same from the 'working' board [2].
Thanks for all the help and best regards
Dirk
[1] Non working board:
root at overo:~# iwlist wlan0 scan
wlan0 Scan completed :
Cell 01 - Address: 00:1F:3F:12:FA:7D
ESSID:"WLAN-001F3F12FA7D"
Mode:Managed
Frequency:2.462 GHz (Channel 11)
Quality=97/100 Signal level=-51 dBm Noise level=-96 dBm
Encryption key:on
Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 11 Mb/s; 6 Mb/s
9 Mb/s; 12 Mb/s; 18 Mb/s; 24 Mb/s; 36 Mb/s
48 Mb/s; 54 Mb/s
IE: WPA Version 1
Group Cipher : TKIP
Pairwise Ciphers (1) : TKIP
Authentication Suites (1) : PSK
IE: IEEE 802.11i/WPA2 Version 1
Group Cipher : TKIP
Pairwise Ciphers (1) : CCMP
Authentication Suites (1) : PSK
root at overo:~# md5sum /usr/sbin/wpa_supplicant
d7bca5c0aa3582c52c754926cef1963a /usr/sbin/wpa_supplicant
root at overo:~# wpa_supplicant -v
wpa_supplicant v0.6.9
Copyright (c) 2003-2009, Jouni Malinen <j at w1.fi> and contributors
root at overo:~# wpa_supplicant -Dwext -iwlan0 -c/etc/wpa_supplicant.conf
-dddt
....
1255407279.012359: Try to find WPA-enabled AP
1255407279.012390: 0: 00:1f:3f:12:fa:7d ssid='WLAN-001F3F12FA7D'
wpa_ie_len=24 rsn_ie_len=20 caps=0x11
1255407279.012451: selected based on RSN IE
1255407279.012481: selected WPA AP 00:1f:3f:12:fa:7d
ssid='WLAN-001F3F12FA7D'
1255407279.012542: Trying to associate with 00:1f:3f:12:fa:7d
(SSID='WLAN-001F3F12FA7D' freq=2462 MHz)
1255407279.012573: Cancelling scan request
1255407279.012603: WPA: clearing own WPA/RSN IE
1255407279.012695: Automatic auth_alg selection: 0x1
1255407279.012786: RSN: using IEEE 802.11i/D9.0
1255407279.012817: WPA: Selected cipher suites: group 8 pairwise 16
key_mgmt 2 proto 2
1255407279.012847: 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
1255407279.012969: WPA: set AP RSN IE - hexdump(len=22): 30 14 01 00
00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1255407279.013061: WPA: using GTK TKIP
1255407279.013092: WPA: using PTK CCMP
1255407279.013122: WPA: using KEY_MGMT WPA-PSK
1255407279.013183: WPA: Set own WPA IE default - hexdump(len=22): 30
14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f a0
1255407279.013275: No keys have been configured - skip key clearing
1255407279.013305: wpa_driver_wext_set_drop_unencrypted
1255407279.013336: State: SCANNING -> ASSOCIATING
1255407279.013397: wpa_driver_wext_set_operstate: operstate 0->0
(DORMANT)
1255407279.013427: WEXT: Operstate: linkmode=-1, operstate=5
1255407279.013488: wpa_driver_wext_associate
1255407279.013610: wpa_driver_wext_set_psk
1255407279.013732: Association request to the driver failed
1255407279.013763: Setting authentication timeout: 10 sec 0 usec
1255407279.013824: EAPOL: External notification - EAP success=0
1255407279.013854: EAPOL: External notification - EAP fail=0
1255407279.013916: EAPOL: External notification - portControl=Auto
1255407279.013946: RSN: Ignored PMKID candidate without preauth flag
1255407279.014526: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1255407279.014587: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
1255407279.014617: Wireless event: cmd=0x8b06 len=8
1255407279.014678: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1255407279.014709: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
1255407279.014770: Wireless event: cmd=0x8b04 len=12
ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
1255407279.611145: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
([UP][LOWER_UP])
1255407279.611297: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
1255407279.611328: Wireless event: cmd=0x8b15 len=20
1255407279.611389: Wireless event: new AP: 00:1f:3f:12:fa:7d
1255407279.611419: State: ASSOCIATING -> ASSOCIATED
1255407279.611450: wpa_driver_wext_set_operstate: operstate 0->0
(DORMANT)
1255407279.611480: WEXT: Operstate: linkmode=-1, operstate=5
1255407279.611602: Associated to a new BSS: BSSID=00:1f:3f:12:fa:7d
1255407279.611663: No keys have been configured - skip key clearing
1255407279.611694: Associated with 00:1f:3f:12:fa:7d
1255407279.611724: WPA: Association event - clear replay counter
1255407279.611755: WPA: Clear old PTK
1255407279.611785: EAPOL: External notification - portEnabled=0
1255407279.611846: EAPOL: External notification - portValid=0
1255407279.611877: EAPOL: External notification - EAP success=0
1255407279.611907: EAPOL: External notification - portEnabled=1
1255407279.611938: EAPOL: SUPP_PAE entering state CONNECTING
1255407279.611968: EAPOL: enable timer tick
1255407279.611999: EAPOL: SUPP_BE entering state IDLE
1255407279.612060: Setting authentication timeout: 10 sec 0 usec
1255407279.612121: Cancelling scan request
1255407279.612670: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
([UP][LOWER_UP])
1255407279.612701: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
1255407280.612365: EAPOL: startWhen --> 0
1255407280.612487: EAPOL: disable timer tick
1255407280.612518: EAPOL: SUPP_PAE entering state CONNECTING
1255407280.612548: EAPOL: enable timer tick
1255407280.612609: EAPOL: txStart
1255407280.612640: WPA: drop TX EAPOL in non-IEEE 802.1X mode (type=1
len=0)
1255407289.612274: Authentication with 00:1f:3f:12:fa:7d timed out.
1255407289.612396: BSSID 00:1f:3f:12:fa:7d blacklist count incremented
to 2
1255407289.612457: wpa_driver_wext_disassociate
ioctl[SIOCSIWMLME]: Operation not supported
1255407289.612915: No keys have been configured - skip key clearing
1255407289.612976: State: ASSOCIATED -> DISCONNECTED
...
[2] 'Working' board:
....
1255407460.303314: Try to find WPA-enabled AP
1255407460.303344: 0: 00:1f:3f:12:fa:7d ssid='WLAN-001F3F12FA7D'
wpa_ie_len=24 rsn_ie_len=20 caps=0x11
1255407460.303436: selected based on RSN IE
1255407460.303497: selected WPA AP 00:1f:3f:12:fa:7d
ssid='WLAN-001F3F12FA7D'
1255407460.303588: Trying to associate with 00:1f:3f:12:fa:7d
(SSID='WLAN-001F3F12FA7D' freq=2462 MHz)
1255407460.303649: Cancelling scan request
1255407460.303680: WPA: clearing own WPA/RSN IE
1255407460.303771: Automatic auth_alg selection: 0x1
1255407460.303863: RSN: using IEEE 802.11i/D9.0
1255407460.303894: WPA: Selected cipher suites: group 8 pairwise 16
key_mgmt 2 proto 2
1255407460.303924: 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
1255407460.304046: WPA: set AP RSN IE - hexdump(len=22): 30 14 01 00
00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
1255407460.304138: WPA: using GTK TKIP
1255407460.304168: WPA: using PTK CCMP
1255407460.304199: WPA: using KEY_MGMT WPA-PSK
1255407460.304229: WPA: Set own WPA IE default - hexdump(len=22): 30
14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f a0
1255407460.304321: No keys have been configured - skip key clearing
1255407460.304382: wpa_driver_wext_set_drop_unencrypted
1255407460.304412: State: SCANNING -> ASSOCIATING
1255407460.304443: wpa_driver_wext_set_operstate: operstate 0->0
(DORMANT)
1255407460.304504: WEXT: Operstate: linkmode=-1, operstate=5
1255407460.304595: wpa_driver_wext_associate
1255407460.304687: wpa_driver_wext_set_psk
1255407460.304809: Association request to the driver failed
1255407460.304870: Setting authentication timeout: 10 sec 0 usec
1255407460.304931: EAPOL: External notification - EAP success=0
1255407460.304962: EAPOL: External notification - EAP fail=0
1255407460.304992: EAPOL: External notification - portControl=Auto
1255407460.305053: RSN: Ignored PMKID candidate without preauth flag
1255407460.305664: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1255407460.305755: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
1255407460.305786: Wireless event: cmd=0x8b06 len=8
1255407460.305847: RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
1255407460.305877: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
1255407460.305908: Wireless event: cmd=0x8b04 len=12
ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
1255407460.933288: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
([UP][LOWER_UP])
1255407460.933410: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
1255407460.933471: Wireless event: cmd=0x8b15 len=20
1255407460.933502: Wireless event: new AP: 00:1f:3f:12:fa:7d
1255407460.933532: State: ASSOCIATING -> ASSOCIATED
1255407460.933593: wpa_driver_wext_set_operstate: operstate 0->0
(DORMANT)
1255407460.933624: WEXT: Operstate: linkmode=-1, operstate=5
1255407460.933746: Associated to a new BSS: BSSID=00:1f:3f:12:fa:7d
1255407460.933807: No keys have been configured - skip key clearing
1255407460.933837: Associated with 00:1f:3f:12:fa:7d
1255407460.933868: WPA: Association event - clear replay counter
1255407460.933898: WPA: Clear old PTK
1255407460.933929: EAPOL: External notification - portEnabled=0
1255407460.933990: EAPOL: External notification - portValid=0
1255407460.934020: EAPOL: External notification - EAP success=0
1255407460.934051: EAPOL: External notification - portEnabled=1
1255407460.934082: EAPOL: SUPP_PAE entering state CONNECTING
1255407460.934112: EAPOL: enable timer tick
1255407460.934143: EAPOL: SUPP_BE entering state IDLE
1255407460.934875: Setting authentication timeout: 10 sec 0 usec
1255407460.934936: Cancelling scan request
1255407460.934997: RTM_NEWLINK: operstate=0 ifi_flags=0x11003
([UP][LOWER_UP])
1255407460.935058: RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added
1255407460.935150: RX EAPOL from 00:1f:3f:12:fa:7d
1255407460.935211: RX EAPOL - hexdump(len=99): 01 03 00 5f 02 00 8a 00
10 00 00 00 00 00 00 00 01 54 30 85 f9 5f 28 07 470
1255407460.935485: Setting authentication timeout: 10 sec 0 usec
1255407460.935577: IEEE 802.1X RX: version=1 type=3 length=95
1255407460.935607: EAPOL-Key type=2
1255407460.935638: key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
1255407460.935668: key_length=16 key_data_length=0
1255407460.935699: replay_counter - hexdump(len=8): 00 00 00 00 00
00 00 01
1255407460.935760: key_nonce - hexdump(len=32): 54 30 85 f9 5f 28 07
47 90 b9 3e 36 dc 77 f1 97 c8 1f e6 1e f1 f5 f3 0e3
1255407460.935852: key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00
1255407460.935913: key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
1255407460.935974: key_id (reserved) - hexdump(len=8): 00 00 00 00
00 00 00 00
1255407460.936035: key_mic - hexdump(len=16): 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00
1255407460.936096: WPA: RX EAPOL-Key - hexdump(len=99): 01 03 00 5f 02
00 8a 00 10 00 00 00 00 00 00 00 01 54 30 85 f9 5f0
1255407460.936431: State: ASSOCIATED -> 4WAY_HANDSHAKE
1255407460.936462: WPA: RX message 1 of 4-Way Handshake from
00:1f:3f:12:fa:7d (ver=2)
1255407460.936523: RSN: msg 1/4 key data - hexdump(len=0):
1255407460.940856: WPA: Renewed SNonce - hexdump(len=32): 65 92 dc b5
41 67 7a 1c 50 72 4c 01 d3 5c 9f 54 86 a2 8c 5e ce 9
1255407460.941101: WPA: PTK derivation - A1=00:19:88:05:b5:31
A2=00:1f:3f:12:fa:7d
1255407460.941162: WPA: PMK - hexdump(len=32): [REMOVED]
1255407460.941192: WPA: PTK - hexdump(len=64): [REMOVED]
1255407460.941253: WPA: WPA IE for msg 2/4 - hexdump(len=22): 30 14 01
00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 020
1255407460.941345: WPA: Sending EAPOL-Key 2/4
1255407460.941406: WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75
02 01 0a 00 00 00 00 00 00 00 00 00 01 65 92 dc b5 40
1255407461.293945: RX EAPOL from 00:1f:3f:12:fa:7d
1255407461.294006: RX EAPOL - hexdump(len=171): 01 03 00 a7 02 13 ca
00 10 00 00 00 00 00 00 00 02 54 30 85 f9 5f 28 07 4a
1255407461.294433: IEEE 802.1X RX: version=1 type=3 length=167
1255407461.294494: EAPOL-Key type=2
1255407461.294494: key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise
Install Ack MIC Secure Encr)
1255407461.294555: key_length=16 key_data_length=72
1255407461.294586: replay_counter - hexdump(len=8): 00 00 00 00 00
00 00 02
1255407461.294647: key_nonce - hexdump(len=32): 54 30 85 f9 5f 28 07
47 90 b9 3e 36 dc 77 f1 97 c8 1f e6 1e f1 f5 f3 0e3
1255407461.294738: key_iv - hexdump(len=16): a6 a6 a6 a6 a6 a6 a6 a6
00 00 00 00 00 00 00 00
1255407461.294799: key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
1255407461.294860: key_id (reserved) - hexdump(len=8): 00 00 00 00
00 00 00 00
1255407461.294891: key_mic - hexdump(len=16): 53 aa 85 87 7b bc c9
07 78 77 0a 05 32 24 55 33
1255407461.294982: WPA: RX EAPOL-Key - hexdump(len=171): 01 03 00 a7
02 13 ca 00 10 00 00 00 00 00 00 00 02 54 30 85 f9 5a
1255407461.295440: RSN: encrypted key data - hexdump(len=72): cc 50 d5
a0 03 63 74 22 9d da de 76 89 15 39 36 31 48 1c 79a
1255407461.295837: WPA: decrypted EAPOL-Key key data -
hexdump(len=64): [REMOVED]
1255407461.295898: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
1255407461.295928: WPA: RX message 3 of 4-Way Handshake from
00:1f:3f:12:fa:7d (ver=2)
1255407461.295959: WPA: IE KeyData - hexdump(len=64): 30 14 01 00 00
0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 d0
1255407461.296142: WPA: Sending EAPOL-Key 4/4
1255407461.296203: WPA: TX EAPOL-Key - hexdump(len=99): 01 03 00 5f 02
03 0a 00 00 00 00 00 00 00 00 00 02 00 00 00 00 000
1255407461.296661: WPA: Installing PTK to the driver.
1255407461.296752: wpa_driver_wext_set_key: alg=3 key_idx=0 set_tx=1
seq_len=6 key_len=16
1255407461.296936: EAPOL: External notification - portValid=1
1255407461.296997: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
1255407461.297027: RSN: received GTK in pairwise handshake -
hexdump(len=34): [REMOVED]
1255407461.297088: WPA: Group Key - hexdump(len=32): [REMOVED]
1255407461.297119: WPA: Installing GTK to the driver (keyidx=2 tx=0
len=32).
1255407461.297149: WPA: RSC - hexdump(len=6): 00 00 00 00 00 00
1255407461.297180: wpa_driver_wext_set_key: alg=2 key_idx=2 set_tx=0
seq_len=6 key_len=32
1255407461.297302: WPA: Key negotiation completed with
00:1f:3f:12:fa:7d [PTK=CCMP GTK=TKIP]
1255407461.297332: Cancelling authentication timeout
1255407461.297393: State: GROUP_HANDSHAKE -> COMPLETED
1255407461.297424: CTRL-EVENT-CONNECTED - Connection to
00:1f:3f:12:fa:7d completed (auth) [id=0 id_str=]
....
More information about the Hostap
mailing list