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
Stefan Winter wrote: ...
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: ... Sending Access-Challenge of id 14 to 158.64... port 1814 EAP-Message = 0x010100061920 State = 0xb6a7e30b6348a332f14e7da16cc90197 ... rad_recv: Access-Request packet from host 158.64...:1814, id=15, length=160
Where's the State attribute? It's *required* to be there for EAP to work. Either the client is dropping State, or one of the proxies is dropping it.
EAP-Message = 0x020100060315
And in any case, that's an EAP NAK, asking for TTLS. This could arguably be considered valid behavior by the client. i.e. it doesn't need the State attribute, because it's not continuing the previous EAP type.
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.
My guess, then, is that one of the other servers is deleting the State attribute. *Please* follow the packets in *both* paths from client through all of the servers, to see what's happening. In order to fix this issue, it's important to know where the State attribute is disappearing, and why.
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.
My guess is that Radiator is throwing away the State attribute. I know FreeRADIUS doesn't. The "unknown EAP conversation" checks could be relaxed a little for EAP type NAK, but that would mean starting over at EAP Identity, because the server has no way of looking up the original identity... because there's no State attribute. All in all, I think one of the proxies is broken. If it's Radiator, discuss it with them, and we can hash it out. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Hi Alan,
Where's the State attribute? It's *required* to be there for EAP to work. Either the client is dropping State, or one of the proxies is dropping it.
All in all, I think one of the proxies is broken. If it's Radiator, discuss it with them, and we can hash it out.
Actually, the first-in-line FR 1.1.3 is the one that behaved strangely. I configured the attr_filter module in the post-proxy section, because I may receive attributes like VLAN id's from upstream proxies which are either meaningless or even harmful. Problem is: the shipped $raddbdir/attrs file strips off EAP conversations completely, so I had to edit it to allow EAP-Message to go through. While doing that, I forgot the State attribute (and wasn't even aware that it is so crucial; time for a little RTFRFC). Now that I added State =* ANY to the list of allowed attributes things work like a charm. But I would like to suggest to add at least EAP-Message and State in the default attrs file that's shipped. This was really an ugly caveat. 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
Stefan Winter wrote:
Problem is: the shipped $raddbdir/attrs file strips off EAP conversations completely, so I had to edit it to allow EAP-Message to go through. While doing that, I forgot the State attribute (and wasn't even aware that it is so crucial; time for a little RTFRFC). Now that I added State =* ANY to the list of allowed attributes things work like a charm.
Ah... ok.
But I would like to suggest to add at least EAP-Message and State in the default attrs file that's shipped. This was really an ugly caveat.
Fixed, thanks. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
But I would like to suggest to add at least EAP-Message and State in the default attrs file that's shipped. This was really an ugly caveat.
Fixed, thanks.
Hm, while you're at it: I also added MS-MPPE-Recv-Key =* ANY, MS-MPPE-Send-Key =* ANY, MS-CHAP-MPPE-Keys =* ANY, because Wireless LAN encryption keying material often accompanies EAP requests in these attributes. Is that another candidate? Stefan -- 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
Stefan Winter wrote:
Hm, while you're at it: I also added
MS-MPPE-Recv-Key =* ANY, MS-MPPE-Send-Key =* ANY, MS-CHAP-MPPE-Keys =* ANY,
because Wireless LAN encryption keying material often accompanies EAP requests in these attributes. Is that another candidate?
Yes, thanks. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
participants (2)
-
Alan DeKok -
Stefan Winter