AVP EAP-KEY name support in FR

Srinu Bandari sbandari at vitesse.com
Mon Feb 18 11:23:05 CET 2013


Alan,



We have tried with patch provided.

Here is the Debug log form old (master 2.2.0) and new (latest 2.x.x branch 18/2/2013)



Old one: Here the tls state machine goes from Access-Request to Access-Challenge and then to Access-Accepted

And New one: Here the tls state machine goes from Access-Request to Access-Rejected and then ends with segmentation fault



Note: configuration of Client and Switch remains the same in both cases.



What could have gone wrong??



///////////////////////////////

Old one:

rad_recv: Access-Request packet from host 10.0.1.10 port 1645, id=3, length=1020

Sat Aug 18 03:04:46 2012 : Info: Found Auth-Type = EAP

Sat Aug 18 03:04:46 2012 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default

Sat Aug 18 03:04:46 2012 : Info: +- entering group authenticate {...}

Sat Aug 18 03:04:46 2012 : Info: [eap] Request found, released from the list

Sat Aug 18 03:04:46 2012 : Info: [eap] EAP/tls

Sat Aug 18 03:04:46 2012 : Info: [eap] processing type tls

Sat Aug 18 03:04:46 2012 : Info: [tls] Authenticate

Sat Aug 18 03:04:46 2012 : Info: [tls] processing EAP-TLS

Sat Aug 18 03:04:46 2012 : Info: [tls] eaptls_verify returned 7

Sat Aug 18 03:04:46 2012 : Info: [tls] Done initial handshake

Sat Aug 18 03:04:46 2012 : Info: [tls] <<< TLS 1.0 Handshake [length 05f6], Certificate

Sat Aug 18 03:04:46 2012 : Info: [tls] chain-depth=1,

Sat Aug 18 03:04:46 2012 : Info: [tls] error=0

Sat Aug 18 03:04:46 2012 : Info: [tls] --> User-Name = testuser-2 at vitesse.com

Sat Aug 18 03:04:46 2012 : Info: [tls] --> BUF-Name = MACsec Test CA

Sat Aug 18 03:04:46 2012 : Info: [tls] --> subject = /C=FI/O=SafeNet, Inc./CN=MACsec Test CA

Sat Aug 18 03:04:46 2012 : Info: [tls] --> issuer  = /C=FI/O=SafeNet, Inc./CN=MACsec Test CA

Sat Aug 18 03:04:46 2012 : Info: [tls] --> verify return:1

Sat Aug 18 03:04:46 2012 : Info: [tls] chain-depth=0,

Sat Aug 18 03:04:46 2012 : Info: [tls] error=0

Sat Aug 18 03:04:46 2012 : Info: [tls] --> User-Name = testuser-2 at vitesse.com

Sat Aug 18 03:04:46 2012 : Info: [tls] --> BUF-Name = test user 2

Sat Aug 18 03:04:46 2012 : Info: [tls] --> verify return:1

Sat Aug 18 03:04:46 2012 : Info: [tls]     TLS_accept: SSLv3 read client certificate A

Sat Aug 18 03:04:46 2012 : Info: [tls] <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange

Sat Aug 18 03:04:46 2012 : Info: [tls]     TLS_accept: SSLv3 read client key exchange A

Sat Aug 18 03:04:46 2012 : Info: [tls] <<< TLS 1.0 Handshake [length 0086], CertificateVerify

Sat Aug 18 03:04:46 2012 : Info: [tls]     TLS_accept: SSLv3 read certificate verify A

Sat Aug 18 03:04:46 2012 : Info: [tls] <<< TLS 1.0 ChangeCipherSpec [length 0001]

Sat Aug 18 03:04:46 2012 : Info: [tls] <<< TLS 1.0 Handshake [length 0010], Finished

Sat Aug 18 03:04:46 2012 : Info: [tls]     TLS_accept: SSLv3 read finished A

Sat Aug 18 03:04:46 2012 : Info: [tls] >>> TLS 1.0 ChangeCipherSpec [length 0001]

Sat Aug 18 03:04:46 2012 : Info: [tls]     TLS_accept: SSLv3 write change cipher spec A

Sat Aug 18 03:04:46 2012 : Info: [tls] >>> TLS 1.0 Handshake [length 0010], Finished

Sat Aug 18 03:04:46 2012 : Info: [tls]     TLS_accept: SSLv3 write finished A

Sat Aug 18 03:04:46 2012 : Info: [tls]     TLS_accept: SSLv3 flush data

Sat Aug 18 03:04:46 2012 : Info: [tls]     (other): SSL negotiation finished successfully

