On 09/10/2011 09:28 PM, Arran Cudbard-Bell wrote:

On 10 Sep 2011, at 17:49, rihad wrote:

...

Hi, sometimes when a NAS with many users reboots FreeRADIUS is unable to cope with the number of incoming requests: How many users ?

Around 6-8k online.

...

Sat Sep 10 13:23:16 2011 : Auth: Login OK: [5702018] (from client 10.10.70.100 port 0) Sat Sep 10 13:23:16 2011 : Error: Received conflicting packet from client 10.10.70.98 port 1645 - ID: 131 due to unfinished request 2814. Giving up on old request. Sat Sep 10 13:23:16 2011 : Auth: Login OK: [5026706] (from client 10.10.70.38 port 0) Sat Sep 10 13:23:16 2011 : Error: Received conflicting packet from client 10.10.70.93 port 1646 - ID: 117 due to unfinished request 1036. Giving up on old request. Sat Sep 10 13:23:16 2011 : Auth: Login OK: [4925140] (from client 10.10.70.93 port 0) Sat Sep 10 13:23:16 2011 : Error: Received conflicting packet from client 10.10.70.60 port 1645 - ID: 109 due to unfinished request 3370. Giving up on old request. Sat Sep 10 13:23:16 2011 : Auth: Login OK: [4977364] (from client 10.10.70.38 port 0) Sat Sep 10 13:23:16 2011 : Error: Received conflicting packet from client 10.10.70.93 port 1646 - ID: 118 due to unfinished request 1040. Giving up on old request. Sat Sep 10 13:23:16 2011 : Error: Received conflicting packet from client 10.10.70.60 port 1645 - ID: 110 due to unfinished request 3373. Giving up on old request. Sat Sep 10 13:23:16 2011 : Auth: Login OK: [4529464] (from client 10.10.70.28 port 0) Sat Sep 10 13:23:16 2011 : Error: Received conflicting packet from client 10.10.70.98 port 1645 - ID: 132 due to unfinished request 2829. Giving up on old request.

and ad infinitum. The duplicate requests come from PPPoE clients after they fail to receive a response within 5 seconds or so. Yes its retransmitting the packets because it assumed they were lost in transit.

...

The problem can then be solved by restarting the daemon once or twice and watching the errors go away. The fact that dropping all current work helped gave me this idea: wouldn't it be nice if FreeRADIUS dropped both the old _and_ the new request at the time it logged that "giving up" message? No... Because then it'd never respond to either request. In a normal network (not under overload condition) if two packets were not lost but delayed, then both reach the server at around the same time, the server would end up dropping both requests ...and there's a bunch of other reasons depending on the deployment scenario.

Don't you think 5 second delay is pretty unusual for a LAN. Yes, UDP acct packets sometimes get dropped and never reach the server, but the delay... It's much safer to sometimes drop 2 auth requests in a row for the reason you stated than allow the server to reach a point where it's unable to make further progress doing _current_ work.

...

That would at least allow it to make progress. BTW, I'm not sure why, but under comparable workloads openradius does not exhibit this problem. What are you doing with FreeRADIUS which is taking such a long time to complete? The log messages are a symptom not a cause.

That's hundreds if not thousands (if you count acct packets too) of requests all reaching the server nearly at the same time. Tomorrow early in the morning I'll try the fix and see how it goes. Thanks for all the info you gave.

...

Any suggestions?

Fix whatever backend is getting overloaded and making FreeRADIUS wait for> 5 seconds to send a response...

-Arran

Arran Cudbard-Bell a.cudbardb@freeradius.org

RADIUS - Waging war on ignorance and apathy one Access-Challenge at a time.

On 09/10/2011 10:20 PM, Arran Cudbard-Bell wrote:

Sat Sep 10 13:23:16 2011 : Auth: Login OK: [5702018] (from client 10.10.70.100 port 0)

...

...

...

