sql ip pool module assign IP 0.0.0.0 to users

[Alan DeKok]

On Nov 24, 2021, at 6:32 AM, Mirko Alberio <mirko.alberio at telemar.it> wrote:
> thanks to your suggestion I delved in the problem and found a MySql server issue.

  That's good.

> Using a mysql stress tool (mysqlslap) and simulating query like this for 1000 concurrent client I managed improved the response time drastically, this command:
> mysqlslap --concurrency=1000 --create-schema=radius --query="use radius;UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE pool_key = 'xxxxx'"
> 
> Now this report that each query take less than 0.2 seconds to execute (before was 20 seconds)

  That's very good.

> So now we should have better situation and in fact tonight we did a test, making about 400 users authenticate at the same time by rebooting their NAS at 4 am.
> 
> We do not get the same exact behaviour but still about 15 of those users got "0.0.0.0" IP Address assignment an we get those log lines:
> 
> 
> Wed Nov 24 04:00:12 2021 : Error: (868963) Ignoring duplicate packet from client  port 53989 - ID: 179 due to unfinished request in component accounting module sql
> ...
> Wed Nov 24 04:00:46 2021 : Error: (869673) Ignoring duplicate packet from client  port 35074 - ID: 182 due to unfinished request in component accounting module sql
> Wed Nov 24 04:00:47 2021 : Error: (869688) Ignoring duplicate packet from client OpenFiber port 57364 - ID: 152 due to unfinished request in component accounting module sql
> Wed Nov 24 04:00:48 2021 : Error: (869719) Ignoring duplicate packet from client OpenFiber port 42418 - ID: 155 due to unfinished request in component accounting module sql
> Wed Nov 24 04:00:49 2021 : Error: (869737) Ignoring duplicate packet from client  port 47589 - ID: 184 due to unfinished request in component accounting module sql
> Wed Nov 24 04:00:50 2021 : Error: Received conflicting packet from client  port 47589 - ID: 184 due to unfinished request.  Giving up on old request.

  That's the same issue...

> Wed Nov 24 04:01:35 2021 : Info: rlm_sql (sql): Closing connection (3196), from 18 unused connections

  i.e. FreeRADIUS opened a lot of connections because it needed them, because the SQL server wasn't responding.  Once the load dropped, those connections became idle.

  The solution here isn't to increase the maximum number of connections for the SQL pool.  The solution is to fix the SQL database so that it doesn't block.

> A strange thing is now we get "rlm_sqlippool became unblocked" but also in other time of the day where no NAS reboot or no MySql event we get: rlm_sql became unblocked / rlm_sqlippool became unblocked

  Something is wrong with your SQL database.  If it's blocking for low loads, that's a serious problem.

> So I am confused on the origin of this error. Could be NAS related?

  No.

  I really don't know how else to say this, or why I need to repeat it:  Your SQL database is slow.  Fix it.

> And if may I ask, I see from the documentation that for a small ISP like ours (10.000 radius users) MySql database engine should be enough. Can you confirm me this?

  Any SQL database can be made slow through misuse.  Lack of indexes, or too many unused indexes, too many rows, too many other services trying to hit the SQL database at the same time.

  You need to investigate all of these.  We don't have access to your systems, so we can't do that.

  A simple approach might be to just (a) make an SQL database used *only* by FreeRADIUS.  Use the schemas, queries, and binaries from 3.0.25.  Before you install the schema, delete any index you're not going to use.

  This is a MySQL DB problem.  No amount of poking the NAS or FreeRADIUS will fix the issue.  You have to fix the database.  I really don't know how else to convince you of this.

  Alan DeKok.