EAP abort in the middle of conversation

Stefan Winter stefan.winter at restena.lu
Tue Nov 21 15:26:34 CET 2006 

Hello,

today I stumbled over a very peculiar problem: an EAP exchange goes like this:

(eapol_test) -> FR 1.1.3 Access-Request (initial) ---------> (2 proxies) ---------> FR 1.1.3
(eapol_test) <- FR 1.1.3   <--------- (2 proxies) <--------- FR 1.1.3 Access-Challenge
(eapol_test) -> FR 1.1.3 Access-Request           ---------> (2 proxies) ---------> FR 1.1.3
(eapol_test) <- FR 1.1.3   <--------- (2 proxies) <--------- FR 1.1.3 Access-Reject

I.e. there is no networking issue, packet exchange works, but as soon as the second Access-Request
comes in, the request is rejected.

The -X log of the packet exchange in question gives a hint:

rad_recv: Access-Request packet from host 158.64....:1814, id=14, length=184
        User-Name = "someuser at restena.lu"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "70-6F-6C-69-73-68"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "rad_eap_test + eapol_test"
        EAP-Message = 0x0200001e0174657374757365722e616c6c6f774072657374656e612e6c75
        Message-Authenticator = 0xa701151b3e81f0317f3ffa1444b0fd06
        RESTENA-Service-Type = "eduroam-lu"
        Proxy-State = 0x313934
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 54
  hints: Matched DEFAULT at 109
  modcall[authorize]: module "preprocess" returns ok for request 54
radius_xlat:  '/var/log/radius/radacct/20061121/eduroam-lu-service/auth-detail'
rlm_detail: /var/log/radius/radacct/%Y%m%d/%{RESTENA-Service-Type}-service/auth-detail expands to /var/log/radius/radacct/20061121/eduroam-lu-service/auth-detail
  modcall[authorize]: module "nas_auth_log" returns ok for request 54
    rlm_realm: Looking up realm "restena.lu" for User-Name = "someuser at restena.lu"
    rlm_realm: Found realm "restena.lu"
    rlm_realm: Proxying request from user someuser to realm restena.lu
    rlm_realm: Adding Realm = "restena.lu"
    rlm_realm: Authentication realm is LOCAL.
  modcall[authorize]: module "suffix" returns noop for request 54
  modcall[authorize]: module "mschap" returns noop for request 54
  modcall[authorize]: module "files" returns notfound for request 54
  rlm_eap: EAP packet type response id 0 length 30
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 54
radius_xlat:  'testuser.allow at restena.lu'
rlm_sql (sql-normal-vpn): sql_set_user escaped user --> 'someuser at restena.lu'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'someuser at restena.lu' ORDER BY id'
rlm_sql (sql-normal-vpn): Reserving sql socket id: 2
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'someuser at restena.lu' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'someuser at restena.lu' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'someuser at restena.lu' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql-normal-vpn): Released sql socket id: 2
rlm_sql (sql-normal-vpn): No matching entry in the database for request from user [someuser at restena.lu]
  modcall[authorize]: module "sql-normal-vpn" returns notfound for request 54
modcall: leaving group authorize (returns updated) for request 54
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 54
  rlm_eap: EAP Identity
  rlm_eap: processing type tls
  rlm_eap_tls: Initiate
  rlm_eap_tls: Start returned 1
  modcall[authenticate]: module "eap" returns handled for request 54
modcall: leaving group authenticate (returns handled) for request 54
Sending Access-Challenge of id 14 to 158.64... port 1814
        EAP-Message = 0x010100061920
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xb6a7e30b6348a332f14e7da16cc90197
        Proxy-State = 0x313934