Sat Sep 10 13:23:16 2011 : Error: Received conflicting packet from client 10.10.70.98 port 1645 - ID: 131 due to unfinished request 2814. Giving up on old request. Sat Sep 10 13:23:16 2011 : Auth: Login OK: [5026706] (from client 10.10.70.38 port 0) Sat Sep 10 13:23:16 2011 : Error: Received conflicting packet from client 10.10.70.93 port 1646 - ID: 117 due to unfinished request 1036. Giving up on old request. Sat Sep 10 13:23:16 2011 : Auth: Login OK: [4925140] (from client 10.10.70.93 port 0) Sat Sep 10 13:23:16 2011 : Error: Received conflicting packet from client 10.10.70.60 port 1645 - ID: 109 due to unfinished request 3370. Giving up on old request. Sat Sep 10 13:23:16 2011 : Auth: Login OK: [4977364] (from client 10.10.70.38 port 0) Sat Sep 10 13:23:16 2011 : Error: Received conflicting packet from client 10.10.70.93 port 1646 - ID: 118 due to unfinished request 1040. Giving up on old request. Sat Sep 10 13:23:16 2011 : Error: Received conflicting packet from client 10.10.70.60 port 1645 - ID: 110 due to unfinished request 3373. Giving up on old request. Sat Sep 10 13:23:16 2011 : Auth: Login OK: [4529464] (from client 10.10.70.28 port 0) Sat Sep 10 13:23:16 2011 : Error: Received conflicting packet from client 10.10.70.98 port 1645 - ID: 132 due to unfinished request 2829. Giving up on old request.

and ad infinitum. The duplicate requests come from PPPoE clients after they fail to receive a response within 5 seconds or so. Yes its retransmitting the packets because it assumed they were lost in transit.

...

The problem can then be solved by restarting the daemon once or twice and watching the errors go away. The fact that dropping all current work helped gave me this idea: wouldn't it be nice if FreeRADIUS dropped both the old _and_ the new request at the time it logged that "giving up" message? No... Because then it'd never respond to either request. In a normal network (not under overload condition) if two packets were not lost but delayed, then both reach the server at around the same time, the server would end up dropping both requests ...and there's a bunch of other reasons depending on the deployment scenario.

Don't you think 5 second delay is pretty unusual for a LAN. Yes. But not everyone configures a 5 second retransmit period. Not everyone is trying to send RADIUS packets over a pure ethernet network with low latency, and even with ethernet, things like spanning-tree topology changes can have really weird effects on duplicate packets, even if the protocol tries to minimise it.

...

Yes, UDP acct packets sometimes get dropped and never reach the server, but the delay... It's much safer to sometimes drop 2 auth requests in a row for the reason you stated than allow the server to reach a point where it's unable to make further progress doing _current_ work. Why are you processing auth requests that you know cannot complete? The server should be configured such that the number of requests assigns to its threads is smaller than the number of requests that will cause your backend AAA systems to have a processing latency greater than your NAS' retransmit period.

You're trying to fix the wrong thing. The server core is fine. Go fix the thread pool count.

Interesting. max_servers was 50 before today, I ramped it up to 100 after today's accident. A total of 24 CPU cores here. CPU: Intel(R) Xeon(R) CPU X5650 @ 2.67GHz (2661.34-MHz K8-class CPU) The disks are a fast SAS 15K RAID, w/ 12G of RAM. start_servers = 5 min_spare_servers = 5 max_spare_servers = 10 max_requests_per_server = 0 max_request_time = 120 # just so that it never triggers cleanup_delay = 10 max_requests = 500000 # just so that it never triggers But increasing them further doesn't seem relevant. You mean I should lower max_requests etc. to the point where I start getting the "too low max_requests" type of errors, and then up it a bit, but not by too much?

...

...

...

That would at least allow it to make progress. BTW, I'm not sure why, but under comparable workloads openradius does not exhibit this problem. What are you doing with FreeRADIUS which is taking such a long time to complete? The log messages are a symptom not a cause.

That's hundreds if not thousands (if you count acct packets too) of requests all reaching the server nearly at the same time. Yes but the server doesn't *have* to try and process them all at the same time. That is one of the other reasons for retransmit period.

-Arran

Arran Cudbard-Bell a.cudbardb@freeradius.org

