WPA Supplicant connection / EAPOL not doing its magic

Mike van Niekerk mvniekerk at gmail.com
Wed Oct 28 11:04:52 EDT 2009


Hi all
I need pointers as what is causing a problem on a WEXT-driver WPA2 connection.

This is my methodology:
1) Disconnect from any connections via the DISCONNECT command
2) Send the settings/keys for an AP to wpa_supplicant with ADD NETWORK et al
3) Enable the network
4) If wpa_supplicant is not SCANNING/DISCONNECTED, then fire RECONNECT

The wpa_supplicant goes all the way to being ASSOCIATED, but the EAPOL
part is lacking:

State: ASSOCIATING -> ASSOCIATED

CTRL-EVENT-STATE-CHANGE id=0 state=4

CTRL_IFACE monitor send - hexdump(len=38): 2f 64 61 74 61 2f 6d 69 73
63 2f 77 69 66 69 2f 73 6f 63 6b 65 74 73 2f 77 70 61 5f 63 74 72 6c
5f 34 38 2d 32 00

wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)

WEXT: Operstate: linkmode=-1, operstate=5

Associated to a new BSS: BSSID=00:22:6b:59:de:a6

No keys have been configured - skip key clearing

Associated with 00:22:6b:59:de:a6

CTRL_IFACE monitor send - hexdump(len=38): 2f 64 61 74 61 2f 6d 69 73
63 2f 77 69 66 69 2f 73 6f 63 6b 65 74 73 2f 77 70 61 5f 63 74 72 6c
5f 34 38 2d 32 00

WPA: Association event - clear replay counter

EAPOL: External notification - portEnabled=0

EAPOL: External notification - portValid=0

EAPOL: External notification - EAP success=0

EAPOL: External notification - portEnabled=1

EAPOL: SUPP_PAE entering state CONNECTING

EAPOL: SUPP_BE entering state IDLE

Setting authentication timeout: 30 sec 0 usec

Cancelling scan request

RX ctrl_iface - hexdump_ascii(len=9):

     41 50 5f 53 43 41 4e 20 31                        AP_SCAN 1

>>>IF AP_SCAN 1


RX ctrl_iface - hexdump_ascii(len=12):

     53 43 41 4e 5f 52 45 53 55 4c 54 53               SCAN_RESULTS

>>>IF SCAN_RESULTS

RX ctrl_iface - hexdump_ascii(len=12):

     53 43 41 4e 5f 52 45 53 55 4c 54 53               SCAN_RESULTS

>>>IF SCAN_RESULTS

EAPOL: startWhen --> 0

EAPOL: SUPP_PAE entering state CONNECTING

EAPOL: txStart

KEY_MGMT: PSK

WPA: drop TX EAPOL in non-IEEE 802.1X mode (type=1 len=0)

This will ultimately time out.

The bummer is - when saving this config to the config file, rebooting
the devices so that wpa_supplicant must pick up its state from the
config file (saved by the parameters given above), it works:
State: SCANNING -> ASSOCIATING

CTRL-EVENT-STATE-CHANGE id=-1 state=3

wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)

WEXT: Operstate: linkmode=-1, operstate=5

wpa_driver_wext_associate

D/StatusBar(   42): updateResources

W/ActivityManager(   42): Unable to start service Intent {
action=com.android.ussd.IExtendedNetworkService }: not found

D/PhoneApp(   90): Resetting audio state/mode: IDLE

D/dalvikvm(   92): GC freed 2676 objects / 179256 bytes in 156ms

unifi0: wlan0: link is up

I/ActivityManager(   42): Start proc com.android.mms for broadcast
com.android.mms/.transaction.SmsReceiver: pid=114 uid=10004
gids={3003}

I/ActivityManager(   42): processNextBroadcast: waiting for
ProcessRecord{436d7b60 114:com.android.mms/10004}

unifi0: Associated with "android-test"

Setting authentication timeout: 20 sec 0 usec

EAPOL: External notification - EAP success=0

EAPOL: External notification - EAP fail=0

EAPOL: External notification - portControl=Auto

RSN: Ignored PMKID candidate without preauth flag

RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])

Wireless event: cmd=0x8b06 len=8

RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])

Wireless event: cmd=0x8b04 len=12

RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])

Wireless event: cmd=0x8b1a len=20

RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])

Wireless event: cmd=0x8c07 len=30

AssocReq IE wireless event - 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

RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])

Wireless event: cmd=0x8c08 len=61

AssocResp IE wireless event - hexdump(len=53): 01 08 82 84 8b 96 24 30
48 6c 32 04 0c 12 18 60 dd 09 00 10 18 02 00 f0 00 00 00 dd 18 00 50
f2 02 01 01 80 00 03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00

RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])

Wireless event: cmd=0x8b15 len=20

