Issue with EAP authentication on packet loss
Hello, We have a problem when packet loss occurs at step #4 of the EAP dialogue: 1) Access-Request 2) Access-Challenge 3) Access-Request 4) Accept or Reject (in this case: Access-Accept) 5) Access-Request (duplicate) 6) Reject In this case, #4 is sent by the server but gets lost on its way to the NAS. I've managed to reproduce using iptables dropping the packet. So after some time the NAS sends packet #3 again. At that point I am getting "No EAP session matching state" from the eap module in the "authenticate" section and the request is rejected. This is consistent with what we see in step #4 (upon sending the Access-Accept which gets lost), namely this: (1) eap : Expiring EAP session with state 0x2f8521a02f84259c (1) eap : Finished EAP session with state 0x2f8521a02f84259c (1) eap : Previous EAP request found for state 0x2f8521a02f84259c, released from the list Who's at fault? How do you solve this (except for not using UDP)? Do you set aggressive timeouts/retries on the NAS? Thanks, Marki
Find and fix the packet loss cause alan On Wed, 25 Apr 2018, 08:53 , <jm+freeradiususer@roth.lu> wrote:
Hello,
We have a problem when packet loss occurs at step #4 of the EAP dialogue: 1) Access-Request 2) Access-Challenge 3) Access-Request 4) Accept or Reject (in this case: Access-Accept) 5) Access-Request (duplicate) 6) Reject
In this case, #4 is sent by the server but gets lost on its way to the NAS. I've managed to reproduce using iptables dropping the packet. So after some time the NAS sends packet #3 again. At that point I am getting "No EAP session matching state" from the eap module in the "authenticate" section and the request is rejected.
This is consistent with what we see in step #4 (upon sending the Access-Accept which gets lost), namely this: (1) eap : Expiring EAP session with state 0x2f8521a02f84259c (1) eap : Finished EAP session with state 0x2f8521a02f84259c (1) eap : Previous EAP request found for state 0x2f8521a02f84259c, released from the list
Who's at fault? How do you solve this (except for not using UDP)? Do you set aggressive timeouts/retries on the NAS?
Thanks, Marki
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi,
We have a problem when packet loss occurs at step #4 of the EAP dialogue: 1) Access-Request 2) Access-Challenge 3) Access-Request 4) Accept or Reject (in this case: Access-Accept) 5) Access-Request (duplicate) 6) Reject
In this case, #4 is sent by the server but gets lost on its way to the NAS. I've managed to reproduce using iptables dropping the packet. So after some time the NAS sends packet #3 again. At that point I am getting "No EAP session matching state" from the eap module in the "authenticate" section and the request is rejected.
To be fair, this is not limited to packet loss. We've seen this in normal operations - the story goes like: - server sends Access-Accept with an attribute X via a chain of proxies - some proxy takes offence by the presence of attribute X, discards - client times out and re-sends - server has forgotten all about the session state, rejects I believe the underlying issue is that FreeRADIUS thinks "fire and forget" when the final packet is out. IMHO it would be useful to maintain session state as it does for any of the intermediate packets (30s by default?). Stefan -- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 2, avenue de l'Université L-4365 Esch-sur-Alzette Tel: +352 424409 1 Fax: +352 422473 PGP key updated to 4096 Bit RSA - I will encrypt all mails if the recipient's key is known to me http://pgp.mit.edu:11371/pks/lookup?op=get&search=0xC0DE6A358A39DC66
On Apr 25, 2018, at 8:45 PM, Stefan Winter <stefan.winter@RESTENA.LU> wrote:
Hi,
We have a problem when packet loss occurs at step #4 of the EAP dialogue: 1) Access-Request 2) Access-Challenge 3) Access-Request 4) Accept or Reject (in this case: Access-Accept) 5) Access-Request (duplicate) 6) Reject
In this case, #4 is sent by the server but gets lost on its way to the NAS. I've managed to reproduce using iptables dropping the packet. So after some time the NAS sends packet #3 again. At that point I am getting "No EAP session matching state" from the eap module in the "authenticate" section and the request is rejected.
To be fair, this is not limited to packet loss.
We've seen this in normal operations - the story goes like: - server sends Access-Accept with an attribute X via a chain of proxies - some proxy takes offence by the presence of attribute X, discards - client times out and re-sends - server has forgotten all about the session state, rejects
I believe the underlying issue is that FreeRADIUS thinks "fire and forget" when the final packet is out.
It should cache the response for the duration of cleanup_delay. If it's not, then that's a bug. -Arran
On 4/25/2018 12:39 PM, Arran Cudbard-Bell wrote:
On Apr 25, 2018, at 8:45 PM, Stefan Winter <stefan.winter@RESTENA.LU> wrote:
Hi,
We have a problem when packet loss occurs at step #4 of the EAP dialogue: 1) Access-Request 2) Access-Challenge 3) Access-Request 4) Accept or Reject (in this case: Access-Accept) 5) Access-Request (duplicate) 6) Reject
In this case, #4 is sent by the server but gets lost on its way to the NAS. I've managed to reproduce using iptables dropping the packet. So after some time the NAS sends packet #3 again. At that point I am getting "No EAP session matching state" from the eap module in the "authenticate" section and the request is rejected. To be fair, this is not limited to packet loss.
We've seen this in normal operations - the story goes like: - server sends Access-Accept with an attribute X via a chain of proxies - some proxy takes offence by the presence of attribute X, discards - client times out and re-sends - server has forgotten all about the session state, rejects
I believe the underlying issue is that FreeRADIUS thinks "fire and forget" when the final packet is out. It should cache the response for the duration of cleanup_delay. If it's not, then that's a bug.
-Arran
Unfortunately, that doesn't seem to be the case. Final packet sent to the NAS (which is lost): (5) eap: Expiring EAP session with state 0x88491844885a1c9c (5) eap: Finished EAP session with state 0x88491844885a1c9c (5) eap: Previous EAP request found for state 0x88491844885a1c9c, released from the list NAS retries after 15 < cleanup_delay = 20 seconds: No success: (even Wireshark detects it as a duplicate, so I guess it is actually a repetition of the initial packet) (6) eap: ERROR: rlm_eap (EAP): No EAP session matching state 0x88491844885a1c9c (6) eap: Either EAP-request timed out OR EAP-response to an unknown EAP-request (6) eap: Failed in handler From the mails that Alan posted this seems to be slightly more complicated.
On Apr 25, 2018, at 10:45 AM, jm+freeradiususer@roth.lu wrote:
Unfortunately, that doesn't seem to be the case.
Final packet sent to the NAS (which is lost): (5) eap: Expiring EAP session with state 0x88491844885a1c9c (5) eap: Finished EAP session with state 0x88491844885a1c9c (5) eap: Previous EAP request found for state 0x88491844885a1c9c, released from the list
NAS retries after 15 < cleanup_delay = 20 seconds: No success: (even Wireshark detects it as a duplicate, so I guess it is actually a repetition of the initial packet)
If it's a duplicate packet, then the duplicate detection cache should catch it. Especially if cleanup_delay is 20 seconds, and the NAS retransmits after 15.
(6) eap: ERROR: rlm_eap (EAP): No EAP session matching state 0x88491844885a1c9c (6) eap: Either EAP-request timed out OR EAP-response to an unknown EAP-request (6) eap: Failed in handler
That means the packet *wasn't* found in the duplicate detection cache. If it can be reproduced in 6 packets, then do "radiusd -Xx" and send that to the list. This is one of the few times where the extra 'x' is useful. Alan DeKok.
On 4/25/2018 4:51 PM, Alan DeKok wrote:
On Apr 25, 2018, at 10:45 AM, jm+freeradiususer@roth.lu wrote:
Unfortunately, that doesn't seem to be the case.
Final packet sent to the NAS (which is lost): (5) eap: Expiring EAP session with state 0x88491844885a1c9c (5) eap: Finished EAP session with state 0x88491844885a1c9c (5) eap: Previous EAP request found for state 0x88491844885a1c9c, released from the list
NAS retries after 15 < cleanup_delay = 20 seconds: No success: (even Wireshark detects it as a duplicate, so I guess it is actually a repetition of the initial packet) If it's a duplicate packet, then the duplicate detection cache should catch it. Especially if cleanup_delay is 20 seconds, and the NAS retransmits after 15.
(6) eap: ERROR: rlm_eap (EAP): No EAP session matching state 0x88491844885a1c9c (6) eap: Either EAP-request timed out OR EAP-response to an unknown EAP-request (6) eap: Failed in handler That means the packet *wasn't* found in the duplicate detection cache.
If it can be reproduced in 6 packets, then do "radiusd -Xx" and send that to the list. This is one of the few times where the extra 'x' is useful.
Ha! The 3.x branch has a limit: Thu Apr 26 17:04:35 2018 : Warning: WARNING: Ignoring "cleanup_delay = 20", forcing to "cleanup_delay = 10" The docs talk about "useful ranges", not ranges being capped ;-) Well guess I need to find out how to tweak the NAS then (and hope a delay < 10 solves the issue) Sidenotes: At first I was not sure if simulating packet loss using iptables was the correct way because it generated : Wed Apr 25 17:21:53 2018 : ERROR: (5) Failed sending reply: sendto failed: Operation not permitted Then I tried NATing the concerned output packets to a blackhole address but for some reason the freeradius traffic does not seem to go through netfilter's NAT tables even though I am able to use its filter tables (as I outlined above). Strange. Then I tried blackhole routing the reply which seems to have worked, so for future reference: iptables -t mangle -A OUTPUT -j MARK --set-mark 6 -p udp --sport 1812 -m string --algo bm --string "123456789ABC" ip route add table 6 default via 127.0.0.1 ip route flush cache To reset: ip route flush table 6 ip route flush cache
Is it normal that the action taken upon receiving the duplicate packet is not shown at all in the debug output? Wireshark: 15 17:54:30.622417450 1.2.3.125 → 1.2.3.98 RADIUS 123456A8E3D3 Access-Request(1) (id=61, l=152) 16 17:54:30.624047615 1.2.3.98 → 1.2.3.125 RADIUS EAP-MD5-CHALLENGE MAC:12-34-56-A8-E3-D3, VLAN:100, NAS:1.2.3.125, Port:109. Access-Challenge(11) (id=61, l=179) 17 17:54:30.627810988 1.2.3.125 → 1.2.3.98 RADIUS 123456A8E3D3 Access-Request(1) (id=62, l=175) 18 17:54:34.128405714 1.2.3.125 → 1.2.3.98 RADIUS 123456A8E3D3 Access-Request(1) (id=62, l=175), Duplicate Request 19 17:54:34.128543224 1.2.3.98 → 1.2.3.125 RADIUS 123456A8E3D3 Access-Accept(2) (id=62, l=75) Freeradius: Thu Apr 26 17:54:30 2018 : Debug: (3) Finished request Thu Apr 26 17:54:30 2018 : Debug: Waking up in 9.9 seconds. Thu Apr 26 17:54:34 2018 : Debug: Waking up in 6.4 seconds. Thu Apr 26 17:54:40 2018 : Debug: (2) Cleaning up request packet ID 61 with timestamp +60 Thu Apr 26 17:54:40 2018 : Debug: Waking up in 10.0 seconds. Thu Apr 26 17:54:50 2018 : Debug: (3) Cleaning up request packet ID 62 with timestamp +60 Thu Apr 26 17:54:50 2018 : Info: Ready to process requests At one point I thought I was going crazy there...
On Apr 25, 2018, at 4:45 AM, Stefan Winter <stefan.winter@restena.lu> wrote:
To be fair, this is not limited to packet loss.
We've seen this in normal operations - the story goes like: - server sends Access-Accept with an attribute X via a chain of proxies - some proxy takes offence by the presence of attribute X, discards
Such proxies are broken and should not be used. <mumble IAS>
- client times out and re-sends
That's the issue... resends *what* ? Not the same packet, because the original request has timed out. So the client sends a new packet, with a new ID. And the proxies send another new packet when they proxy it. And the home server receives a brand new RADIUS packet. That RADIUS packet contains a State attribute from (say) 10 seconds ago. But the original RADIUS request and reply are long gone.
- server has forgotten all about the session state, rejects
As it should. (mostly)
I believe the underlying issue is that FreeRADIUS thinks "fire and forget" when the final packet is out.
The server caches replies for 5s. If it receives an *identical* request, it resends the identical response. In a sequence of packets, the server caches requests and replies for *all* of them, for 5s. But that has limitations. Let's say we have: packet N ID X State S1 packet N+ 1 ID Y State S2 * if the client (or proxy) sends a NEW packet which re-uses ID X, then the server tosses the cached request / reply, and processes the new packet * the same goes for ID Y, of course * States S1 and S2 are tracked by the EAP module (for the sake of discussion) so that it can track ongoing EAP sessions The problem comes when ID X is re-used, and the client "retransmits" packet N, with ID Z, and State S1. This packet isn't detected as a retransmission, because it has ID Z (not ID X). So it gets passed to the EAP module. For fairly good reasons, the EAP module doesn't keep State attributes around for minutes. Once it moves to the next state, it discards the previous one. This makes sense, because the EAP module has no idea what is in the final reply. For Access-Challenge it's mostly EAP stuff. But the same issue can be seen with Access-Accept, so we have to deal with that, too. There is a solution, I think. It involves the cache module. The idea is this: * when sending an Access-Challenge, the server should: * cache all attributes in the reply * using a key of State in the request * when receiving an Access-Request, the server should: * look up the State in the cache * if found, send back the cached reply attributes * using whatever packet (accept / challenge) from the original reply That should mostly work. Except the cache will get huge, because it isn't cleaned up. The solution is to clean up packet with State S1 when you get the *next* packet in sequence, with state S2. i.e.: * when sending an Access-Challenge, the server should ALSO * add a SECOND cache entry containing only the State from the request - S1 * and an internal attribute saying "this isn't a real reply" * using a key of the State in the *reply* - S2 * when receiving an Access-Request, the server should FIRST * look up the State in the cache (this should be S2) * if the cache entry is marked as "this isn't a real reply', THEN * the cache entry contains State S1, which is pointer to the previously cached attributes * delete the cache entry for the State S1, as we know the end user has received the previous reply This lets the server "clean up" old cache entries when the *end users system* moves to the next packet. I think that could be done in unlang with a bit of cache, in v3. We haven't done it until now because the cache module is fairly new. And, 99.99% of the time everything works. But... even if we did this, it wouldn't solve the problem of intermediate proxies dropping replies. If they dropped a reply because of a "bad attribute", the next reply will include that attribute, and the proxy will drop it again. This change would only help with transient networking issues. Which I suspect is pretty much every day for Eduroam. :( Alan DeKok.
Hmm... I've tried to do this with unlang and the cache module in v3. It's possible, but complex. It might be simpler to just write a new module that does this. It doesn't need persistence, because if the server restarts, all EAP sessions are tossed. So it can just be an in-memory thing. And, doing lookups is hard with the cache module. i.e. look up something, but *don't* pollute the existing request, just look something up. I suspect I can probably write something in less than a day. I'll take a look. Alan DeKok.
Hi,
This lets the server "clean up" old cache entries when the *end users system* moves to the next packet.
Yes, that's arguably the more correct thing to do. After all EAP is a lock-step protocol, and until one side isn't sure that the other side has taken the next step, it must be prepared to repeat the previous step.
But... even if we did this, it wouldn't solve the problem of intermediate proxies dropping replies. If they dropped a reply because of a "bad attribute", the next reply will include that attribute, and the proxy will drop it again.
Yes, but: it will then consistently drop. So far, FreeRADIUS changes the drop to a Reject on second try, which is even less intuitive than a bad, but consistent behaviour.
This change would only help with transient networking issues. Which I suspect is pretty much every day for Eduroam. :(
Our backbones are really very well-maintained and error-free :-) Greetings, Stefan -- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 2, avenue de l'Université L-4365 Esch-sur-Alzette Tel: +352 424409 1 Fax: +352 422473 PGP key updated to 4096 Bit RSA - I will encrypt all mails if the recipient's key is known to me http://pgp.mit.edu:11371/pks/lookup?op=get&search=0xC0DE6A358A39DC66
On Apr 25, 2018, at 7:52 PM, jm+freeradiususer@roth.lu wrote:
Hello,
We have a problem when packet loss occurs at step #4 of the EAP dialogue: 1) Access-Request 2) Access-Challenge 3) Access-Request 4) Accept or Reject (in this case: Access-Accept) 5) Access-Request (duplicate) 6) Reject
In this case, #4 is sent by the server but gets lost on its way to the NAS. I've managed to reproduce using iptables dropping the packet. So after some time the NAS sends packet #3 again. At that point I am getting "No EAP session matching state" from the eap module in the "authenticate" section and the request is rejected.
This is consistent with what we see in step #4 (upon sending the Access-Accept which gets lost), namely this: (1) eap : Expiring EAP session with state 0x2f8521a02f84259c (1) eap : Finished EAP session with state 0x2f8521a02f84259c (1) eap : Previous EAP request found for state 0x2f8521a02f84259c, released from the list
Who's at fault? How do you solve this (except for not using UDP)? Do you set aggressive timeouts/retries on the NAS?
Yeah you can do that. What's happening are there are internal timers that cleanup the session information (keyed off the State attribute), so when that retransmission comes in the session has already been cleared out. In v3.0.x the state tree cleanup time is main_config.max_request_time * 10. In v4.0.x the state tree cleanup time is continuation_timeout which defaults to 15. You should try and fix the underlying issue before going down the route of tweaking timers though. -Arran
On 4/25/2018 10:55 AM, Arran Cudbard-Bell wrote:
What's happening are there are internal timers that cleanup the session information (keyed off the State attribute), so when that retransmission comes in the session has already been cleared out.
In v3.0.x the state tree cleanup time is main_config.max_request_time * 10.
I don't believe this applies here. max_request_time * 10 would be 300 seconds. The second attempt from the NAS comes in after 15 seconds. So there's plenty of time. As I have shown, debugging output clearly throws away the session instantly during the first response (which is getting lost). BTW this is happening every now and then only. I don't think that's abnormal, but it's not cool when reauthentications are being used and users are disconnected for a few minutes until the NAS retries the a completely new authentication.
On Apr 25, 2018, at 9:09 PM, jm+freeradiususer@roth.lu wrote:
On 4/25/2018 10:55 AM, Arran Cudbard-Bell wrote:
What's happening are there are internal timers that cleanup the session information (keyed off the State attribute), so when that retransmission comes in the session has already been cleared out.
In v3.0.x the state tree cleanup time is main_config.max_request_time * 10.
I don't believe this applies here. max_request_time * 10 would be 300 seconds. The second attempt from the NAS comes in after 15 seconds. So there's plenty of time.
Ah then what's happening is the state entry is being removed from the tree when the request is processed, and a new entry inserted for the next round. When the response is sent that's cached by the server and that's controlled by another config item which is cleanup_delay. When your request is coming in it must be after cleanup delay, so it's treated as a new request and the state lookup code fails because the previous entry has already been removed.
BTW this is happening every now and then only. I don't think that's abnormal,
It's pretty abnornal for the responses not to reach or be processed by the NAS.
but it's not cool when reauthentications are being used and users are disconnected for a few minutes until the NAS retries the a completely new authentication.
Increase cleanup_delay, decrease retransmission interval on your NAS, prioritise RADIUS traffic so it's not lost, fix any odd things between the NAS and the RADIUS server. -Arran
participants (5)
-
Alan Buxey -
Alan DeKok -
Arran Cudbard-Bell -
jm+freeradiususer＠roth.lu -
Stefan Winter