RADIUS - Waging war on ignorance and apathy one Access-Challenge at a time.

rihad wrote:

Don't you think 5 second delay is pretty unusual for a LAN.

You misunderstand. The packets are reaching the server just fine. You've configured the server to do *something* strange. So it's taking more than 20 seconds to respond. This does not happen in the default configuration.

Yes, UDP acct packets sometimes get dropped and never reach the server, but the delay... It's much safer to sometimes drop 2 auth requests in a row for the reason you stated than allow the server to reach a point where it's unable to make further progress doing _current_ work.

*You* are the one who allowed the server to reach a point where it can't make progress. The server *is* dropping the authentication requests. See the log output you posted. I suggest understanding how RADIUS works before offering advice.

That's hundreds if not thousands (if you count acct packets too) of requests all reaching the server nearly at the same time.

The server can handle 1000's and even 10's of 1000's of packets per second. If you are seeing performance less than that, it's because you've configured something to be slow. i.e. you're putting the accounting packets into a slow DB, or a DB without indexes. When you make FreeRADIUS depend on something else like a slow DB, then the server performance is limited by that DB. Blaming FreeRADIUS isn not appropriate. Alan DeKok.

Tomorrow early in the morning I'll try the fix and see how it goes.

Thanks for all the info you gave.

...

...

Any suggestions?

Fix whatever backend is getting overloaded and making FreeRADIUS wait for> 5 seconds to send a response...

-Arran

Arran Cudbard-Bell a.cudbardb@freeradius.org

RADIUS - Waging war on ignorance and apathy one Access-Challenge at a time.

- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html

rihad wrote:

...

The server *is* dropping the authentication requests. See the log output you posted. The current ones, yes, but alas not the new ones. We only get the "conflicting packets" messages when the system is under load, like when a "heavy" NAS reboots. The code fix seems easy though.

The code fix is wrong. It won't do anything. You asked for help on this list. We gave you help. Rather than believing us, you insist on breaking the server even *more*.

I'm not blaming anyone.

Nonsense. You stated clearly that FreeRADIUS couldn't handle the load. It can handle the load. The reason it's not making progress is that *you* broke the system, and *you* are ignoring our advice.

Thanks for the great software and for sharing it with us. The great thing about open source is that I can tweak it to my needs. I'm not saying this is the best way to get rid of the problem. But it may be the easiest and the quickest.

Cutting your leg off will stop the pain from a broken toe. That doesn't make it a smart thing to do. Alan DeKok.

On 10 Sep 2011, at 20:23, Arran Cudbard-Bell wrote:

...

I'm not blaming anyone. Thanks for the great software and for sharing it with us. The great thing about open source is that I can tweak it to my needs. I'm not saying this is the best way to get rid of the problem. But it may be the easiest and the quickest. -

It's a really bad way to fix the problem. You're just masking the underlying issue doing this.

You need to figure out why your backend authentication system is taking more than 5 seconds to complete a request. Its that simple.

I'm suggesting lowering the max thread count to reduce the number of requests running in parallel to take load of your backend system, so it starts responding before the NAS retransmits the packet.

Likely there's much more that could be done to deal with high volumes of requests, but we would need to know what modules you're using with the server, and so far you've ignored all requests for this information.

If you just want to throw new requests away once the number queued gets stupidly large, use the undocumented parameter 'max_queue_size' in the threadpool stanza.

One the server has X number of pending requests, it'll start throwing new ones away, relying on the NAS' retransmit behaviour to eventually get the request processed.

-Arran

Arran Cudbard-Bell a.cudbardb@freeradius.org

Your NAS is also behaving very strangely. FreeRADIUS only gives up on processing a request if a request with a duplicate ID, SRC IP, and SRC PORT but a different REQUEST AUTHENTICATOR is received. When a NAS retransmits it should use the same ID, SRC IP, SRC PORT and REQUEST AUTHENTICATOR. Coming back to your first message, it could be than Open RADIUS implements different logic for processing retransmits and so you don't see the problem... The wrong logic in terms of standards compliance, but something that works around the broken NAS. If you have a example of the NAS you're using, point it at a real IP, but with no RADIUS server running, try and authenticate, and capture the packets. We'll be able to tell you very easily weather your NAS has implemented the correct retransmit behaviour. -Arran Arran Cudbard-Bell a.cudbardb@freeradius.org RADIUS - Waging war on ignorance and apathy one Access-Challenge at a time.