Wireless event: new AP: 00:22:6b:59:de:a6

Received 816 bytes of scan results (3 BSSes)

wpa_driver_wext_update_beacon_ies: - hexdump(len=26): 30 18 01 00 00
0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00

Association info event

req_ies - 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

resp_ies - hexdump(len=53): 01 08 82 84 8b 96 24 30 48 6c 32 04 0c 12
18 60 dd 09 00 10 18 02 00 f0 00 00 00 dd 18 00 50 f2 02 01 01 80 00
03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00

beacon_ies - hexdump(len=26): 30 18 01 00 00 0f ac 02 02 00 00 0f ac
04 00 0f ac 02 01 00 00 0f ac 02 0c 00

WPA: set own WPA/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

WPA: set AP RSN IE - hexdump(len=26): 30 18 01 00 00 0f ac 02 02 00 00
0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00

WPA: clearing AP WPA IE

State: ASSOCIATING -> ASSOCIATED

CTRL-EVENT-STATE-CHANGE id=0 state=4

wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)

WEXT: Operstate: linkmode=-1, operstate=5

Associated to a new BSS: BSSID=00:22:6b:59:de:a6

No keys have been configured - skip key clearing

Associated with 00:22:6b:59:de:a6

WPA: Association event - clear replay counter

EAPOL: External notification - portEnabled=0

EAPOL: External notification - portValid=0

EAPOL: External notification - EAP success=0

EAPOL: External notification - portEnabled=1

EAPOL: SUPP_PAE entering state CONNECTING

EAPOL: SUPP_BE entering state IDLE

Setting authentication timeout: 30 sec 0 usec

Cancelling scan request

RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])

RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added

RX EAPOL from 00:22:6b:59:de:a6

RX EAPOL - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00
00 00 03 de 3b 4f 84 5e 7c a7 34 d2 28 be a2 82 20 7d ee 94 5e cf 68
21 0e 13 d8 2b 03 bc 57 f9 f0 3e b5 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

Setting authentication timeout: 20 sec 0 usec

D/BT HSHFP(   90): Starting BluetoothHeadsetService

IEEE 802.1X RX: version=2 type=3 length=95

  EAPOL-Key type=2

  key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)

  key_length=16 key_data_length=0

  replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 03

  key_nonce - hexdump(len=32): de 3b 4f 84 5e 7c a7 34 d2 28 be a2 82
20 7d ee 94 5e cf 68 21 0e 13 d8 2b 03 bc 57 f9 f0 3e b5

  key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

  key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00

  key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00

  key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

WPA: RX EAPOL-Key - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00
00 00 00 00 00 03 de 3b 4f 84 5e 7c a7 34 d2 28 be a2 82 20 7d ee 94
5e cf 68 21 0e 13 d8 2b 03 bc 57 f9 f0 3e b5 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

State: ASSOCIATED -> 4WAY_HANDSHAKE

CTRL-EVENT-STATE-CHANGE id=0 state=5

WPA: RX message 1 of 4-Way Handshake from 00:22:6b:59:de:a6 (ver=2)

RSN: msg 1/4 key data - hexdump(len=0):

WPA: Renewed SNonce - hexdump(len=32): e4 89 15 2c 95 7e 42 77 c4 77
82 7d d5 05 ab 37 4a 02 22 3c bd 1c 50 a6 2f e3 73 61 3d da cb f7

WPA: PMK - hexdump(len=32): [REMOVED]

WPA: PTK - hexdump(len=64): [REMOVED]

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 02 00 00

WPA: Sending EAPOL-Key 2/4

WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 01 0a 00 00 00 00
00 00 00 00 00 03 e4 89 15 2c 95 7e 42 77 c4 77 82 7d d5 05 ab 37 4a
02 22 3c bd 1c 50 a6 2f e3 73 61 3d da cb f7 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 f5 22 96 db f3 8f c3 97 f8 a1 ba 50 38 11 b2 dd 00 16 30 14 01 00
00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00

W/SurfaceComposerClient(   42): lock_layer timed out (is the CPU
pegged?) layer=0, lcblk=0x41045020, state=00000000 (was 00000013)

W/SurfaceComposerClient(   42): lock_layer() timed out but didn't
appear to need to be locked and we recovered (layer=0,
lcblk=0x41045020, state=00000000)

D/HomeLoaders(   92): load applications

D/HomeLoaders(   92): loading user items

D/HomeLoaders(   92):   --> starting workspace loader

D/dalvikvm(   42): GC freed 4152 objects / 184960 bytes in 181ms

RX EAPOL from 00:22:6b:59:de:a6

RX EAPOL - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00
00 00 04 de 3b 4f 84 5e 7c a7 34 d2 28 be a2 82 20 7d ee 94 5e cf 68
21 0e 13 d8 2b 03 bc 57 f9 f0 3e b5 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

