DHCP module and external DHCP relay
Hi! We use FreeRADIUS 2.2.0 as DHCP server with rlm_perl to connect to external database to run stored procedure there that returns IP/mask/DNS etc for option82-enabled requests. The database is pretty fast and serves hundreds of parallel requests in 1 second or less. FreeRADIUS receives all DHCP requests from external high loaded DHCP relay and threats them all as coming from single DHCP client. Our perl script does extensive logging through direct syslog connection and I see that there is great delay between the moment of DHCP request arrival as shown by tcpdump and the moment when post_auth perl function is invoked by FreeRADIUS. This delay is about 6 seconds and some DHCP clients do not wait for so long. Is it possible to eliminate these delays? Here are lines from radiusd log: Request 14280134 has been waiting in the processing queue for 6 seconds. Check that all databases are running properly! Discarding duplicate request from client dhcp port 67 - ID: 1381353109 due to unfinished request 14280311 Again, our database processes most request in less than 1 second and very seldom in 2 seconds but mentioned problem is persistent. Eugene Grosbein
Eugene Grosbein wrote:
We use FreeRADIUS 2.2.0 as DHCP server with rlm_perl to connect to external database to run stored procedure there that returns IP/mask/DNS etc for option82-enabled requests.
Why rlm_perl? Why not use rlm_sql directly? You can update the SQL qeuries to run a stored procedure. Then, make sure that the stored procedure returns "Attribute = value". The SQL module will then take care of parsing those attributes, and adding them to the reply.
The database is pretty fast and serves hundreds of parallel requests in 1 second or less.
That's bad. One second is *not* a fast response time for a database.
FreeRADIUS receives all DHCP requests from external high loaded DHCP relay and threats them all as coming from single DHCP client.
Our perl script does extensive logging through direct syslog connection and I see that there is great delay between the moment of DHCP request arrival as shown by tcpdump and the moment when post_auth perl function is invoked by FreeRADIUS.
Run FreeRADIUS in debugging mode to see why.
This delay is about 6 seconds and some DHCP clients do not wait for so long.
Is it possible to eliminate these delays? Here are lines from radiusd log:
Yes. Fix your database so it's fast. Remove the rlm_perl step.
Request 14280134 has been waiting in the processing queue for 6 seconds. Check that all databases are running properly!
That message is pretty definitive.
Discarding duplicate request from client dhcp port 67 - ID: 1381353109 due to unfinished request 14280311
Again, our database processes most request in less than 1 second and very seldom in 2 seconds but mentioned problem is persistent.
I'm not sure what else to say. FreeRADIUS can handle 50K requests/s all by itself. So if you're seeing responses delayed more than 20 microseconds, it's not FreeRADIUS. My guess is that it's a combination of (a) your database being slow, and (b) the Perl code not using the database efficiently. Alan DeKok.
On 04.04.2014 20:04, Alan DeKok wrote:
Eugene Grosbein wrote:
We use FreeRADIUS 2.2.0 as DHCP server with rlm_perl to connect to external database to run stored procedure there that returns IP/mask/DNS etc for option82-enabled requests.
Why rlm_perl? Why not use rlm_sql directly? You can update the SQL qeuries to run a stored procedure. Then, make sure that the stored procedure returns "Attribute = value". The SQL module will then take care of parsing those attributes, and adding them to the reply.
There is more logic in my perl script. It keeps pool of persistent connections to database, restarts them if they fail and fallbacks to local indexed storage if database does not respond at all.
The database is pretty fast and serves hundreds of parallel requests in 1 second or less.
That's bad. One second is *not* a fast response time for a database.
Generally, response time is much less than 1 second.
FreeRADIUS receives all DHCP requests from external high loaded DHCP relay and threats them all as coming from single DHCP client.
Our perl script does extensive logging through direct syslog connection and I see that there is great delay between the moment of DHCP request arrival as shown by tcpdump and the moment when post_auth perl function is invoked by FreeRADIUS.
Run FreeRADIUS in debugging mode to see why.
This delay is about 6 seconds and some DHCP clients do not wait for so long.
Is it possible to eliminate these delays? Here are lines from radiusd log:
Yes. Fix your database so it's fast. Remove the rlm_perl step.
Request 14280134 has been waiting in the processing queue for 6 seconds. Check that all databases are running properly!
That message is pretty definitive.
Discarding duplicate request from client dhcp port 67 - ID: 1381353109 due to unfinished request 14280311
Again, our database processes most request in less than 1 second and very seldom in 2 seconds but mentioned problem is persistent.
I'm not sure what else to say. FreeRADIUS can handle 50K requests/s all by itself. So if you're seeing responses delayed more than 20 microseconds, it's not FreeRADIUS.
My guess is that it's a combination of (a) your database being slow, and (b) the Perl code not using the database efficiently.
You missed the point. Perl script and database process request pretty fast and I have hundreds of free threads in the rlm_perl's pool. But FreeRADIUS dhcp module thinks that all requests from the same source are request from single client. This is plain wrong in case of DHCP relay in between DHCP clients and FreeRADIUS that is located in an isolated vlan. So, FreeRADIUS queues requests and does not pass them to rlm_perl instantly as it should. 6 seconds is delay between DHCP request arrival to the box via network interface and invoke of post_auth perl function. Basically, I'd like dhcp module running mode in which it would pass ALL requests to rlm_perl without duplicate checks and queueing as I perform thread-safe in-memory caching of results distinguishing cliens using DHCP Option 82 details. Or, another mode of dhcp module in which it would be able to check existance of the Option 82 in the request and use it to no treat requests from distinct clients as coming from single source. Something like that. Eugene Grosbein
Eugene Grosbein wrote:
There is more logic in my perl script. It keeps pool of persistent connections to database, restarts them if they fail and fallbacks to local indexed storage if database does not respond at all.
Which re-implements a lot of the code in the server core. Re-inventing the wheel is a lot of work. Sometimes you can make a mistake.
You missed the point. Perl script and database process request pretty fast and I have hundreds of free threads in the rlm_perl's pool.
<shrug> The default configuration can assign 10K IP addresses per second from the "mac2ip" module. So the problem isn't FreeRADIUS. It's your local changes. Also, having hundreds of threads is a problem. You shouldn't need that many.
But FreeRADIUS dhcp module thinks that all requests from the same source are request from single client. This is plain wrong in case of DHCP relay in between DHCP clients and FreeRADIUS that is located in an isolated vlan.
I don't see how that's a problem. The DHCP code doesn't use client definitions. The server core doesn't queue requests by client.
So, FreeRADIUS queues requests and does not pass them to rlm_perl instantly as it should. 6 seconds is delay between DHCP request arrival to the box via network interface and invoke of post_auth perl function.
So... what, FreeRADIUS does *nothing* with the packets for 6 seconds? That doesn't make sense. When the server receives a packet, the packet gets put onto a queue. The queue is ordered, so first-in, first-out. The queue doesn't care whether the packet is RADIUS, DHCP, VMPS, or which client the packet came from. When a thread is done with one request, it pulls the next one from the queue. Again, the thread doesn't care what kind of packet it is, or which client it came from. The ONLY reason for the server to block is if all threads are unresponsive. The ONLY reason that the threads become unresponsive is if they're doing some non-default action... which blocks the server.
Basically, I'd like dhcp module running mode in which it would pass ALL requests to rlm_perl without duplicate checks and queueing as I perform thread-safe in-memory caching of results distinguishing cliens using DHCP Option 82 details.
It's not doing duplicate checks. It DOES do queueing, because that's how the server works. The DHCP code does NOT look at Option 82. The DHCP code does NOT do any queuing of DHCP packets. Honestly, if you're going to re-implement everything in Perl, you're probably better off writing your own DHCP server in Perl.
Or, another mode of dhcp module in which it would be able to check existance of the Option 82 in the request and use it to no treat requests from distinct clients as coming from single source.
The DHCP module does NOT do that. I have no idea why you think it does. The server does NOT work how you think. I can't emphasize this enough. There is no magic queuing of packets for 6 seconds. There are no "DHCP clients". There is no special treatment of packets with Option 82 The ONLY reason FreeRADIUS is taking 6 seconds to respond is that YOU changed the configuration. Honestly, try using the "mac2ip" module. Pull the MACs and IPs from your database. and put them into the mac2ip file. Configure the mac2ip module, and disable your Perl script. You will see that the response time of FreeRADIUS drop to 40ms or so. It will be able to do about 10K DHCP packets per second. I don't know how else to explain this. Your Perl script is causing the problem. Alan DeKok.
On 04.04.2014 22:23, Alan DeKok wrote:
Re-inventing the wheel is a lot of work. Sometimes you can make a mistake.
Yes, it is possible. The problem is that delay occurs before this code starts. I will explain how can this happen lower.
But FreeRADIUS dhcp module thinks that all requests from the same source are request from single client. This is plain wrong in case of DHCP relay in between DHCP clients and FreeRADIUS that is located in an isolated vlan.
I don't see how that's a problem. The DHCP code doesn't use client definitions. The server core doesn't queue requests by client.
The DHCP code does DOES use "client definitions". There is a comment in src/lib/dhcp.c before the code I'm speaking about: /* * Create a unique vector from the MAC address and the * DHCP opcode. This is a hack for the RADIUS * infrastructure in the rest of the server. * * Note: packet->data[2] == 6, which is smaller than * sizeof(packet->vector) * * FIXME: Look for client-identifier in packet, * and use that, too? */ memset(packet->vector, 0, sizeof(packet->vector)); memcpy(packet->vector, packet->data + 28, packet->data[2]); packet->vector[packet->data[2]] = packet->code & 0xff; This is plain wrong as it's making non-unique "vector" when all requests come from the same MAC address of the DHCP relay.
So, FreeRADIUS queues requests and does not pass them to rlm_perl instantly as it should. 6 seconds is delay between DHCP request arrival to the box via network interface and invoke of post_auth perl function.
So... what, FreeRADIUS does *nothing* with the packets for 6 seconds? That doesn't make sense.
No, it does something. It drops some requests. In detail: 1. New client sends DHCP Discover via DHCP relay with new xid. 2. FreeRADIUS has plenty of requests from this DHCP relay and drops the request with a note in its log about duplicate request. That's a monent when it fails. 3. Client does not sit silent and repeats its request with the same xid several times. 4. Eventually, the request with noted xid comes in such a moment that FreeRAIDUS accepts it without a drop and passes to post_auth(). There are 6 seconds between point 1 and point 4 generally and several retransmissions from the DHCP clients with the same xid.
When the server receives a packet, the packet gets put onto a queue.
Or dropped as "duplicate".
The queue is ordered, so first-in, first-out. The queue doesn't care whether the packet is RADIUS, DHCP, VMPS, or which client the packet came from.
When a thread is done with one request, it pulls the next one from the queue. Again, the thread doesn't care what kind of packet it is, or which client it came from.
Yes.
The ONLY reason for the server to block is if all threads are unresponsive. The ONLY reason that the threads become unresponsive is if they're doing some non-default action... which blocks the server.
No-no, we are not talking about server "blocking".
Basically, I'd like dhcp module running mode in which it would pass ALL requests to rlm_perl without duplicate checks and queueing as I perform thread-safe in-memory caching of results distinguishing cliens using DHCP Option 82 details.
It's not doing duplicate checks.
FreeRADIUS core does.
Or, another mode of dhcp module in which it would be able to check existance of the Option 82 in the request and use it to no treat requests from distinct clients as coming from single source.
The DHCP module does NOT do that. I have no idea why you think it does.
I known it does not do that. I wish it would :-)
Honestly, try using the "mac2ip" module. Pull the MACs and IPs from your database. and put them into the mac2ip file. Configure the mac2ip module, and disable your Perl script.
You will see that the response time of FreeRADIUS drop to 40ms or so. It will be able to do about 10K DHCP packets per second.
Our business logic is not so straight-forward and considers all of source data in the DHCP option 82 and lots of additional data in the database to decide if this client should get ACK or NAK and which pool should be used for this particular request and should client get IP/mask only or gateway/DNS too etc. etc. It makes many complex decisions and makes them very fast for hundreds of requests in parallel. Eugene Grosbein
Eugene Grosbein wrote:
The DHCP code does DOES use "client definitions".
It has one, but it doesn't *use* it for anything.
There is a comment in src/lib/dhcp.c before the code I'm speaking about:
/* * Create a unique vector from the MAC address and the * DHCP opcode. This is a hack for the RADIUS * infrastructure in the rest of the server. * * Note: packet->data[2] == 6, which is smaller than * sizeof(packet->vector) * * FIXME: Look for client-identifier in packet, * and use that, too? */ memset(packet->vector, 0, sizeof(packet->vector)); memcpy(packet->vector, packet->data + 28, packet->data[2]); packet->vector[packet->data[2]] = packet->code & 0xff;
This is plain wrong as it's making non-unique "vector" when all requests come from the same MAC address of the DHCP relay.
That field ( CHADDR ) is the MAC address of the client. Not the relay. If the relay is putting it's own MAC into the CHADDR field, then the relay is broken. Throw it in the garbage, and get one that works
1. New client sends DHCP Discover via DHCP relay with new xid. 2. FreeRADIUS has plenty of requests from this DHCP relay and drops the request with a note in its log about duplicate request. That's a monent when it fails.
You're not posting the debug log, as suggested in the FAQ, "man" page, etc. That *would* have helped. The duplicate detection code uses the XID. So if the server sees a duplicate it's because the XID is the same. Some of the issue here is that I'm working with v3. I don't work with v2 any more, except to fix bugs.
3. Client does not sit silent and repeats its request with the same xid several times. 4. Eventually, the request with noted xid comes in such a moment that FreeRAIDUS accepts it without a drop and passes to post_auth().
I have no idea what that means.
There are 6 seconds between point 1 and point 4 generally and several retransmissions from the DHCP clients with the same xid.
Which disagrees with your earlier post which said: Request 14280134 has been waiting in the processing queue for 6 seconds. Check that all databases are running properly! Discarding duplicate request from client dhcp port 67 - ID: 1381353109 due to unfinished request 14280311 The ONLY reason that message occurs is because your database is slow. If the server DROPS the first packet, then the packet CANNOT be sitting in the processing queue for 6 seconds. Yet you say your database is fast. Your explanations are in gross disagreement. One or more of your assumptions is completely wrong.
No-no, we are not talking about server "blocking".
Then why did the server produce the message I quoted above? You're changing your story. It's annoying. The server IS blocking. The server IS NOT dropping duplicates. You've posted 2 lines of debug output showing that the server is blocking. You've posted ZERO debug output showing that the server is dropping duplicates. Your explanation about the relay putting it's own MAC address into the CHADDR fields makes ZERO sense. Alan DeKok.
On 05.04.2014 01:28, Alan DeKok wrote:
You're changing your story. It's annoying.
Not meant to. May be, I have not describe the case right at first.
The server IS blocking. The server IS NOT dropping duplicates.
Then why I have lots of lines telling be of dropping duplicate requests like I've shown?
You've posted 2 lines of debug output showing that the server is blocking.
You've posted ZERO debug output showing that the server is dropping duplicates.
"Discarding duplicate request from client dhcp port 67 - ID: 1381353109 due to unfinished request 14280311" If this line does not show that the server is dropping duplicates, why it uses words "discarding" and "duplicate request"?
Your explanation about the relay putting it's own MAC address into the CHADDR fields makes ZERO sense.
Ok, may be my analysis is wrong at this point. I'll return to this matter on Monday, repeating my tests and supplying more logs. By the way, xid by itself should not be used as "unique" client id without additional details like client MAC, option 82 field (if supplied) etc. I'm ready to move to 3.0.2, too.
Eugene Grosbein wrote:
The server IS blocking. The server IS NOT dropping duplicates.
Then why I have lots of lines telling be of dropping duplicate requests like I've shown?
Because the server is blocking. OK. After looking at it a bit more, there are duplicate checks in the v2 code. Here's what's happening: 1) your Perl code is breaking the server. 2) Probably because the database is slow 3) because the DB is slow, all of the threads are blocked 4) because threads are blocked, packets sit in the queue for many seconds 5) because packets sit in the queue for too long, the client doesn't see a response 6) the client retransmits 7) the server sees that it's a duplicate of a packet waiting in the queue, and complains about duplicate packet. The messages in v2.2.4 are a bit better. They describe more clearly what's going on. If you're having issues with 2.2.4, PLEASE submit bug reports. They won't get fixed otherwise. Try using the "mac2ip" module as I suggested. DON'T use your Perl script. You'll see the server doing 10K DHCP packets/s. The problem IS your script, or the database. There is just no other way that FreeRADIUS sits on packets for many seconds.
By the way, xid by itself should not be used as "unique" client id without additional details like client MAC, option 82 field (if supplied) etc.
That's what the code does. It uses XID && MAC to determine unique packets.
I'm ready to move to 3.0.2, too.
Use th v3.0.x branch from git, which has some fixes to the Perl code. Alan DeKok/
Let me go further... My guess is that you're using MySQL to store IPs. You're using a "SELECT FOR UPDATE ... LIMIT 1" query to grab the IP. That's the problem. MySQL will lock all of the rows SELECTed, even if you say LIMIT 1. The result is massive lock contention, and MySQL will take many seconds to respond. Use a real database, like PostgreSQL. The problem will go away. Alan DeKok.
On 04.04.2014 22:44, Alan DeKok wrote:
Let me go further...
My guess is that you're using MySQL to store IPs. You're using a "SELECT FOR UPDATE ... LIMIT 1" query to grab the IP.
That's the problem. MySQL will lock all of the rows SELECTed, even if you say LIMIT 1. The result is massive lock contention, and MySQL will take many seconds to respond.
Use a real database, like PostgreSQL. The problem will go away.
We do not use MySQL or SELECT FOR UPDATE. We use MS SQL and stored procedures there and when hundreds of simultaneous requests come from _distinct_ MAC addresses without using DHCP relays, then FreeRADIUS processes them instantly. But when DHCP relay stays in front of FreeRADIUS, request drops and bad queueing happen due to wrong assumptions in its code that looks for duplicates in the queue of requests. These assumptions are just fine for RADIUS protocol and they are fine for DHCP without relays but they are plain wrong when all DHCP requests come from single MAC address of DHCP relay.
Eugene Grosbein wrote:
We do not use MySQL or SELECT FOR UPDATE. We use MS SQL and stored procedures there and when hundreds of simultaneous requests come from _distinct_ MAC addresses without using DHCP relays, then FreeRADIUS processes them instantly.
That's good.
But when DHCP relay stays in front of FreeRADIUS, request drops and bad queueing happen due to wrong assumptions in its code that looks for duplicates in the queue of requests.
You've said that already. How about providing some *evidence*, like debug output?
These assumptions are just fine for RADIUS protocol and they are fine for DHCP without relays but they are plain wrong when all DHCP requests come from single MAC address of DHCP relay.
You've said that already. You've also said that there are bugs with 2.2.4, but you refuse to say what those are. So... you're asking for help, but you're refusing to provide any useful information. That is rude and anti-social. I can't help you until you say something useful. Alan DeKok.
On 05.04.2014 01:18, Alan DeKok wrote:
But when DHCP relay stays in front of FreeRADIUS, request drops and bad queueing happen due to wrong assumptions in its code that looks for duplicates in the queue of requests.
You've said that already. How about providing some *evidence*, like debug output?
Hmm. I've shown some log lines in the very first message of this thread. I could post hundreds of lines on dropping "duplicate" requests that are not duplicates but why pollute the list?
These assumptions are just fine for RADIUS protocol and they are fine for DHCP without relays but they are plain wrong when all DHCP requests come from single MAC address of DHCP relay.
You've said that already.
I've shown the code in another message.
You've also said that there are bugs with 2.2.4, but you refuse to say what those are.
I just don't want to discuss 2.2.4 for now mixing completely different problems. May be in another thread. And I'm not asking for help with 2.2.4-specific problems.
So... you're asking for help, but you're refusing to provide any useful information. That is rude and anti-social.
I can't help you until you say something useful.
Sorry, not meant to be rude. I will supply any details needed to solve our DHCP problem. But please leave 2.2.4-specific coredumps aside for now, that's much more complex problem. Eugene Grosbein
participants (2)
-
Alan DeKok -
Eugene Grosbein