On 09/11/2011 11:11 AM, rihad wrote:

On 09/10/2011 11:23 PM, Arran Cudbard-Bell wrote:

...

...

I'm not blaming anyone. Thanks for the great software and for sharing it with us. The great thing about open source is that I can tweak it to my needs. I'm not saying this is the best way to get rid of the problem. But it may be the easiest and the quickest. - It's a really bad way to fix the problem. You're just masking the underlying issue doing this.

You need to figure out why your backend authentication system is taking more than 5 seconds to complete a request. Its that simple.

I'm suggesting lowering the max thread count to reduce the number of requests running in parallel to take load of your backend system, so it starts responding before the NAS retransmits the packet.

Likely there's much more that could be done to deal with high volumes of requests, but we would need to know what modules you're using with the server, and so far you've ignored all requests for this information. We're using preprocess, rlm_perl (for AAA), acct_unique, detail, attr_filter.accounting_response. If you just want to throw new requests away once the number queued gets stupidly large, use the undocumented parameter 'max_queue_size' in the threadpool stanza.

One the server has X number of pending requests, it'll start throwing new ones away, relying on the NAS' retransmit behaviour to eventually get the request processed. Great. First I thought of tweaking max_clients to the point where it never triggerred under "normal" load, but started dropping new request (and logging the fact) whenever the box couldn't cope with the current load. max_queue_size may turn out to be just as useful.

s/max_clients/max_requests/ I just dropped max_requests to a mere 512. That's around 50 requests per second given cleanup_delay=10. Enough for the normal load as it is now. I'll see how it goes.

rihad wrote:

We're using preprocess, rlm_perl (for AAA),

I think it's abundantly clear you don't understand what you're doing. Perl doesn't do AAA. Perl is a programming language. What I *suspect* you're doing is using Perl to connect to a DB. (Notice how I keep mentioning DB, and you keep ignoring it? Maybe it's important!) Your Perl script is breaking the server. Fix it. Any competent person should be able to make a 12 core system handle more than 50 request per second. FreeRADIUS was getting 100+ requests/s with MySQL over a decade ago. Alan DeKok.

On 11 Sep 2011, at 12:51, rihad wrote:

On 09/11/2011 01:58 PM, Alan DeKok wrote:

...

rihad wrote:

...

We're using preprocess, rlm_perl (for AAA), I think it's abundantly clear you don't understand what you're doing.

Perl doesn't do AAA. Perl is a programming language. In case I wasn't clear enough: Perl scripts servicing AAA requests.

...

What I *suspect* you're doing is using Perl to connect to a DB. (Notice how I keep mentioning DB, and you keep ignoring it? Maybe it's important!)

Your Perl script is breaking the server. Fix it. I know that. The auth & billing software we're using is admittedly slow. But see how easy it was to lower max_requests and allow FreeRADIUS to make progress on its own during load spikes (like when a NAS reboots). PPPoE clients (most of which are ADSL modems) retry auth anyway. Noting in radiusd.conf that max_clients shouldn't be set higher than the system can process within cleanup_delay seconds might save some poor soul their spare time in the future.

Cleanup delay just controls the lifetime of the request cache... If it is effecting how the server is performing that points to your NAS re-using IDs way too quickly. It may be that its pool of src ports is too small, or it only uses a single source port. Either way it's extremely specific to your case so not really useful advice for a wider audience.

Let me just quote Mr. Arran again:

...

Your NAS is also behaving very strangely. FreeRADIUS only gives up on processing a request if a request with a duplicate ID, SRC IP, and SRC PORT but a different REQUEST AUTHENTICATOR is received.