IEEE 802.1X RX: version=2 type=3 length=95

  EAPOL-Key type=2

  key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)

  key_length=16 key_data_length=0

  replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 04

Iunifi0: siwencodeext: flags=0x1, alg=3, ext_flags=0xA, key_len=16,

//system/bin/wpa_supplicant(   83):   key_nonce - hexdump(len=32): de
3b 4f 84 5e 7c a7 34 d2 28unifi0:               addr=00:22:6B:59:DE:A6

 be a2 82 20 7d ee 94 5e cf 68 2unifi0: SETKEYS: key 0, len 16, CSS=00:0f:ac:04

         addr=00:22:6b:59:d

1 0e 13 d8 2b 03 bc 57 f9 f0 3e b5

  key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

  key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00

  key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00

  key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

WPA: RX EAPOL-Key - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00
00 00 00 00 00 04 de 3b 4f 84 5e 7c a7 34 d2 28 be a2 82 20 7d ee 94
5e cf 68 21 0e 13 d8 2b 03 bc 57 f9 f0 3e b5 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE

CTRL-EVENT-STATE-CHANGE id=0 state=5

WPA: RX message 1 of 4-Way Handshake from 00:22:6b:59:de:a6 (ver=2)

RSN: msg 1/4 key data - hexdump(len=0):

WPA: PMK - hexdump(len=32): [REMOVED]

WPA: PTK - hexdump(len=64): [REMOVED]

WPA: WPunifi0: siwencodeext: flags=0x3, alg=2, ext_flags=0x6, key_len=32,

A 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 02 00 00

WPA: Sending EAPOL-Key 2/4

WPA: TX EAPOL-Key - hexdump(len=121unifi0:               addr=FF:FF:FF:FF:FF:FF

): 01 03 00 75 02 01 0a 00 00 00unifi0: SETKEYS: key 2, len 32, CSS=00:0f:ac:02

         addr=ff:ff:ff:ff:f

 00 00 00 00 00 00 04 e4 89 15 2c 95 7e 42 77 c4 77 82 7d d5 05 ab 37
4a 02 22 3c bd 1c 50 a6 2f e3 73 61 3d da cb f7 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 79 e1 08 ab 87 01 bf 6b b0 63 3a ea 3e ca 40 d7 00 16 30 14 01
00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00

D/StatusBar(   42): updateResources

D/HomeLoaders(   92):   --> starting applications loader

RX EAPOL from 00:22:6b:59:de:a6

RX EAPOL - hexdump(len=179): 02 03 00 af 02 13 ca 00 10 00 00 00 00 00
00 00 05 de 3b 4f 84 5e 7c a7 34 d2 28 be a2 82 20 7d ee 94 5e cf 68
21 0e 13 d8 2b 03 bc 57 f9 f0 3e b5 94 5e cf 68 21 0e 13 d8 2b 03 bc
57 f9 f0 3e b6 89 27 02 00 00 00 00 00 00 00 00 00 00 00 00 00 b3 56
25 be f9 22 cc eb bf eb f1 8b 32 17 a3 76 00 50 f7 aa 30 4a a3 7f 62
c8 01 40 71 91 45 5c 7d 4f ee 18 0b c7 6f 1e 37 03 cf 9b 5b 9c fb c9
0c 70 9d 1b f9 cd 84 d4 4a b7 75 d7 0f 3a 24 f6 2b 55 24 e2 bb 6a a5
79 11 4a bd eb 8d f7 e3 6b 16 c8 f3 09 0c 34 9d f4 56 6c 18 fd 64 7d
72 09 a9 53

IEEE 802.1X RX: version=2 type=3 length=175

  EAPOL-Key type=2

  key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)

  key_length=16 key_data_length=80

  replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 05

  key_nonce - hexdump(len=32): de 3b 4f 84 5e 7c a7 34 d2 28 be a2 82
20 7d ee 94 5e cf 68 21 0e 13 d8 2b 03 bc 57 f9 f0 3e b5

  key_iv - hexdump(len=16): 94 5e cf 68 21 0e 13 d8 2b 03 bc 57 f9 f0 3e b6

  key_rsc - hexdump(len=8): 89 27 02 00 00 00 00 00

  key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00

  key_mic - hexdump(len=16): b3 56 25 be f9 22 cc eb bf eb f1 8b 32 17 a3 76

