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@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@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@restena.lu' rlm_sql (sql-normal-vpn): sql_set_user escaped user --> 'someuser@restena.lu' radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'someuser@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@restena.lu' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id' radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'someuser@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@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@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@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@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@restena.lu' rlm_sql (sql-normal-vpn): sql_set_user escaped user --> 'someuser@restena.lu' radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'someuser@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@restena.lu' AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id' radius_xlat: 'SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'someuser@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@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@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@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@restena.lu Tel.: +352 424409-1 http://www.restena.lu Fax: +352 422473