When a NAS retransmits it should use the same ID, SRC IP, SRC PORT and REQUEST AUTHENTICATOR. By this it should be clear that it's not NAS resending unanswered auth requests, but rather ADSL modems issuing _new_ requests.

Not necessarily, the NAS is using the same request ID, if this were a completely new request you'd expect that to change as well as the request authenticator. This behaviour has compounded the issue you're experiencing. Usually the NAS handles retransmits, and a retransmit would not cause the original request to be dropped like you're seeing. It's because the server thinks the NAS has given up waiting on the original request, and has looped through all 256 IDs, and is sending a new, completely unrelated request, that it trashes the original. This is not normal behaviour for a NAS, I would check to see if there's anything you could do to make the ADSL clients back off, and have the NAS handle retransmits, as well as what you've already done (if in fact the ADSL clients are handling the retransmits, i'm not convinced without seeing packet traces). Also, if you think processing the accounting data might be slowing down authentication processing you might want to consider using a detail writer and detail reader virtual server (there are examples in sites-available, robust something or other). The server can spool accounting requests to a detail file very quickly, much quicker than rlm_perl could process them. The reader intelligently throttles based on server load, so unless the billing software needs to be notified in real time of a client connecting or disconnecting, it's a very good solution for dealing with load spikes. -Arran Arran Cudbard-Bell a.cudbardb@freeradius.org RADIUS - Waging war on ignorance and apathy one Access-Challenge at a time.

...

Also, if you think processing the accounting data might be slowing down authentication processing you might want to consider using a detail writer and detail reader virtual server (there are examples in sites-available, robust something or other). The server can spool accounting requests to a detail file very quickly, much quicker than rlm_perl could process them. The reader intelligently throttles based on server load, so unless the billing software needs to be notified in real time of a client connecting or disconnecting, it's a very good solution for dealing with load spikes.

Thank you, Arran, I think the problem was solved because new requests are no longer accepted when the system is under heavy load, so FreeRADIUS can sustain the load spikes until they're over.

Undoubtedly. What I was saying is that you might want to prioritise traffic during a spike so that processing authentications take precedence over processing billing data, so your customers get a more reliable service, and can reconnect quickly. But yeah, i'm done with this thread. Seems like you have something that works for you... and i'm open to ideas for documentation, but your use case is a-typicial, and honestly I think tuning the number of worker threads is a better way of achieving what you're doing. Anyway we won't be changing the documentation, and we won't be adding your modification to the server. TTFN -Arran Arran Cudbard-Bell a.cudbardb@freeradius.org RADIUS - Waging war on ignorance and apathy one Access-Challenge at a time.

rihad wrote:

Did you mean something like decreasing max_servers (was: 50), and setting max_queue_size somewhere around 10?

You've made it clear that you are not interested in listening to advice. Why then ask questions on this list? You'd be better off unsubscribing. Alan DeKok.

rihad wrote:

Excuse me, sir, what exactly is the problem?

What part of my response did you not understand?

Is there anything wrong with my specific question above to Mr. Arran?

Yes. You have a history of asking questions, and ignoring the answers. So you're wasting your time, and ours, by asking questions. Alan DeKok.

On 09/11/2011 04:58 PM, Alan DeKok wrote:

rihad wrote:

...

On 09/11/2011 01:58 PM, Alan DeKok wrote:

...

Your Perl script is breaking the server. Fix it.

I know that. The auth& billing software we're using is admittedly slow. Then stop your complaints about FreeRADIUS. Don't change FreeRADIUS. It's fine.

...

But see how easy it was to lower max_requests and allow FreeRADIUS to make progress on its own during load spikes (like when a NAS reboots). That is a bad solution, and one which makes the problem worse.

It's a working one. Just think of it: some of the new requests get dropped because the server thinks it can't handle them right now: it has already received max_requests req's during the past cleanup_delay seconds. Doesn't my tweak do exactly this: src/main/event.c can_handle_new_request(): /* * FUTURE: Add checks for system load. If the system is * busy, start dropping requests... * * We can probably keep some statistics ourselves... if * there are more requests coming in than we can handle, * start dropping some. */ ?

...

PPPoE clients (most of which are ADSL modems) retry auth anyway. Noting in radiusd.conf that max_clients shouldn't be set higher than the system can process within cleanup_delay seconds might save some poor soul their spare time in the future. I doubt that. Everyone else ensures that their system can handle the load.

...

Let me just quote Mr. Arran again:

...

Your NAS is also behaving very strangely. FreeRADIUS only gives up on processing a request if a request with a duplicate ID, SRC IP, and SRC PORT but a different REQUEST AUTHENTICATOR is received.

When a NAS retransmits it should use the same ID, SRC IP, SRC PORT and REQUEST AUTHENTICATOR. By this it should be clear that it's not NAS resending unanswered auth requests, but rather ADSL modems issuing _new_ requests. That doesn't matter, even if it was true.

Pretty much every piece of equipment you have is horribly broken. Your solution is to break FreeRADIUS rather than the fix the equipment.

Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html

On 09/12/2011 01:14 AM, Alan Buxey wrote:

Hi,

...

It's a working one. Just think of it: some of the new requests get dropped because the server thinks it can't handle them right now: it has but the server can handle them - you jst need to fix your bottleneck. what is the bottleneck in your system? I'm going to guess its a database. it usually is. what is your database? MySQL? do you have indexes? do you clean up old junk? I have FreeRADIUS with postgresQL and can happily do 10k auths/second

Yes, MySQL, indexed. The billing software itself (abills.net.ua) is bulky and convoluted, written to be extremely inefficient. The box can do probably 30-50 req/s when a NAS reboots (judging by the logs). But I at least found a way how to easily let it crawl through. All I wanted was to find out how to drop new requests under heavy load. This will buy us a year or two.

On 09/10/2011 11:45 PM, Alan DeKok wrote:

rihad wrote:

...

BTW, I'm not sure why, but under comparable workloads openradius does not exhibit this problem. Look at the source code to OpenRADIUS. It doesn't do duplicate detection that's suggested by RFC 5080 (which I'm the author of). This is understandable, because the most recent release of OpenRADIUS is 4 years ago, before RFC 5080 was published.