WPA: RX EAPOL-Key - hexdump(len=179): 02 03 00 af 02 13 ca 00 10 00 00
00 00 00 00 00 05 de 3b 4f 84 5e 7c a7 34 d2 28 be a2 82 20 7d ee 94
5e cf 68 21 0e 13 d8 2b 03 bc 57 f9 f0 3e b5 94 5e cf 68 21 0e 13 d8
2b 03 bc 57 f9 f0 3e b6 89 27 02 00 00 00 00 00 00 00 00 00 00 00 00
00 b3 56 25 be f9 22 cc eb bf eb f1 8b 32 17 a3 76 00 50 f7 aa 30 4a
a3 7f 62 c8 01 40 71 91 45 5c 7d 4f ee 18 0b c7 6f 1e 37 03 cf 9b 5b
9c fb c9 0c 70 9d 1b f9 cd 84 d4 4a b7 75 d7 0f 3a 24 f6 2b 55 24 e2
bb 6a a5 79 11 4a bd eb 8d f7 e3 6b 16 c8 f3 09 0c 34 9d f4 56 6c 18
fd 64 7d 72 09 a9 53

RSN: encrypted key data - hexdump(len=80): f7 aa 30 4a a3 7f 62 c8 01
40 71 91 45 5c 7d 4f ee 18 0b c7 6f 1e 37 03 cf 9b 5b 9c fb c9 0c 70
9d 1b f9 cd 84 d4 4a b7 75 d7 0f 3a 24 f6 2b 55 24 e2 bb 6a a5 79 11
4a bd eb 8d f7 e3 6b 16 c8 f3 09 0c 34 9d f4 56 6c 18 fd 64 7d 72 09
a9 53

WPA: decrypted EAPOL-Key key data - hexdump(len=72): [REMOVED]

State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE

CTRL-EVENT-STATE-CHANGE id=0 state=5

WPA: RX message 3 of 4-Way Handshake from 00:22:6b:59:de:a6 (ver=2)

WPA: IE KeyData - hexdump(len=72): 30 18 01 00 00 0f ac 02 02 00 00 0f
ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00 dd 26 00 0f ac 01 02 00 3f
9f 7f 18 d9 fc 46 ee 6d 44 ed de 02 df ff 27 26 82 71 ef 28 29 5a af
e9 2b 2a 50 e2 4c c1 ff dd 00 00 00 00 00

WPA: Sending EAPOL-Key 4/4

WPA: TX EAPOL-Key - hexdump(len=99): 01 03 00 5f 02 03 0a 00 00 00 00
00 00 00 00 00 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00 7f 91 72 7c 83 86 a9 4c da 28 08 42 1b 61 a0 94 00 00

WPA: Installing PTK to the driver.

wpa_driver_wext_set_key: alg=3 key_idx=0 set_tx=1 seq_len=6 key_len=16

I/ActivityManager(   42): Start proc com.android.inputmethod.latin for
service com.android.inputmethod.latin/.LatinIME: pid=129 uid=10002
gids={3003}

EAPOL: External notification - portValid=1

State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE

CTRL-EVENT-STATE-CHANGE id=0 state=6

RSN: received GTK in pairwise handshake - hexdump(len=34): [REMOVED]

WPA: Group Key - hexdump(len=32): [REMOVED]

WPA: Installing GTK to the driver (keyidx=2 tx=0).

WPA: RSC - hexdump(len=6): 89 27 02 00 00 00

wpa_driver_wext_set_key: alg=2 key_idx=2 set_tx=0 seq_len=6 key_len=32

D/HomeLoaders(   92):   --> wait for applications loader

WPA: Key negotiation completed with 00:22:6b:59:de:a6 [PTK=CCMP GTK=TKIP]

Cancelling authentication timeout

State: GROUP_HANDSHAKE -> COMPLETED

CTRL-EVENT-STATE-CHANGE id=0 state=7

CTRL-EVENT-CONNECTED - Connection to 00:22:6b:59:de:a6 completed
(auth) [id=0 id_str=]

wpa_driver_wext_set_operstate: operstate 0->1 (UP)

WEXT: Operstate: linkmode=-1, operstate=6

EAPOL: External notification - portValid=1

EAPOL: External notification - EAP success=1

EAPOL: SUPP_PAE entering state AUTHENTICATING

EAPOL: SUPP_BE entering state SUCCESS

EAP: EAP entering state DISABLED

EAPOL: SUPP_PAE entering state AUTHENTICATED

EAPOL: SUPP_BE entering state IDLE

RTM_NEWLINK: operstate=1 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP])

RTM_NEWLINK, IFLA_IFNAME: Interface 'wlan0' added

D/dalvikvm(   90): GC freed 4328 objects / 246824 bytes in 327ms

CTRL_IFACE monitor attached - hexdump(len=38): 2f 64 61 74 61 2f 6d 69
73 63 2f 77 69 66 69 2f 73 6f 63 6b 65 74 73 2f 77 70 61 5f 63 74 72
6c 5f 34 32 2d 32 00

Thus -> Give it config settings = No show
--> Save same config settings, close, reboot, reread from config file
= working connection.

I hope someone can help me.

Best regards
Mike


More information about the HostAP mailing list