Trouble migrating EAP TLS authentication from Free Radius 1.1.8 to 2.1.9

[SEELEMANN, Sven]

Hi,

I've been trying to migrate the FreeRadius server from 1.1.8 to the 
latest (stable) release (2.1.9 at the last try, 2.1.8 before that).  I'm 
using EAP TLS to authenticate modem connection to our DSLAM (using 2 way 
authentication).  The 1.1.8 server has no trouble performing the task, 
however, the 2.1.x server doesn't ever complete the authentication 
process. From what I can tell, once the 1.1.8 server gets the final TLS 
ACK it allows the connection, but the 2.1.x server is looking for 
something else.

Is this a FreeRadius issue or a DSLAM problem?  If DSLAM, where is the 
best place to start looking for description of what should be happening?

I have openssl 1.0.0 installed on the sparc Solaris 10 server that is 
running FreeRadius.

Using a single modem and debug mode, I've got the following log snippets 
(from the end of the session each):

Version 1.1.8:
Waking up in 5 seconds...
rad_recv: Access-Request packet from host 138.120.206.110:10000, id=56, 
length=158
     NAS-Identifier = "SSL-7330-3"
     NAS-IP-Address = 138.120.206.110
     User-Name = "00:18:3F:5E:57:B0"
     NAS-Port = 136383488
     NAS-Port-Type = xDSL
     Acct-Session-Id = "173:26:18::0075"
     NAS-Port-Id = "atm 1/1/04/13:0:32"
     Calling-Station-Id = "\000\030?^W\260"
     EAP-Message = 0x020700060d00
     Message-Authenticator = 0x778fd2a832af2ac150c6df5119a51f88
     State = 0x2638193a96b23d3b2ac39fe35dff53cb
   Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 49
   modcall[authorize]: module "preprocess" returns ok for request 49
radius_xlat:  
'/usr/local/etc/raddb/var/log/radius/radacct/138.120.206.110/auth-detail-20100306'
rlm_detail: 
/usr/local/etc/raddb/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to 
/usr/local/etc/raddb/var/log/radius/radacct/138.120.206.110/auth-detail-20100306
   modcall[authorize]: module "auth_log" returns ok for request 49
   modcall[authorize]: module "chap" returns noop for request 49
   modcall[authorize]: module "mschap" returns noop for request 49
     rlm_realm: No '@' in User-Name = "00:18:3F:5E:57:B0", looking up 
realm NULL
     rlm_realm: No such realm "NULL"
   modcall[authorize]: module "suffix" returns noop for request 49
   rlm_eap: EAP packet type response id 7 length 6
   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
   modcall[authorize]: module "eap" returns updated for request 49
   modcall[authorize]: module "files" returns notfound for request 49
modcall: group authorize returns updated for request 49
   rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
   Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 49
   rlm_eap: Request found, released from the list
   rlm_eap: EAP/tls
   rlm_eap: processing type tls
   rlm_eap_tls: Authenticate
   rlm_eap_tls: processing TLS
rlm_eap_tls: Received EAP-TLS ACK message
   rlm_eap_tls: ack handshake is finished
   eaptls_verify returned 3
   eaptls_process returned 3
   rlm_eap: Freeing handler
   modcall[authenticate]: module "eap" returns ok for request 49
modcall: group authenticate returns ok for request 49
Sending Access-Accept of id 56 to 138.120.206.110:10000
     MS-MPPE-Recv-Key = 
0x7b94ecfc920b6cd85506aee431a4d876e4af891c3dc51c433af623302ace6490
     MS-MPPE-Send-Key = 
0x370e00c44f3145ad3eaa77720d9e48a102750fcefdb44f980156c67c2dc790ee
     EAP-Message = 0x03070004
     Message-Authenticator = 0x00000000000000000000000000000000
     User-Name = "00:18:3F:5E:57:B0"
Finished request 49
Going to the next request
Waking up in 5 seconds...

Version 2.1.9:
Waking up in 4.2 seconds.
rad_recv: Access-Request packet from host 138.120.206.113 port 10000, 
id=202, length=158
     NAS-Identifier = "SSL-7330-4"
     NAS-IP-Address = 138.120.206.113
     User-Name = "00:1B:5B:10:97:88"
     NAS-Port = 136392448
     NAS-Port-Type = xDSL
     Acct-Session-Id = "157:52:37::0371"
     NAS-Port-Id = "atm 1/1/04/48:0:32"
     Calling-Station-Id = "\000\033[\020\227\210"
     EAP-Message = 0x020e00060d00
     Message-Authenticator = 0xdffd259e9fa9cef084a12d640fb51073
     State = 0x056b0543006508967ef0ed7dafcf0427
+- entering group authorize {...}
++[preprocess] returns ok
[eap] EAP packet type response id 14 length 6
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] returns updated
++[unix] returns notfound
++[files] returns noop
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns noop
Found Auth-Type = EAP
+- entering group authenticate {...}
[eap] Request found, released from the list
[eap] EAP/tls
[eap] processing type tls
[tls] Authenticate
[tls] processing EAP-TLS
[tls] Received TLS ACK
[tls] No SSL info available. Waiting for more SSL data.
[tls] eaptls_verify returned 1
[tls] eaptls_process returned 13
++[eap] returns handled
Sending Access-Challenge of id 202 to 138.120.206.113 port 10000
     EAP-Message = 0x010f000a0d8000000000
     Message-Authenticator = 0x00000000000000000000000000000000
     State = 0x056b0543036408967ef0ed7dafcf0427
Finished request 13.
Going to the next request

Thanks for any assistance,

Sven.

-- 
Sven A. Seelemann, P. Eng.
Alcatel-Lucent
SIT Designer
600 March Road, PO Box 13600
Ottawa, Ontario, CANADA K2K 2E6
email: sven.seelemann at alcatel-lucent.com
Phone: 613-784-3202
Fax: 613-599-3684