So OpenRADIUS is worse than FreeRADIUS. It will process both the old and the new request, which *increases* the load on your system. And it *won't* tell you that there's a problem.

You are making a very, very, common mistake. You see an error message, and you're trying to get rid of the error message. You are *not* trying to understand the problem. You are *not* trying to solve the real problem.

Go find out why something is blocking FreeRADIUS. And this is bad, too:

...

The duplicate requests come from PPPoE clients after they fail to receive a response within 5 seconds or so. Your NAS is broken. Giving up on requests after 5 seconds is *stupid*. RFC 5080 suggests a better method. RADIUS clients in 1993 had better methods than "give up after 5s".

AFAIK it's not the NAS decision per se to resend the auth after about 5 seconds, but clients' ADSL modems'.

Use a NAS that isn't broken. Fix your database so it can handle the load.

*Don't* go poking at FreeRADIUS. It's fine.

Alan DeKok.

On 09/10/2011 11:45 PM, Alan DeKok wrote:

rihad wrote:

...

BTW, I'm not sure why, but under comparable workloads openradius does not exhibit this problem. Look at the source code to OpenRADIUS. It doesn't do duplicate detection that's suggested by RFC 5080 (which I'm the author of). This is understandable, because the most recent release of OpenRADIUS is 4 years ago, before RFC 5080 was published.

So OpenRADIUS is worse than FreeRADIUS. It will process both the old and the new request, which *increases* the load on your system. And it *won't* tell you that there's a problem.

You are making a very, very, common mistake. You see an error message, and you're trying to get rid of the error message. You are *not* trying to understand the problem. You are *not* trying to solve the real problem.

Go find out why something is blocking FreeRADIUS. And this is bad, too: I think I solved the issue by configuring max_requests so that it brakes at the right time. It wouldn't be bad to mention in radiusd.conf that max_requests divided by cleanup_delay should be set by the administrator to a value that is the expected maximum req/s supported by the system.

Just my 2 cents.