EAP-Success = failure?
Ryan M. Adamson
adamsonrm
Tue Jan 15 06:52:45 PST 2008
Jouni,
We're running an Interlink RAD-series RADIUS server, v 6.1.4. I'm using
the latest (stable) compiled source for both wpa_supplicant and madwifi
drivers. Our access point is a Cisco Aironet 1200. I've included the
debug logs of both wpa_supplicant and the RADIUS server. It looks like
authentication on the radius end is working.
Here's the full output of wpa_supplicant with -d from the SCANNING state
onward:
State: DISCONNECTED -> SCANNING
Trying to associate with SSID 'ornlwpa'
Cancelling scan request
WPA: clearing own WPA/RSN IE
Automatic auth_alg selection: 0x1
WPA: No WPA/RSN IE available from association info
WPA: Set cipher suites based on configuration
WPA: Selected cipher suites: group 14 pairwise 8 key_mgmt 1 proto 1
WPA: clearing AP WPA IE
WPA: clearing AP RSN IE
WPA: using GTK TKIP
WPA: using PTK TKIP
WPA: using KEY_MGMT 802.1X
WPA: not using MGMT group cipher
WPA: Set own WPA IE default - hexdump(len=24): dd 16 00 50 f2 01 01 00
00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 01
No keys have been configured - skip key clearing
wpa_driver_wext_set_drop_unencrypted
State: SCANNING -> ASSOCIATING
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
WEXT: Operstate: linkmode=-1, operstate=5
wpa_driver_wext_associate
Setting authentication timeout: 60 sec 0 usec
EAPOL: External notification - portControl=Auto
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Wireless event: cmd=0x8b06 len=8
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Wireless event: cmd=0x8b1a len=16
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Wireless event: cmd=0x8b19 len=8
Received 3039 bytes of scan results (13 BSSes)
Scan results: 13
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:14:a9:c8:11:b0
State: ASSOCIATING -> ASSOCIATED
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
WEXT: Operstate: linkmode=-1, operstate=5
Associated to a new BSS: BSSID=00:14:a9:c8:11:b0
No keys have been configured - skip key clearing
Network configuration found for the current AP
WPA: Using WPA IE from AssocReq to set cipher suites
WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 1 proto 1
WPA: clearing AP WPA IE
WPA: clearing AP RSN IE
WPA: using GTK TKIP
WPA: using PTK TKIP
WPA: using KEY_MGMT 802.1X
WPA: not using MGMT group cipher
WPA: Set own WPA IE default - hexdump(len=24): dd 16 00 50 f2 01 01 00
00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 01
EAPOL: External notification - portControl=Auto
Associated with 00:14:a9:c8:11:b0
WPA: Association event - clear replay counter
EAPOL: External notification - portEnabled=0
EAPOL: External notification - portValid=0
EAPOL: External notification - portEnabled=1
EAPOL: SUPP_PAE entering state CONNECTING
EAPOL: SUPP_BE entering state IDLE
EAP: EAP entering state INITIALIZE
EAP: EAP entering state IDLE
Setting authentication timeout: 10 sec 0 usec
Cancelling scan request
RX EAPOL from 00:14:a9:c8:11:b0
Setting authentication timeout: 70 sec 0 usec
EAPOL: Received EAP-Packet frame
EAPOL: SUPP_PAE entering state RESTART
EAP: EAP entering state INITIALIZE
EAP: EAP entering state IDLE
EAPOL: SUPP_PAE entering state AUTHENTICATING
EAPOL: SUPP_BE entering state REQUEST
EAPOL: getSuppRsp
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=1 method=1 vendor=0 vendorMethod=0
EAP: EAP entering state IDENTITY
CTRL-EVENT-EAP-STARTED EAP authentication started
EAP: EAP-Request Identity data - hexdump_ascii(len=41):
00 6e 65 74 77 6f 72 6b 69 64 3d 6f 72 6e 6c 77 _networkid=ornlw
70 61 2c 6e 61 73 69 64 3d 41 50 43 53 42 2d 36 pa,nasid=APCSB-6
2c 70 6f 72 74 69 64 3d 30 ,portid=0
EAP: using real identity - hexdump_ascii(len=8):
4f 52 4e 4c 5c 75 75 61 ORNL\uua
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
EAPOL: SUPP_BE entering state RESPONSE
EAPOL: txSuppRsp
EAPOL: SUPP_BE entering state RECEIVE
RX EAPOL from 00:14:a9:c8:11:b0
EAPOL: Received EAP-Packet frame
EAPOL: SUPP_BE entering state REQUEST
EAPOL: getSuppRsp
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=2 method=25 vendor=0 vendorMethod=0
EAP: EAP entering state GET_METHOD
EAP: Initialize selected EAP method: vendor 0 method 25 (PEAP)
EAP-PEAP: Phase2 EAP types - hexdump(len=72): 00 00 00 00 04 00 00 00 00
00 00 00 1a 00 00 00 00 00 00 00 06 00 00 00 00 00 00 00 05 00 00 00 00
00 00 00 11 00 00 00 00 00 00 00 2f 00 00 00 00 00 00 00 2e 00 00 00 00
00 00 00 30 00 00 00 00 00 00 00 ff 00 00 00
CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected
EAP: EAP entering state METHOD
SSL: Received packet(len=6) - Flags 0x21
EAP-PEAP: Start (server ver=1, own ver=1)
EAP-PEAP: Using PEAP version 1
SSL: (where=0x10 ret=0x1)
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:before/connect initialization
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3 write client hello A
SSL: (where=0x1002 ret=0xffffffff)
SSL: SSL_connect:error in SSLv3 read server hello A
SSL: SSL_connect - want more data
SSL: 97 bytes pending from ssl_out
SSL: 97 bytes left to be sent out (of total 97 bytes)
EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
EAPOL: SUPP_BE entering state RESPONSE
EAPOL: txSuppRsp
EAPOL: SUPP_BE entering state RECEIVE
RX EAPOL from 00:14:a9:c8:11:b0
EAPOL: Received EAP-Packet frame
EAPOL: SUPP_BE entering state REQUEST
EAPOL: getSuppRsp
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=3 method=25 vendor=0 vendorMethod=0
EAP: EAP entering state METHOD
SSL: Received packet(len=1000) - Flags 0x81
SSL: TLS Message Length: 990
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3 read server hello A
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3 read server certificate A
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3 read server done A
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3 write client key exchange A
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3 write change cipher spec A
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3 write finished A
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3 flush data
SSL: (where=0x1002 ret=0xffffffff)
SSL: SSL_connect:error in SSLv3 read finished A
SSL: SSL_connect - want more data
SSL: 190 bytes pending from ssl_out
SSL: 190 bytes left to be sent out (of total 190 bytes)
EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
EAPOL: SUPP_BE entering state RESPONSE
EAPOL: txSuppRsp
EAPOL: SUPP_BE entering state RECEIVE
RX EAPOL from 00:14:a9:c8:11:b0
EAPOL: Received EAP-Packet frame
EAPOL: SUPP_BE entering state REQUEST
EAPOL: getSuppRsp
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=4 method=25 vendor=0 vendorMethod=0
EAP: EAP entering state METHOD
SSL: Received packet(len=61) - Flags 0x81
SSL: TLS Message Length: 51
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3 read finished A
SSL: (where=0x20 ret=0x1)
SSL: (where=0x1002 ret=0x1)
SSL: 0 bytes pending from ssl_out
OpenSSL: tls_connection_handshake - Failed to read possible Application
Data error:00000000:lib(0):func(0):reason(0)
SSL: No data to be sent out
EAP-PEAP: TLS done, proceed to Phase 2
EAP-PEAP: using label 'client EAP encryption' in key derivation
EAP-PEAP: Derived key - hexdump(len=64): [REMOVED]
SSL: Building ACK
EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
EAPOL: SUPP_BE entering state RESPONSE
EAPOL: txSuppRsp
EAPOL: SUPP_BE entering state RECEIVE
RX EAPOL from 00:14:a9:c8:11:b0
EAPOL: Received EAP-Packet frame
EAPOL: SUPP_BE entering state REQUEST
EAPOL: getSuppRsp
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=5 method=25 vendor=0 vendorMethod=0
EAP: EAP entering state METHOD
SSL: Received packet(len=72) - Flags 0x01
EAP-PEAP: received 66 bytes encrypted data for Phase 2
EAP-PEAP: Decrypted Phase 2 EAP - hexdump(len=5): 01 00 00 05 01
EAP-PEAP: received Phase 2: code=1 identifier=0 length=5
EAP-PEAP: Phase 2 Request: type=1
EAP: using real identity - hexdump_ascii(len=8):
4f 52 4e 4c 5c 75 75 61 ORNL\uua
EAP-PEAP: Encrypting Phase 2 data - hexdump(len=13): [REMOVED]
EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
EAPOL: SUPP_BE entering state RESPONSE
EAPOL: txSuppRsp
EAPOL: SUPP_BE entering state RECEIVE
RX EAPOL from 00:14:a9:c8:11:b0
EAPOL: Received EAP-Packet frame
EAPOL: SUPP_BE entering state REQUEST
EAPOL: getSuppRsp
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=6 method=25 vendor=0 vendorMethod=0
EAP: EAP entering state METHOD
SSL: Received packet(len=96) - Flags 0x01
EAP-PEAP: received 90 bytes encrypted data for Phase 2
EAP-PEAP: Decrypted Phase 2 EAP - hexdump(len=33): 01 01 00 21 1a 01 01
00 1c 10 47 8c be 37 e9 a9 d0 ba d7 8c 2e 61 cd 1b bf 80 72 61 64 69 75
73 31
EAP-PEAP: received Phase 2: code=1 identifier=1 length=33
EAP-PEAP: Phase 2 Request: type=26
EAP-PEAP: Selected Phase 2 EAP vendor 0 method 26
EAP-MSCHAPV2: RX identifier 1 mschapv2_id 1
EAP-MSCHAPV2: Received challenge
EAP-MSCHAPV2: Authentication Servername - hexdump_ascii(len=7):
72 61 64 69 75 73 31 radius1
EAP-MSCHAPV2: Generating Challenge Response
EAP-MSCHAPV2: auth_challenge - hexdump(len=16): 47 8c be 37 e9 a9 d0 ba
d7 8c 2e 61 cd 1b bf 80
EAP-MSCHAPV2: peer_challenge - hexdump(len=16): a9 f4 e1 da 7e 5d 24 55
1c 9f ef bc c6 ed 7e d9
EAP-MSCHAPV2: username - hexdump_ascii(len=3):
75 75 61 uua
EAP-MSCHAPV2: password - hexdump_ascii(len=8): [REMOVED]
EAP-MSCHAPV2: response - hexdump(len=24): 37 89 d7 32 de 40 e4 8c 08 f3
9f fe 99 0b a2 fb 74 64 13 57 cb 47 3a 60
EAP-MSCHAPV2: TX identifier 1 mschapv2_id 1 (response)
EAP-PEAP: Encrypting Phase 2 data - hexdump(len=67): [REMOVED]
EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
EAPOL: SUPP_BE entering state RESPONSE
EAPOL: txSuppRsp
EAPOL: SUPP_BE entering state RECEIVE
RX EAPOL from 00:14:a9:c8:11:b0
EAPOL: Received EAP-Packet frame
EAPOL: SUPP_BE entering state REQUEST
EAPOL: getSuppRsp
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=7 method=25 vendor=0 vendorMethod=0
EAP: EAP entering state METHOD
SSL: Received packet(len=120) - Flags 0x01
EAP-PEAP: received 114 bytes encrypted data for Phase 2
EAP-PEAP: Decrypted Phase 2 EAP - hexdump(len=55): 01 01 00 37 1a 03 01
00 32 53 3d 45 41 46 46 38 33 45 36 39 43 33 41 33 43 35 46 32 39 42 34
44 32 46 39 39 44 41 44 46 44 41 44 33 46 42 33 32 32 41 34 4d 3d 4f 4b
EAP-PEAP: received Phase 2: code=1 identifier=1 length=55
EAP-PEAP: Phase 2 Request: type=26
EAP-MSCHAPV2: RX identifier 1 mschapv2_id 1
EAP-MSCHAPV2: Received success
EAP-MSCHAPV2: Success message - hexdump_ascii(len=4):
4d 3d 4f 4b M=OK
EAP-MSCHAPV2: Authentication succeeded
EAP-PEAP: Encrypting Phase 2 data - hexdump(len=6): [REMOVED]
EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
EAPOL: SUPP_BE entering state RESPONSE
EAPOL: txSuppRsp
EAPOL: SUPP_BE entering state RECEIVE
RX EAPOL from 00:14:a9:c8:11:b0
EAPOL: Received EAP-Packet frame
EAPOL: SUPP_BE entering state REQUEST
EAPOL: getSuppRsp
EAP: EAP entering state RECEIVED
EAP: Received EAP-Success
EAP: EAP entering state FAILURE
CTRL-EVENT-EAP-FAILURE EAP authentication failed
EAPOL: SUPP_PAE entering state HELD
EAPOL: SUPP_BE entering state RECEIVE
EAPOL: SUPP_BE entering state FAIL
EAPOL: SUPP_BE entering state IDLE
RX EAPOL from 00:14:a9:c8:11:b0
EAPOL: Ignoring WPA EAPOL-Key frame in EAPOL state machines
IEEE 802.1X RX: version=1 type=3 length=95
EAPOL-Key type=254
key_info 0x89 (ver=1 keyidx=0 rsvd=0 Pairwise Ack)
key_length=32 key_data_length=0
replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 01
key_nonce - hexdump(len=32): 01 0d fa c7 9b 0e 31 a6 83 53 c6 46 c4
9c 90 fc 0a 55 08 58 a7 72 d5 b0 66 46 d7 78 54 6b 56 99
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
State: ASSOCIATED -> 4WAY_HANDSHAKE
WPA: RX message 1 of 4-Way Handshake from 00:14:a9:c8:11:b0 (ver=1)
WPA: Failed to get master session key from EAPOL state machines
WPA: Key handshake aborted
RX EAPOL from 00:14:a9:c8:11:b0
EAPOL: Ignoring WPA EAPOL-Key frame in EAPOL state machines
IEEE 802.1X RX: version=1 type=3 length=95
EAPOL-Key type=254
key_info 0x89 (ver=1 keyidx=0 rsvd=0 Pairwise Ack)
key_length=32 key_data_length=0
replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 02
key_nonce - hexdump(len=32): 01 0d fa c7 9b 0e 31 a6 83 53 c6 46 c4
9c 90 fc 0a 55 08 58 a7 72 d5 b0 66 46 d7 78 54 6b 56 9a
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
State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
WPA: RX message 1 of 4-Way Handshake from 00:14:a9:c8:11:b0 (ver=1)
WPA: Failed to get master session key from EAPOL state machines
WPA: Key handshake aborted
RX EAPOL from 00:14:a9:c8:11:b0
EAPOL: Ignoring WPA EAPOL-Key frame in EAPOL state machines
IEEE 802.1X RX: version=1 type=3 length=95
EAPOL-Key type=254
key_info 0x89 (ver=1 keyidx=0 rsvd=0 Pairwise Ack)
key_length=32 key_data_length=0
replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 03
key_nonce - hexdump(len=32): 01 0d fa c7 9b 0e 31 a6 83 53 c6 46 c4
9c 90 fc 0a 55 08 58 a7 72 d5 b0 66 46 d7 78 54 6b 56 9b
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
State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
WPA: RX message 1 of 4-Way Handshake from 00:14:a9:c8:11:b0 (ver=1)
WPA: Failed to get master session key from EAPOL state machines
WPA: Key handshake aborted
RTM_NEWLINK: operstate=0 ifi_flags=0x1003 ([UP])
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:00:00:00:00:00
Setting scan request: 0 sec 100000 usec
Added BSSID 00:14:a9:c8:11:b0 into blacklist
CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=1 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=2 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=3 set_tx=0 seq_len=0 key_len=0
wpa_driver_wext_set_key: alg=0 key_idx=0 set_tx=0 seq_len=0 key_len=0
State: 4WAY_HANDSHAKE -> DISCONNECTED
wpa_driver_wext_set_operstate: operstate 0->0 (DORMANT)
WEXT: Operstate: linkmode=-1, operstate=5
EAPOL: External notification - portEnabled=0
EAPOL: SUPP_PAE entering state DISCONNECTED
EAPOL: SUPP_BE entering state INITIALIZE
EAP: EAP entering state DISABLED
EAPOL: External notification - portValid=0
RTM_NEWLINK: operstate=0 ifi_flags=0x11003 ([UP][LOWER_UP])
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:14:a9:c8:11:b0
State: DISCONNECTED -> ASSOCIATED
Here's the relevant logs from our RADIUS server:
Tue Jan 15 09:07:51 2008: Received-Authentication: 81/27272 'ORNL\\uua'
from 160.091.088.015 port 5166788 dumb - Start EAP
Tue Jan 15 09:07:51 2008: Created-Authentication: 85/27277 'ORNL\\uua'
from 160.091.088.015 port 5166788 dumb - Start EAP
Tue Jan 15 09:07:51 2008: Inner-Authentication: 23812/27282 'ORNL\\uua'
via radius1 from 160.091.088.015 port 5166788 dumb -- OK
Tue Jan 15 09:07:51 2008: Authentication: 87/27281 'ORNL\\uua' from
160.091.088.015 port 5166788 dumb - OK -- total 0, holding 0
Finally, here's my wpa_supplicant.conf:
ctrl_interface=/var/run/wpa_supplicant
ctrl_interface_group=10
ap_scan=2
network={
ssid="ornlwpa"
proto=WPA
key_mgmt=WPA-EAP
pairwise=TKIP
group=TKIP
eap=PEAP
identity="ORNL\uua"
password="***"
phase1="peaplabel=1"
phase2="auth=MSCHAPV2"
ca_cert="/etc/pki/tls/cert.pem"
disabled=0
}
Jouni Malinen wrote:
> On Fri, Jan 11, 2008 at 02:39:06PM -0500, Ryan M. Adamson wrote:
>
>> I'm running wpa_supplicant on RHEL5 using EAP-PEAP/MSCHAPv2 with a
>> RADIUS server. From what I can tell by looking at the debug logs on my
>> machine and the RADIUS server logs, authentication through the RADIUS
>> server is successful.
>
> Which RADIUS server are you using?
>
>> The 4-way handshake is failing, however, with:
>>
>> WPA: Failed to get master session key from EAPOL state machines
>> WPA: Key handshake aborted
>
> This would indicate that the EAP authentication was not completed
> successfully.
>
>> A little bit earlier in the logs, I see this:
>>
>> EAPOL: Received EAP-Packet frame
>> EAPOL: SUPP_BE entering state REQUEST
>> EAPOL: getSuppRsp
>> EAP: EAP entering state RECEIVED
>> EAP: Received EAP-Success
>> EAP: EAP entering state FAILURE
>> CTRL-EVENT-EAP-FAILURE EAP authentication failed
>
> And indeed, the EAP part had failed. The EAP state machine moves into
> FAILURE state if an EAP-Success is received when it was not received.
> You did not include enough context (i.e., what happened before this
> EAP-Success was received) to figure out what triggered this particular
> issue.
>
More information about the Hostap
mailing list