help seeing more debugging EAP-TTLS handshake

23 Sep 2015

      Hi,
I am trying to debug an EAP-TTLS handshake problem between FreeRADIUS 2.2.4
with OpenSSL 1.0.1f and Mac OS X 10.10.5 and 10.9.5.  The Macs are using
WPA2 Enterprise / 802.1x through a Meraki MR34 Access Point. This
configuration works fine with Windows 8 and Android 4.4.1.

My questions for the FreeRADIUS folks:

a) Is there a way that I can view the decoded TLS attributes from the TLS
handshake? (I'm already running with the -X option).  For example, I'd like
to see what ciphersuites are being proposed and any additional attributes
in the the ClientHello.

b) FreeRADIUS/OpenSSL and these versions of Mac OS X can all do TLS 1.2.
Does the text "TLS 1.0 Handshake" in the log really mean that it is only
using TLS 1.0 instead of TLS 1.2?

c) There is a message in the log "TLS_accept: failed in SSLv3 read client
certificate A". Does this mean that there was a client certificate
presented by the client? (there shouldn't be a client cert at all)

d) Does anyone have any other suggestions to make this work? I already
tried setting the cipher_list to well used ciphers that the Macs generally
like ('AES+aRSA') and got the same result. (The trace below is with the
default cipher_list).

Many thanks,
-rohan

eap.conf:
        eap {
                default_eap_type = ttls
                timer_expire     = 60
                ignore_unknown_eap_types = no
                cisco_accounting_username_bug = no
                max_sessions = 4096
                tls {
                        certdir = ${confdir}/certs
                        cadir = ${confdir}/certs
                        private_key_password = somepasswordhere
                        private_key_file = ${certdir}/server.key
                        certificate_file = ${certdir}/server.pem
                        dh_file = ${certdir}/dh
                        CA_path = ${cadir}
                         cipher_list = "DEFAULT"
                        ecdh_curve = "prime256v1"
                        random_file = /dev/urandom
                        cache {
                              enable = yes
                              lifetime = 24 # hours
                              max_entries = 255
                        }
                        verify {
                        }
                        ocsp {
                              enable = no
                              override_cert_url = yes
                              url = "http://127.0.0.1/ocsp/"
                        }
                }
                ttls {
                        default_eap_type = md5
                        copy_request_to_tunnel = no
                        use_tunneled_reply = no
                        virtual_server = "inner-tunnel"
                }
        }