Sat Aug 18 03:04:46 2012 : Debug: SSL Connection Established

Sat Aug 18 03:04:46 2012 : Info: [tls] eaptls_process returned 13

Sat Aug 18 03:04:46 2012 : Info: ++[eap] returns handled

Sending Access-Challenge of id 3 to 10.0.1.10 port 1645

      EAP-Message = 0x010c00350d800000002b1403010001011603010020f2847b79b15d316feb376cd0294bffca228fb31bcdfd4e3ac450b4b3148c0eda

      Message-Authenticator = 0x00000000000000000000000000000000

      State = 0x1bc2fd5d1fcef0fc7198dd89ed915160

Sat Aug 18 03:04:46 2012 : Info: Finished request 4.

Sat Aug 18 03:04:46 2012 : Debug: Going to the next request

Sat Aug 18 03:04:46 2012 : Debug: Waking up in 4.8 seconds.

rad_recv: Access-Request packet from host 10.0.1.10 port 1645, id=4, length=191

Sat Aug 18 03:04:46 2012 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default

Sat Aug 18 03:04:46 2012 : Info: +- entering group authorize {...}

Sat Aug 18 03:04:46 2012 : Info: ++[preprocess] returns ok

Sat Aug 18 03:04:46 2012 : Info: ++[chap] returns noop

Sat Aug 18 03:04:46 2012 : Info: ++[mschap] returns noop

Sat Aug 18 03:04:46 2012 : Info: ++[digest] returns noop

Sat Aug 18 03:04:46 2012 : Info: [suffix] Looking up realm "vitesse.com" for User-Name = "testuser-2 at vitesse.com"

Sat Aug 18 03:04:46 2012 : Info: [suffix] No such realm "vitesse.com"

Sat Aug 18 03:04:46 2012 : Info: ++[suffix] returns noop

Sat Aug 18 03:04:46 2012 : Info: [eap] EAP packet type response id 12 length 6

Sat Aug 18 03:04:46 2012 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation

Sat Aug 18 03:04:46 2012 : Info: ++[eap] returns updated

Sat Aug 18 03:04:46 2012 : Info: ++[files] returns noop

Sat Aug 18 03:04:46 2012 : Info: ++[expiration] returns noop

Sat Aug 18 03:04:46 2012 : Info: ++[logintime] returns noop

Sat Aug 18 03:04:46 2012 : Info: ++[pap] returns noop

Sat Aug 18 03:04:46 2012 : Info: Found Auth-Type = EAP

Sat Aug 18 03:04:46 2012 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default

Sat Aug 18 03:04:46 2012 : Info: +- entering group authenticate {...}

Sat Aug 18 03:04:46 2012 : Info: [eap] Request found, released from the list

Sat Aug 18 03:04:46 2012 : Info: [eap] EAP/tls

Sat Aug 18 03:04:46 2012 : Info: [eap] processing type tls

Sat Aug 18 03:04:46 2012 : Info: [tls] Authenticate

Sat Aug 18 03:04:46 2012 : Info: [tls] processing EAP-TLS

Sat Aug 18 03:04:46 2012 : Info: [tls] Received TLS ACK

Sat Aug 18 03:04:46 2012 : Info: [tls] ACK handshake is finished

Sat Aug 18 03:04:46 2012 : Info: [tls] eaptls_verify returned 3

Sat Aug 18 03:04:46 2012 : Info: [tls] eaptls_process returned 3

Sat Aug 18 03:04:46 2012 : Info: [tls] Adding user data to cached session

Sat Aug 18 03:04:46 2012 : Info: [eap] Freeing handler

Sat Aug 18 03:04:46 2012 : Info: ++[eap] returns ok

Sat Aug 18 03:04:46 2012 : Info: # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default

Sat Aug 18 03:04:46 2012 : Info: +- entering group post-auth {...}

Sat Aug 18 03:04:46 2012 : Info: ++[exec] returns noop

Sat Aug 18 03:04:46 2012 : Info:    expand: %{reply:EAP-Session-Id} ->

Sat Aug 18 03:04:46 2012 : Info: ++[reply] returns noop

Sending Access-Accept of id 4 to 10.0.1.10 port 1645

      MS-MPPE-Recv-Key = 0xabfde3ba0cc6ec4bf616ec5c094607c9ba1c4b9936ff5145b50f35e19f15423f

      MS-MPPE-Send-Key = 0x1855579adb2ba678eef70b24a449df8f8a8d9ac120b2a82fbe44371aa6f976e6

      EAP-Message = 0x030c0004

      Message-Authenticator = 0x00000000000000000000000000000000

      User-Name = "testuser-2 at vitesse.com"