Finished request 54
Going to the next request
Waking up in 1 seconds...
rad_recv: Access-Request packet from host 158.64...:1814, id=15, length=160
        User-Name = "someuser at restena.lu"
        NAS-IP-Address = 127.0.0.1
        Calling-Station-Id = "70-6F-6C-69-73-68"
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "rad_eap_test + eapol_test"
        EAP-Message = 0x020100060315
        Message-Authenticator = 0x4109008e4025ee5df4b62db3e8feaa9d
        RESTENA-Service-Type = "eduroam-lu"
        Proxy-State = 0x313935
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 55
  hints: Matched DEFAULT at 109
  modcall[authorize]: module "preprocess" returns ok for request 55
radius_xlat:  '/var/log/radius/radacct/20061121/eduroam-lu-service/auth-detail'
rlm_detail: /var/log/radius/radacct/%Y%m%d/%{RESTENA-Service-Type}-service/auth-detail expands to /var/log/radius/radacct/20061121/eduroam-lu-service/auth-detail
  modcall[authorize]: module "nas_auth_log" returns ok for request 55
    rlm_realm: Looking up realm "restena.lu" for User-Name = "someuser at restena.lu"
    rlm_realm: Found realm "restena.lu"
    rlm_realm: Proxying request from user someuser to realm restena.lu
    rlm_realm: Adding Realm = "restena.lu"
    rlm_realm: Authentication realm is LOCAL.
  modcall[authorize]: module "suffix" returns noop for request 55
  modcall[authorize]: module "mschap" returns noop for request 55
  modcall[authorize]: module "files" returns notfound for request 55
  rlm_eap: EAP packet type response id 1 length 6
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 55
radius_xlat:  'someuser at restena.lu'
rlm_sql (sql-normal-vpn): sql_set_user escaped user --> 'someuser at restena.lu'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'someuser at restena.lu' ORDER BY id'
rlm_sql (sql-normal-vpn): Reserving sql socket id: 1
radius_xlat:  'SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op  FROM radgroupcheck,usergroup WHERE usergroup.Username = 'someuser at restena.lu' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'someuser at restena.lu' ORDER BY id'
radius_xlat:  'SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op  FROM radgroupreply,usergroup WHERE usergroup.Username = 'someuser at restena.lu' AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql-normal-vpn): Released sql socket id: 1
rlm_sql (sql-normal-vpn): No matching entry in the database for request from user [someuser at restena.lu]
  modcall[authorize]: module "sql-normal-vpn" returns notfound for request 55
modcall: leaving group authorize (returns updated) for request 55
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 55
rlm_eap: Either EAP-request timed out OR EAP-response to an unknown EAP-request
  rlm_eap: Failed in handler
  modcall[authenticate]: module "eap" returns invalid for request 55
modcall: leaving group authenticate (returns invalid) for request 55
auth: Failed to validate the user.
Login incorrect: [someuser at restena.lu] (from client ... port 0 cli 70-6F-6C-69-73-68)

Now, the message "rlm_eap: Either EAP-request timed out OR EAP-response to an unknown EAP-request"

seems definitive, but it is definitely not a timeout (all happens within a few seconds,
and eap.conf timeout is set to 60), and the EAP request really should be known, it's a
conversation that started only a few millis ago.

I would guess that eapol_test might be broken, but strangely enough it works perfectly
when initiating an EAP exchange to another server that ends up at the same home server.
So, the only thing that's different is the first-in-line FR 1.1.3 server.
I'm perfectly clueless here :-( Why would the EAP conversation be unknown?

All FR servers in the chain are 1.1.3, there is one Radiator server in the proxy chain.

Greetings,

Stefan Winter

-- 
Stefan WINTER

Stiftung RESTENA - Réseau Téléinformatique de l'Education Nationale et de 
la Recherche
Ingenieur Forschung & Entwicklung

6, rue Richard Coudenhove-Kalergi
L-1359 Luxembourg
E-Mail: stefan.winter at restena.lu     Tel.:     +352 424409-1
http://www.restena.lu                Fax:      +352 422473
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20061121/d65a93c5/attachment.pgp>

More information about the Freeradius-Users mailing list