FreeRADIUS Log file:
rad_recv: Access-Request packet from host 10.0.2.2 port 34931, id=8,
length=164
User-Name = "anonymous"
NAS-IP-Address = 10.0.10.203
NAS-Port = 0
Called-Station-Id = "02-18-5A-1D-AE-03:Remind101-SSO"
Calling-Station-Id = "9C-F3-87-C2-62-C6"
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 0Mbps 802.11b"
EAP-Message = 0x02ba000e01616e6f6e796d6f7573
Message-Authenticator = 0x61ebdbe946edd0fdc49b8c3e41c387a8
Wed Sep 23 17:29:11 2015 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Sep 23 17:29:11 2015 : Info: +- entering group authorize {...}
Wed Sep 23 17:29:11 2015 : Info: ++[preprocess] returns ok
Wed Sep 23 17:29:11 2015 : Info: [eap] EAP packet type response id 186
length 14
Wed Sep 23 17:29:11 2015 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Wed Sep 23 17:29:11 2015 : Info: ++[eap] returns updated
Wed Sep 23 17:29:11 2015 : Info: ++[expiration] returns noop
Wed Sep 23 17:29:11 2015 : Info: ++[logintime] returns noop
Wed Sep 23 17:29:11 2015 : Info: [pap] WARNING! No "known good" password
found for the user.  Authentication may fail because of this.
Wed Sep 23 17:29:11 2015 : Info: ++[pap] returns noop
Wed Sep 23 17:29:11 2015 : Info: Found Auth-Type = EAP
Wed Sep 23 17:29:11 2015 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Sep 23 17:29:11 2015 : Info: +- entering group authenticate {...}
Wed Sep 23 17:29:11 2015 : Info: [eap] EAP Identity
Wed Sep 23 17:29:11 2015 : Info: [eap] processing type tls
Wed Sep 23 17:29:11 2015 : Info: [tls] Flushing SSL sessions (of #0)
Wed Sep 23 17:29:11 2015 : Info: [tls] Initiate
Wed Sep 23 17:29:11 2015 : Info: [tls] Start returned 1
Wed Sep 23 17:29:11 2015 : Info: ++[eap] returns handled
Sending Access-Challenge of id 8 to 10.0.2.2 port 34931
EAP-Message = 0x01bb00061520
Message-Authenticator = 0x00000000000000000000000000000000
State = 0xccf836bacc4323f9b322d4bda37008ed
Wed Sep 23 17:29:11 2015 : Info: Finished request 0.
Wed Sep 23 17:29:11 2015 : Debug: Going to the next request
Wed Sep 23 17:29:11 2015 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.0.2.2 port 34931, id=9,
length=320
User-Name = "anonymous"
NAS-IP-Address = 10.0.10.203
NAS-Port = 0
Called-Station-Id = "02-18-5A-1D-AE-03:Remind101-SSO"
Calling-Station-Id = "9C-F3-87-C2-62-C6"
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 0Mbps 802.11b"
EAP-Message =
0x02bb009815800000008e16030100890100008503015602e16a73b82ed270ffcaa50eac91e3c23b8ed8dbca78c08f2e2e7ceb43a60f00004a00ffc024c023c00ac009c008c028c027c014c013c012c026c025c005c004c003c02ac029c00fc00ec00d006b0067003900330016003d003c0035002f000ac007c011c002c00c0005000401000012000a00080006001700180019000b00020100
State = 0xccf836bacc4323f9b322d4bda37008ed
Message-Authenticator = 0x6ae3c689ec343b04cf0eb36a770f298e
Wed Sep 23 17:29:11 2015 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Sep 23 17:29:11 2015 : Info: +- entering group authorize {...}
Wed Sep 23 17:29:11 2015 : Info: ++[preprocess] returns ok
Wed Sep 23 17:29:11 2015 : Info: [eap] EAP packet type response id 187
length 152
Wed Sep 23 17:29:11 2015 : Info: [eap] Continuing tunnel setup.
Wed Sep 23 17:29:11 2015 : Info: ++[eap] returns ok
Wed Sep 23 17:29:11 2015 : Info: Found Auth-Type = EAP
Wed Sep 23 17:29:11 2015 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Sep 23 17:29:11 2015 : Info: +- entering group authenticate {...}
Wed Sep 23 17:29:11 2015 : Info: [eap] Request found, released from the list
Wed Sep 23 17:29:11 2015 : Info: [eap] EAP/ttls
Wed Sep 23 17:29:11 2015 : Info: [eap] processing type ttls
Wed Sep 23 17:29:11 2015 : Info: [ttls] Authenticate
Wed Sep 23 17:29:11 2015 : Info: [ttls] processing EAP-TLS
Wed Sep 23 17:29:11 2015 : Debug:   TLS Length 142
Wed Sep 23 17:29:11 2015 : Info: [ttls] Length Included
Wed Sep 23 17:29:11 2015 : Info: [ttls] eaptls_verify returned 11
Wed Sep 23 17:29:11 2015 : Info: [ttls]     (other): before/accept
initialization
Wed Sep 23 17:29:11 2015 : Info: [ttls]     TLS_accept: before/accept
initialization
Wed Sep 23 17:29:11 2015 : Info: [ttls] <<< TLS 1.0 Handshake [length
0089], ClientHello
Wed Sep 23 17:29:11 2015 : Info: [ttls]     TLS_accept: SSLv3 read client
hello A
Wed Sep 23 17:29:11 2015 : Info: [ttls] >>> TLS 1.0 Handshake [length
0059], ServerHello
Wed Sep 23 17:29:11 2015 : Info: [ttls]     TLS_accept: SSLv3 write server
hello A
Wed Sep 23 17:29:11 2015 : Info: [ttls] >>> TLS 1.0 Handshake [length
03f6], Certificate
Wed Sep 23 17:29:11 2015 : Info: [ttls]     TLS_accept: SSLv3 write
certificate A
Wed Sep 23 17:29:11 2015 : Info: [ttls] >>> TLS 1.0 Handshake [length
014b], ServerKeyExchange
Wed Sep 23 17:29:11 2015 : Info: [ttls]     TLS_accept: SSLv3 write key
exchange A
Wed Sep 23 17:29:11 2015 : Info: [ttls] >>> TLS 1.0 Handshake [length
0004], ServerHelloDone
Wed Sep 23 17:29:11 2015 : Info: [ttls]     TLS_accept: SSLv3 write server
done A
Wed Sep 23 17:29:11 2015 : Info: [ttls]     TLS_accept: SSLv3 flush data
Wed Sep 23 17:29:11 2015 : Info: [ttls]     TLS_accept: Need to read more
data: SSLv3 read client certificate A
Wed Sep 23 17:29:11 2015 : Debug: In SSL Handshake Phase
Wed Sep 23 17:29:11 2015 : Debug: In SSL Accept mode
Wed Sep 23 17:29:11 2015 : Info: [ttls] eaptls_process returned 13
Wed Sep 23 17:29:11 2015 : Info: ++[eap] returns handled
Sending Access-Challenge of id 9 to 10.0.2.2 port 34931
EAP-Message =
0x01bc040015c0000005b2160301005902000055030113d3df9c72a85ca65f386048d87391ee9afc3c8e76736fcafa1c90308bc16fd120ecd03fda52b76224194100c0ac75ba9e3b8c138945a39636e9bcebffdeb76340c01400000dff01000100000b00040300010216030103f60b0003f20003ef0003ec308203e8308202d0a003020102020102300d06092a864886f70d0101050500308199310b30090603550406130255533113301106035504080c0a43616c69666f726e69613116301406035504070c0d53616e204672616e636973636f31123010060355040a0c0952656d696e64204851311f301d06092a864886f70d010901161061646d696e
EAP-Message =
0x4072656d696e642e636f6d3128302606035504030c1f52656d696e6420485120436572746966696361746520417574686f72697479301e170d3135303831313232343133395a170d3136303831303232343133395a308183310b30090603550406130255533113301106035504080c0a43616c69666f726e696131123010060355040a0c0952656d696e64204851312a302806035504030c2152656d696e64204851205769466920536572766572204365727469666963617465311f301d06092a864886f70d010901161061646d696e4072656d696e642e636f6d30820122300d06092a864886f70d01010105000382010f003082010a0282010100f4
EAP-Message =
0x88df40780f23fd9c004763db97703d78fb881aa9b1f7997fe78f78e4a607f577a089c68d35a37ba1b5be35df87d33c4c57ab4ffece858ee922bfc46147f210b0d460da5341e18242a59a52498a1d4bf62b9ad4c600767e5d2ad93b7d8a13481325ffea7d5c738873761e9b450ffc2de000bcbd690fd8397866a8a1ecf08e2596ce146826a83da3b531fe14bee2d94f6ada414e9e7f4b8af806de0cd692fb61353e7b66735f655a74130dde40b55594d71f847704c8f78c2cfa81e58a67e41e0d32d97ceaf2987575b32239bff27fbcc84ef6b3904846fab1234739c66af20c2fed514a33b2c171f909233e7ee3a441f78315d4490e7b89fa96501c6761
EAP-Message =
0x310f0203010001a34f304d30130603551d25040c300a06082b0601050507030130360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e636f6d2f6578616d706c655f63612e63726c300d06092a864886f70d01010505000382010100a5a587d02f2245d7058b7e15a99660290b3e61278c38b78eeb664a2b076c9b060b694d225c01681eaf09284641fedd80e42a0299dda8f026615e8a59633f949bee830cc0b35b75a66468518416889600bae0a5a4c818caed479e000b322cb8082e0c5133e0fb827682adb12b4264ca0a02e9cdbefbf596944ecd677f9f043c2fbcd824a11c841d32ec27e246753a177e3a
EAP-Message = 0x8c447f914a438a685741f3b5
Message-Authenticator = 0x00000000000000000000000000000000
State = 0xccf836bacd4423f9b322d4bda37008ed
Wed Sep 23 17:29:11 2015 : Info: Finished request 1.
Wed Sep 23 17:29:11 2015 : Debug: Going to the next request
Wed Sep 23 17:29:11 2015 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.0.2.2 port 34931, id=10,
length=174
User-Name = "anonymous"
NAS-IP-Address = 10.0.10.203
NAS-Port = 0
Called-Station-Id = "02-18-5A-1D-AE-03:Remind101-SSO"
Calling-Station-Id = "9C-F3-87-C2-62-C6"
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 0Mbps 802.11b"
EAP-Message = 0x02bc00061500
State = 0xccf836bacd4423f9b322d4bda37008ed
Message-Authenticator = 0x76a0ebaf55da4ea748e3a91d1c5cec57
Wed Sep 23 17:29:11 2015 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Sep 23 17:29:11 2015 : Info: +- entering group authorize {...}
Wed Sep 23 17:29:11 2015 : Info: ++[preprocess] returns ok
Wed Sep 23 17:29:11 2015 : Info: [eap] EAP packet type response id 188
length 6
Wed Sep 23 17:29:11 2015 : Info: [eap] Continuing tunnel setup.
Wed Sep 23 17:29:11 2015 : Info: ++[eap] returns ok
Wed Sep 23 17:29:11 2015 : Info: Found Auth-Type = EAP
Wed Sep 23 17:29:11 2015 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Sep 23 17:29:11 2015 : Info: +- entering group authenticate {...}
Wed Sep 23 17:29:11 2015 : Info: [eap] Request found, released from the list
Wed Sep 23 17:29:11 2015 : Info: [eap] EAP/ttls
Wed Sep 23 17:29:11 2015 : Info: [eap] processing type ttls
Wed Sep 23 17:29:11 2015 : Info: [ttls] Authenticate
Wed Sep 23 17:29:11 2015 : Info: [ttls] processing EAP-TLS
Wed Sep 23 17:29:11 2015 : Info: [ttls] Received TLS ACK
Wed Sep 23 17:29:11 2015 : Info: [ttls] ACK handshake fragment handler
Wed Sep 23 17:29:11 2015 : Info: [ttls] eaptls_verify returned 1
Wed Sep 23 17:29:11 2015 : Info: [ttls] eaptls_process returned 13
Wed Sep 23 17:29:11 2015 : Info: ++[eap] returns handled
Sending Access-Challenge of id 10 to 10.0.2.2 port 34931
EAP-Message =
0x01bd01c61580000005b2fb46633c5848cee0329bc65d69b76e0fbdaea7a3908b670c77fd43386dda5b7dfd5b6194b2e217630e7ed3fcaf4b58c9557fcc863e662005a929f556bc5238ed01b4cac3358590385cd0e8a6b29cec783c0e110a955813876b2df0631ad835b2ad9888160301014b0c00014703001741045121517bd8ad0efeac7a598718fe61bb8af1e6808aa1336ca156dd9d478105035e2d6ea738e43581419c240db2fff0ca113416a99feb214cb9aa801d9e6ef9750100d41b74c1d5fc7adef7cbb7f2630bc1d1f455bd158e3bfaf422298670906fcd98d276ff57063e33113f5c2e32f76b793d21c69555a03c8bd365e4ad850bf7345b
EAP-Message =
0x3e8e65a3eb436972c79ee1a91fd4c81b1a8ad83b8bae15666a28f66d14c8b6ad9eb5e2555ef01a005730a582cc84a83abdda1455beb911acbd6f7345d6b1e56d1b9b4c77382e1274afdab7e270ce8b031039cae39264ffa5578c2dc4803c43e0ab40f2bc885eebb10e8e5e5b59f651bb5020ab4b7a669b7d0506570134d2efb56f81a54314233e01503ca4417db967597455f1e1dce5f307f63ff3b9946a69c35cc162991a253e322cdf649a153b0814b2a908c6099a2b7e7770b133fe5cec0316030100040e000000
Message-Authenticator = 0x00000000000000000000000000000000
State = 0xccf836bace4523f9b322d4bda37008ed
Wed Sep 23 17:29:11 2015 : Info: Finished request 2.
Wed Sep 23 17:29:11 2015 : Debug: Going to the next request
Wed Sep 23 17:29:11 2015 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.0.2.2 port 34931, id=11,
length=185
User-Name = "anonymous"
NAS-IP-Address = 10.0.10.203
NAS-Port = 0
Called-Station-Id = "02-18-5A-1D-AE-03:Remind101-SSO"
Calling-Station-Id = "9C-F3-87-C2-62-C6"
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 0Mbps 802.11b"
EAP-Message = 0x02bd001115800000000715030100020100
State = 0xccf836bace4523f9b322d4bda37008ed
Message-Authenticator = 0x9cb7425be35279493d1aec7a86122067
Wed Sep 23 17:29:11 2015 : Info: # Executing section authorize from file
/etc/freeradius/sites-enabled/default
Wed Sep 23 17:29:11 2015 : Info: +- entering group authorize {...}
Wed Sep 23 17:29:11 2015 : Info: ++[preprocess] returns ok
Wed Sep 23 17:29:11 2015 : Info: [eap] EAP packet type response id 189
length 17
Wed Sep 23 17:29:11 2015 : Info: [eap] Continuing tunnel setup.
Wed Sep 23 17:29:11 2015 : Info: ++[eap] returns ok
Wed Sep 23 17:29:11 2015 : Info: Found Auth-Type = EAP
Wed Sep 23 17:29:11 2015 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Sep 23 17:29:11 2015 : Info: +- entering group authenticate {...}
Wed Sep 23 17:29:11 2015 : Info: [eap] Request found, released from the list
Wed Sep 23 17:29:11 2015 : Info: [eap] EAP/ttls
Wed Sep 23 17:29:11 2015 : Info: [eap] processing type ttls
Wed Sep 23 17:29:11 2015 : Info: [ttls] Authenticate
Wed Sep 23 17:29:11 2015 : Info: [ttls] processing EAP-TLS
Wed Sep 23 17:29:11 2015 : Debug:   TLS Length 7
Wed Sep 23 17:29:11 2015 : Info: [ttls] Length Included
Wed Sep 23 17:29:11 2015 : Info: [ttls] eaptls_verify returned 11
Wed Sep 23 17:29:11 2015 : Info: [ttls] <<< TLS 1.0 Alert [length 0002],
warning close_notify
Wed Sep 23 17:29:11 2015 : Error: TLS Alert read:warning:close notify
Wed Sep 23 17:29:11 2015 : Error:     TLS_accept: failed in SSLv3 read
client certificate A
Wed Sep 23 17:29:11 2015 : Error: rlm_eap: SSL error error:140940E5:SSL
routines:SSL3_READ_BYTES:ssl handshake failure
Wed Sep 23 17:29:11 2015 : Error: SSL: SSL_read failed in a system call
(-1), TLS session fails.
Wed Sep 23 17:29:11 2015 : Debug: TLS receive handshake failed during
operation
Wed Sep 23 17:29:11 2015 : Info: [ttls] eaptls_process returned 4
Wed Sep 23 17:29:11 2015 : Info: [eap] Handler failed in EAP/ttls
Wed Sep 23 17:29:11 2015 : Info: [eap] Failed in EAP select
Wed Sep 23 17:29:11 2015 : Info: ++[eap] returns invalid
Wed Sep 23 17:29:11 2015 : Info: Failed to authenticate the user.
Wed Sep 23 17:29:11 2015 : Info: Using Post-Auth-Type Reject
Wed Sep 23 17:29:11 2015 : Info: # Executing group from file
/etc/freeradius/sites-enabled/default
Wed Sep 23 17:29:11 2015 : Info: +- entering group REJECT {...}
Wed Sep 23 17:29:11 2015 : Info: [attr_filter.access_reject] expand:
%{User-Name} -> anonymous
Wed Sep 23 17:29:11 2015 : Debug: attr_filter: Matched entry DEFAULT at
line 11
Wed Sep 23 17:29:11 2015 : Info: ++[attr_filter.access_reject] returns
updated
Wed Sep 23 17:29:11 2015 : Info: Delaying reject of request 3 for 1 seconds
Wed Sep 23 17:29:11 2015 : Debug: Going to the next request
Wed Sep 23 17:29:11 2015 : Debug: Waking up in 0.9 seconds.
Wed Sep 23 17:29:12 2015 : Info: Sending delayed reject for request 3
Sending Access-Reject of id 11 to 10.0.2.2 port 34931
EAP-Message = 0x04bd0004
Message-Authenticator = 0x00000000000000000000000000000000

help seeing more debugging EAP-TTLS handshake

Rohan Mahy