Sat Aug 18 03:04:46 2012 : Info: Finished request 5.

Sat Aug 18 03:04:46 2012 : Debug: Going to the next request

Sat Aug 18 03:04:46 2012 : Debug: Waking up in 4.8 seconds



///////////////////////////////

And New one: Here the tls state machine goes from Access-Request to Access-Rejected and then segmentation fault



rad_recv: Access-Request packet from host 10.0.1.10 port 1645, id=147, length=205

Sat Aug 18 02:44:32 2012 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default

Sat Aug 18 02:44:32 2012 : Info: +- entering group authorize {...}

Sat Aug 18 02:44:32 2012 : Info: ++[preprocess] returns ok

Sat Aug 18 02:44:32 2012 : Info: ++[chap] returns noop

Sat Aug 18 02:44:32 2012 : Info: ++[mschap] returns noop

Sat Aug 18 02:44:32 2012 : Info: ++[digest] returns noop

Sat Aug 18 02:44:32 2012 : Info: [suffix] Looking up realm "vitesse.com" for User-Name = "testuser-2 at vitesse.com"

Sat Aug 18 02:44:32 2012 : Info: [suffix] No such realm "vitesse.com"

Sat Aug 18 02:44:32 2012 : Info: ++[suffix] returns noop

Sat Aug 18 02:44:32 2012 : Info: [eap] EAP packet type response id 1 length 38

Sat Aug 18 02:44:32 2012 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation

Sat Aug 18 02:44:32 2012 : Info: ++[eap] returns updated

Sat Aug 18 02:44:32 2012 : Info: ++[files] returns noop

Sat Aug 18 02:44:32 2012 : Info: ++[expiration] returns noop

Sat Aug 18 02:44:32 2012 : Info: ++[logintime] returns noop

Sat Aug 18 02:44:32 2012 : Info: [pap] WARNING! No "known good" password found for the user.  Authentication may fail because of this.

Sat Aug 18 02:44:32 2012 : Info: ++[pap] returns noop

Sat Aug 18 02:44:32 2012 : Info: Found Auth-Type = EAP

Sat Aug 18 02:44:32 2012 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default

Sat Aug 18 02:44:32 2012 : Info: +- entering group authenticate {...}

Sat Aug 18 02:44:32 2012 : Info: [eap] EAP Identity

Sat Aug 18 02:44:32 2012 : Info: [eap] processing type tls

Sat Aug 18 02:44:32 2012 : Info: [tls] Requiring client certificate

Sat Aug 18 02:44:32 2012 : Info: [tls] Initiate

Sat Aug 18 02:44:32 2012 : Info: [tls] Start returned 1

Sat Aug 18 02:44:32 2012 : Info: ++[eap] returns handled

Sat Aug 18 02:44:32 2012 : Info: Failed to authenticate the user.

Sat Aug 18 02:44:32 2012 : Info: Using Post-Auth-Type REJECT

Sat Aug 18 02:44:32 2012 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default

Sat Aug 18 02:44:32 2012 : Info: +- entering group REJECT {...}

Sat Aug 18 02:44:32 2012 : Info: [attr_filter.access_reject]      expand: %{User-Name} -> testuser-2 at vitesse.com

Sat Aug 18 02:44:32 2012 : Debug: attr_filter: Matched entry DEFAULT at line 11

Sat Aug 18 02:44:32 2012 : Info: ++[attr_filter.access_reject] returns updated

Sat Aug 18 02:44:32 2012 : Info: Delaying reject of request 0 for 1 seconds

Sat Aug 18 02:44:32 2012 : Debug: Going to the next request

Sat Aug 18 02:44:32 2012 : Debug: Waking up in 0.9 seconds.

Sat Aug 18 02:44:33 2012 : Info: Sending delayed reject for request 0



Sending Access-Reject of id 147 to 10.0.1.10 port 1645

Sat Aug 18 02:44:33 2012 : Debug: Waking up in 0.3 seconds.

Sat Aug 18 02:44:33 2012 : Info: Sending delayed reject for request 1

Sending Access-Reject of id 148 to 10.0.1.10 port 1645



Thanks,

Srinivas B
CONFIDENTIALITY NOTICE: This e-mail message, including any attachments, is for the sole use of the intended recipient(s) and may contain confidential and privileged information. Any unauthorized review, use, disclosure or distribution is prohibited. If you are not the intended recipient, please contact the sender by reply e-mail and destroy all copies of the original message.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20130218/2bbd11d4/attachment-0001.html>


More information about the Freeradius-Users mailing list