sql ip pool module assign IP 0.0.0.0 to users
Hello! We have the following problem: When many of out NAS (which are Wireless PPPOE POPs) that are Mikrotik based are rebooted (for maintanance, updates or maybe outages) and then simultaneously connect to our Freeradius instance to authenticate again we are experiencing the following rows in the logs: Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client OpenFiber port 50242 - ID: 114 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 33577 - ID: 70 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 37882 - ID: 21 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 50131 - ID: 95 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 40360 - ID: 211 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : WARNING: (8349606) WARNING: Module rlm_sql became unblocked Thu Nov 18 06:25:06 2021 : WARNING: (8349607) WARNING: Module rlm_sql became unblocked Thu Nov 18 06:25:06 2021 : WARNING: (8349608) WARNING: Module rlm_sql became unblocked Thu Nov 18 06:25:06 2021 : WARNING: (8349609) WARNING: Module rlm_sql became unblocked Thu Nov 18 06:25:06 2021 : WARNING: (8349610) WARNING: Module rlm_sql became unblocked Thu Nov 18 06:25:06 2021 : WARNING: (8349605) WARNING: Module rlm_sql became unblocked Thu Nov 18 06:25:06 2021 : WARNING: (8349611) WARNING: Module rlm_sql became unblocked ... etc ... And the customers PPPOE sessions are getting an assigned IP = 0.0.0.0 instead of one of the IP pool. If we disconnect those sessions proprerly and let them authenticate again the problem is fixed. We have some doubts that this could happen because the POPs are not sending the correct AccTerminate packets when rebooting, so it is not freeing up the pools. And also those sessions are not recognized as active because we are using NAS PORT ID as pool key and it changes, maybe would be better tu user the Mac Address as key? A final note: our IP pool is nearly exhausted, we have about 30 free IPs. Could this also give problems? Thanks. -- Mirko Alberio - Assistenza tecnica e-mail: mirko.alberio@telemar.it Telemar SpA Internet Quality Provider Via Enrico Fermi, 235 - 36100 Vicenza - Italia Tel 0444 291302 - Fax 0444 566310 - www.telemar.it Assistenza tecnica 0444 1420000 Reg. Imp. Di Vicenza /C.F./P.I. 02508710247 Cap. Soc. € 120.000,00 I.V. R.E.A. VI-236292
On Nov 19, 2021, at 5:03 AM, Mirko Alberio via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
We have the following problem:
When many of out NAS (which are Wireless PPPOE POPs) that are Mikrotik based are rebooted (for maintanance, updates or maybe outages) and then simultaneously connect to our Freeradius instance to authenticate again we are experiencing the following rows in the logs:
Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client OpenFiber port 50242 - ID: 114 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 33577 - ID: 70 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 37882 - ID: 21 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 50131 - ID: 95 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 40360 - ID: 211 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : WARNING: (8349606) WARNING: Module rlm_sql became unblocked Thu Nov 18 06:25:06 2021 : WARNING: (8349607) WARNING: Module rlm_sql became unblocked
This means that your SQL server can't keep up with the load. Add more CPU / disk / memory / replicas in order to fix it. No amount of poking FreeRADIUS will make your SQL server run faster.
And the customers PPPOE sessions are getting an assigned IP = 0.0.0.0 instead of one of the IP pool.
The SQL IP pool module does not assign IP of 0.0.0.0 when the SQL server is down. Either you updated the FreeRADIUS configuration to do that, or FreeRADIUS is *not* returning an IP, and then the NAS is assigning that address itself.
We have some doubts that this could happen because the POPs are not sending the correct AccTerminate packets when rebooting, so it is not freeing up the pools. And also those sessions are not recognized as active because we are using NAS PORT ID as pool key and it changes, maybe would be better tu user the Mac Address as key?
It's best to make the SQL databases run faster. If the POPs aren't sending Accounting-On when rebooting, then fix them so that they do that. This is a separate issue, but still a problem.
A final note: our IP pool is nearly exhausted, we have about 30 free IPs. Could this also give problems?
That shouldn't be a problem, unless all of the IPs are used. The server should then *reject* the users requests, as IPs cannot be allocated. Alan DeKok.
Hi Alan, thanks as always for your help, actually I was monitoring MYSQL server load and performance but it did not seem the bottleneck. The strange behaviour is that Radius successfully authenticates the users (so can read the radius users table) but assign those 0.0.0.0 (and in some limit cases even actually public IPs, but the same to multiple users. See below. Also, I can say that POPs are sending Accounting on when rebooting. The problem seems is they are not sending Accounting off and probably the IP assignation lingers there, or should (like you explained before) those sessione be marked as "dead" and so IP can be re-used? Mirko Alberio - Assistenza tecnica e-mail:mirko.alberio@telemar.it Telemar SpA Internet Quality Provider Via Enrico Fermi, 235 - 36100 Vicenza - Italia Tel 0444 291302 - Fax 0444 566310 -www.telemar.it Assistenza tecnica 0444 1420000 Reg. Imp. Di Vicenza /C.F./P.I. 02508710247 Cap. Soc. € 120.000,00 I.V. R.E.A. VI-236292 Il 19/11/2021 13:47, Alan DeKok ha scritto:
On Nov 19, 2021, at 5:03 AM, Mirko Alberio via Freeradius-Users<freeradius-users@lists.freeradius.org> wrote:
We have the following problem:
When many of out NAS (which are Wireless PPPOE POPs) that are Mikrotik based are rebooted (for maintanance, updates or maybe outages) and then simultaneously connect to our Freeradius instance to authenticate again we are experiencing the following rows in the logs:
Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client OpenFiber port 50242 - ID: 114 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 33577 - ID: 70 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 37882 - ID: 21 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 50131 - ID: 95 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 40360 - ID: 211 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : WARNING: (8349606) WARNING: Module rlm_sql became unblocked Thu Nov 18 06:25:06 2021 : WARNING: (8349607) WARNING: Module rlm_sql became unblocked This means that your SQL server can't keep up with the load. Add more CPU / disk / memory / replicas in order to fix it.
No amount of poking FreeRADIUS will make your SQL server run faster.
And the customers PPPOE sessions are getting an assigned IP = 0.0.0.0 instead of one of the IP pool. The SQL IP pool module does not assign IP of 0.0.0.0 when the SQL server is down. Either you updated the FreeRADIUS configuration to do that, or FreeRADIUS is *not* returning an IP, and then the NAS is assigning that address itself.
We have some doubts that this could happen because the POPs are not sending the correct AccTerminate packets when rebooting, so it is not freeing up the pools. And also those sessions are not recognized as active because we are using NAS PORT ID as pool key and it changes, maybe would be better tu user the Mac Address as key? It's best to make the SQL databases run faster.
If the POPs aren't sending Accounting-On when rebooting, then fix them so that they do that. This is a separate issue, but still a problem.
A final note: our IP pool is nearly exhausted, we have about 30 free IPs. Could this also give problems? That shouldn't be a problem, unless all of the IPs are used. The server should then *reject* the users requests, as IPs cannot be allocated.
Alan DeKok.
On Nov 19, 2021, at 9:47 AM, Mirko Alberio via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
actually I was monitoring MYSQL server load and performance but it did not seem the bottleneck.
When the logs say: Thu Nov 18 06:25:06 2021 : WARNING: (8349606) WARNING: Module rlm_sql became unblocked That means that the SQL module sent a query to MySQL, and MySQL didn't respond for 5 seconds. That's a problem. Plus, you said this happens when power goes off / on again. That is a huge spike of traffic, which can easily overload databases.
The strange behaviour is that Radius successfully authenticates the users (so can read the radius users table)
Yes, which is just reading a table. That may work, but IP allocation is read/write. That can result in congestion, as many queries try to read/write locked rows. One fix is to be sure that you're using the latest server, and the latest queries, and the latest schema. We've put work into optimizing this so it works better in high-load scenarios: https://networkradius.com/articles/2021/05/20/DHCP-enhancements-in-FreeRADIU... That page mentions DHCP, but we've done similar things for RADIUS. But even as you'll see there, it tops out at ~2K IPs allocated per second.
but assign those 0.0.0.0 (and in some limit cases even actually public IPs, but the same to multiple users. See below.
FreeRADIUS does *not* assign 0.0.0.0 if something goes wrong. If the sqlippool module is unable to allocate an IP address, it returns FAIL or NOOP. It will *never* return a 0.0.0.0 IP address to the user.
Also, I can say that POPs are sending Accounting on when rebooting.
That's fine.
The problem seems is they are not sending Accounting off
That isn't an issue.
and probably the IP assignation lingers there, or should (like you explained before) those sessione be marked as "dead" and so IP can be re-used?
The sessions will be marked dead when FreeRADIUS receives Accounting On. Alan DeKok.
Hi Alan! thanks to your suggestion I delved in the problem and found a MySql server issue. 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) 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:30 2021 : Auth: (869342) Login OK: [*****/******] (from client port 15742033 cli 3C:A6:2F:99:ED:5A) Wed Nov 24 04:00:32 2021 : Auth: (869383) Login OK: [*****/******] (from client port 15751442 cli CC:32:E5:5B:75:2F) Wed Nov 24 04:00:38 2021 : Info: rlm_sql (sql): Closing connection (3168), from 18 unused connections 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. Wed Nov 24 04:00:50 2021 : Info: rlm_sql (sql): Need 3 more connections to reach 10 spares Wed Nov 24 04:00:50 2021 : Info: rlm_sql (sql): Opening additional connection (3196), 1 of 36 pending slots used Wed Nov 24 04:00:50 2021 : WARNING: (869737) WARNING: Module rlm_sql became unblocked Wed Nov 24 04:01:04 2021 : Auth: (870092) Login OK: [*****/******] (from client port 15739845 cli 00:01:21:02:32:53) Wed Nov 24 04:01:18 2021 : Auth: (870385) Login OK: [*****/******] (from client port 15738081 cli 2C:3A:FD:19:5E:0C) Wed Nov 24 04:01:20 2021 : Info: rlm_sql (sql): Closing connection (3173), from 19 unused connections Wed Nov 24 04:01:20 2021 : Auth: (870412) Login OK: [*****/******] (from client CCR Servizi port 15741062 cli DC:15:C8:03:DA:D6) Wed Nov 24 04:01:33 2021 : Auth: (870669) Login OK: [*****/******] (from client port 15743572 cli 18:31:BF:5A:60:F8) Wed Nov 24 04:01:35 2021 : Info: rlm_sql (sql): Closing connection (3196), from 18 unused connections Wed Nov 24 04:01:41 2021 : Auth: (870847) Login OK: [*****/******] (from client port 15745851 cli CC:CE:1E:73:E3:0D) Wed Nov 24 04:01:42 2021 : Info: rlm_sql (sql): Closing connection (3194), from 17 unused connections Wed Nov 24 04:01:45 2021 : Info: rlm_sql (sql): Closing connection (3191), from 16 unused connections Wed Nov 24 04:01:46 2021 : Info: rlm_sql (sql): Closing connection (3174), from 15 unused connections Wed Nov 24 04:01:47 2021 : Info: rlm_sql (sql): Closing connection (3190), from 14 unused connections Wed Nov 24 04:01:48 2021 : Info: rlm_sql (sql): Closing connection (3157), from 13 unused connections Wed Nov 24 04:01:49 2021 : Info: rlm_sql (sql): Closing connection (3187), from 12 unused connections Wed Nov 24 04:01:50 2021 : Info: rlm_sql (sql): Closing connection (3179), from 11 unused connections Wed Nov 24 04:01:51 2021 : Info: rlm_sql (sql): Closing connection (3189), from 10 unused connections Wed Nov 24 04:01:52 2021 : Info: rlm_sql (sql): Closing connection (3181), from 9 unused connections Wed Nov 24 04:01:53 2021 : Info: rlm_sql (sql): Closing connection (3188), from 8 unused connections Wed Nov 24 04:01:54 2021 : Info: rlm_sql (sql): Closing connection (3161), from 7 unused connections Wed Nov 24 04:01:54 2021 : Auth: (871083) Login OK: [*****/******] (from client port 15751443 cli CC:32:E5:5B:75:2F) Wed Nov 24 04:01:55 2021 : Info: rlm_sql (sql): Closing connection (3195), from 6 unused connections Wed Nov 24 04:01:56 2021 : Info: rlm_sql (sql): Closing connection (3156), from 5 unused connections Wed Nov 24 04:01:57 2021 : Info: rlm_sql (sql): Closing connection (3192), from 4 unused connections Wed Nov 24 04:01:58 2021 : Info: rlm_sql (sql): Closing connection (3193), from 3 unused connections Wed Nov 24 04:01:59 2021 : Info: rlm_sql (sql): Closing connection (3176), from 2 unused connections Wed Nov 24 04:01:59 2021 : Auth: (871202) Login OK: [*****/******] (from client port 15751444 cli 00:90:7F:E0:B9:EC) Wed Nov 24 04:02:00 2021 : Info: rlm_sql (sql): Closing connection (3184), from 1 unused connections Wed Nov 24 04:02:03 2021 : Info: rlm_sql (sql): Need 3 more connections to reach 10 spares Wed Nov 24 04:02:03 2021 : Info: rlm_sql (sql): Opening additional connection (3197), 1 of 54 pending slots used Wed Nov 24 04:02:07 2021 : Info: rlm_sql (sql): Need 1 more connections to reach 10 spares Wed Nov 24 04:02:07 2021 : Info: rlm_sql (sql): Opening additional connection (3198), 1 of 53 pending slots used Wed Nov 24 04:02:22 2021 : Auth: (871713) Login OK: [*****/******] (from client port 15764119 cli E8:DF:70:C0:A4:6C) Wed Nov 24 04:02:31 2021 : Auth: (871845) Login OK: [*****/******] (from client port 15746218 cli 00:24:01:38:38:AF) Wed Nov 24 04:02:34 2021 : Auth: (871893) Login OK: [*****/******] (from client port 15734140 cli CC:CE:1E:CC:F8:5F) Wed Nov 24 04:02:37 2021 : Info: rlm_sql (sql): Closing connection (3172), from 2 unused connections Wed Nov 24 04:02:37 2021 : Auth: (871958) Login OK: [*****/******] (from client port 15745852 cli CC:CE:1E:73:E3:0D) Wed Nov 24 04:02:38 2021 : Info: rlm_sql (sql): Need 1 more connections to reach 10 spares Wed Nov 24 04:02:38 2021 : Info: rlm_sql (sql): Opening additional connection (3199), 1 of 53 pending slots used Wed Nov 24 04:02:54 2021 : Info: rlm_sql (sql): Need 1 more connections to reach 10 spares Wed Nov 24 04:02:54 2021 : Info: rlm_sql (sql): Opening additional connection (3200), 1 of 52 pending slots used Wed Nov 24 04:03:03 2021 : Auth: (872587) Login OK: [*****/******] (from client port 15738372 cli CC:CE:1E:75:02:58) Wed Nov 24 04:03:03 2021 : Auth: (872592) Login OK: [*****/******] (from client port 15751445 cli E8:65:D4:B8:26:10) Wed Nov 24 04:03:20 2021 : Info: rlm_sql (sql): Need 1 more connections to reach 10 spares Wed Nov 24 04:03:20 2021 : Info: rlm_sql (sql): Opening additional connection (3201), 1 of 51 pending slots used Wed Nov 24 04:03:22 2021 : Auth: (873025) Login OK: [*****/******] (from client port 15757447 cli 9C:D3:6D:0A:85:48) Wed Nov 24 04:03:26 2021 : Auth: (873095) Login OK: [*****/******] (from client port 15734141 cli CC:CE:1E:CC:F8:5F) Wed Nov 24 04:03:33 2021 : Auth: (873213) Login OK: [*****/******] (from client port 15764120 cli E8:DF:70:C0:A4:6C) Wed Nov 24 04:03:43 2021 : Auth: (873379) Login OK: [*****/******] (from client port 15735354 cli 70:4C:A5:87:B9:41) Wed Nov 24 04:03:50 2021 : Info: rlm_sql (sql): Closing connection (3197), from 3 unused connections Wed Nov 24 04:03:53 2021 : Auth: (873547) Login OK: [*****/******] (from client port 15738373 cli CC:CE:1E:75:02:58) Wed Nov 24 04:03:59 2021 : Auth: (873644) Login OK: [*****/******] (from client port 15735355 cli 70:4C:A5:87:B9:41) Wed Nov 24 04:04:02 2021 : Auth: (873684) Login OK: [*****/******] (from client port 15757448 cli 9C:D3:6D:0A:85:48) Wed Nov 24 04:04:05 2021 : Info: rlm_sql (sql): Closing connection (3199), from 3 unused connections Wed Nov 24 04:04:10 2021 : Auth: (873839) Login OK: [*****/******] (from client port 15764121 cli 98:9B:CB:F9:12:CC) Wed Nov 24 04:04:11 2021 : Auth: (873847) Login OK: [*****/******] (from client port 15755204 cli 5C:49:79:CF:31:A2) Wed Nov 24 04:04:12 2021 : Info: rlm_sql (sql): Closing connection (3186), from 2 unused connections Wed Nov 24 04:04:13 2021 : Auth: (873872) Login OK: [*****/******] (from client port 15748467 cli D8:32:14:75:EE:08) Wed Nov 24 04:04:15 2021 : Info: rlm_sql (sql): Closing connection (3185), from 1 unused connections Wed Nov 24 04:04:28 2021 : Info: rlm_sql (sql): Need 1 more connections to reach 10 spares Wed Nov 24 04:04:28 2021 : Info: rlm_sql (sql): Opening additional connection (3202), 1 of 54 pending slots used Wed Nov 24 04:04:34 2021 : Info: rlm_sql (sql): Need 1 more connections to reach 10 spares Wed Nov 24 04:04:34 2021 : Info: rlm_sql (sql): Opening additional connection (3203), 1 of 53 pending slots used Wed Nov 24 04:04:49 2021 : Auth: (874499) Login OK: [*****/******] (from client port 15736560 cli 00:A0:C5:9E:92:15) Wed Nov 24 04:04:49 2021 : Auth: (874502) Login OK: [*****/******] (from client port 15751446 cli 2C:3A:FD:25:2D:D9) Wed Nov 24 04:04:54 2021 : Auth: (874590) Login OK: [*****/******] (from client port 15757449 cli 9C:D3:6D:0A:85:48) Wed Nov 24 04:05:01 2021 : Auth: (874708) Login OK: [*****/******] (from client port 15755205 cli F0:B0:14:C5:4C:A7) Wed Nov 24 04:05:04 2021 : Info: rlm_sql (sql): Closing connection (3175), from 2 unused connections Wed Nov 24 04:05:09 2021 : Info: rlm_sql (sql): Need 1 more connections to reach 10 spares Wed Nov 24 04:05:09 2021 : Info: rlm_sql (sql): Opening additional connection (3204), 1 of 53 pending slots used Wed Nov 24 04:05:11 2021 : Auth: (874873) Login OK: [*****/******] (from client port 15744122 cli DC:15:C8:03:CF:5A) Wed Nov 24 04:05:19 2021 : Auth: (875045) Login OK: [*****/******] (from client port 15757450 cli 9C:D3:6D:0A:85:48) Wed Nov 24 04:05:28 2021 : Auth: (875218) Login OK: [*****/******] (from client port 15746637 cli 00:1D:AA:56:66:7A) Wed Nov 24 04:05:30 2021 : Auth: (875260) Login OK: [*****/******] (from client port 15728690 cli 00:1D:AA:8E:CB:6D) Wed Nov 24 04:05:30 2021 : Auth: (875267) Login OK: [*****/******] (from client port 15728691 cli CC:2D:E0:93:37:43) Wed Nov 24 04:05:30 2021 : Auth: (875268) Login OK: [*****/******] (from client port 15728689 cli 90:9A:4A:FC:5D:DE) Wed Nov 24 04:05:31 2021 : Auth: (875275) Login OK: [*****/******] (from client port 15728692 cli 60:32:B1:40:B3:77) Wed Nov 24 04:05:31 2021 : Auth: (875279) Login OK: [*****/******] (from client port 15728693 cli CC:2D:E0:93:37:15) Wed Nov 24 04:05:31 2021 : Auth: (875284) Login OK: [*****/******] (from client port 15728694 cli 60:32:B1:40:65:32) Wed Nov 24 04:05:31 2021 : Auth: (875293) Login OK: [*****/******] (from client port 15728695 cli 6C:3B:6B:07:4D:EA) Wed Nov 24 04:05:31 2021 : Auth: (875294) Login OK: [*****/******] (from client port 15728696 cli C4:6E:1F:0D:1D:41) Wed Nov 24 04:05:32 2021 : Auth: (875308) Login OK: [*****/******] (from client port 15728697 cli E4:8D:8C:60:26:4B) Wed Nov 24 04:05:33 2021 : ERROR: (875323) sql: ERROR: rlm_sql_mysql: ERROR 1582 (Incorrect parameter count in the call to native function 'FROM_UNIXTIME'): 42000 Wed Nov 24 04:05:34 2021 : Auth: (875345) Login OK: [*****/******] (from client port 15728698 cli 2C:C8:1B:6C:C5:1C) Wed Nov 24 04:05:35 2021 : Auth: (875346) Login OK: [*****/******] (from client port 15728699 cli CC:2D:E0:4E:49:A0) Wed Nov 24 04:05:37 2021 : ERROR: (875385) sql: ERROR: rlm_sql_mysql: ERROR 1582 (Incorrect parameter count in the call to native function 'FROM_UNIXTIME'): 42000 Wed Nov 24 04:05:37 2021 : Auth: (875395) Login OK: [*****/******] (from client port 15728700 cli 4A:00:3E:7A:64:CA) Wed Nov 24 04:05:38 2021 : Auth: (875404) Login OK: [*****/******] (from client port 15728701 cli CC:2D:E0:08:C5:17) Wed Nov 24 04:05:38 2021 : Auth: (875407) Login OK: [*****/******] (from client port 15728702 cli B8:69:F4:B6:CE:38) Wed Nov 24 04:05:38 2021 : Auth: (875418) Login OK: [*****/******] (from client port 15728703 cli 00:1D:AA:8E:CB:6D) Wed Nov 24 04:05:39 2021 : Info: rlm_sql (sql): Closing connection (3182), from 2 unused connections 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 Wed Nov 24 02:50:48 2021 : Info: rlm_sql (sql): Need 1 more connections to reach 10 spares Wed Nov 24 02:50:48 2021 : Info: rlm_sql (sql): Opening additional connection (2904), 9 of 36 pending slots used Wed Nov 24 02:50:49 2021 : Error: (783847) Ignoring duplicate packet from client OpenFiber port 35910 - ID: 150 due to unfinished request in component accounting module sql Wed Nov 24 02:50:49 2021 : Error: (783848) Ignoring duplicate packet from client port 56111 - ID: 176 due to unfinished request in component accounting module sql Wed Nov 24 02:50:49 2021 : Error: Received conflicting packet from client port 56111 - ID: 176 due to unfinished request. Giving up on old request. Wed Nov 24 02:50:50 2021 : WARNING: (783848) WARNING: Module rlm_sqlippool became unblocked Wed Nov 24 02:50:50 2021 : Error: (783873) Ignoring duplicate packet from client CCR Servizi port 58376 - ID: 238 due to unfinished request in component accounting module sql Wed Nov 24 02:50:51 2021 : Error: Received conflicting packet from client CCR Servizi port 58376 - ID: 238 due to unfinished request. Giving up on old request. Wed Nov 24 02:50:51 2021 : WARNING: (783873) WARNING: Module rlm_sql became unblocked Wed Nov 24 02:50:51 2021 : Error: (783882) Ignoring duplicate packet from client port 39326 - ID: 246 due to unfinished request in component accounting module sqlippool Wed Nov 24 02:51:14 2021 : Auth: (784420) Login OK: [rizzi_paolo/kfnyzx2510] (from client port 15730127 cli 2C:3A:FD:25:2E:65) So I am confused on the origin of this error. Could be NAS related? 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? Thanks! Mirko Alberio - Assistenza tecnica e-mail: mirko.alberio@telemar.it Telemar SpA Internet Quality Provider Via Enrico Fermi, 235 - 36100 Vicenza - Italia Tel 0444 291302 - Fax 0444 566310 - www.telemar.it Assistenza tecnica 0444 1420000 Reg. Imp. Di Vicenza /C.F./P.I. 02508710247 Cap. Soc. € 120.000,00 I.V. R.E.A. VI-236292 Il 19/11/2021 13:47, Alan DeKok ha scritto:
On Nov 19, 2021, at 5:03 AM, Mirko Alberio via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
We have the following problem:
When many of out NAS (which are Wireless PPPOE POPs) that are Mikrotik based are rebooted (for maintanance, updates or maybe outages) and then simultaneously connect to our Freeradius instance to authenticate again we are experiencing the following rows in the logs:
Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client OpenFiber port 50242 - ID: 114 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 33577 - ID: 70 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 37882 - ID: 21 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 50131 - ID: 95 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : Error: Received conflicting packet from client port 40360 - ID: 211 due to unfinished request. Giving up on old request. Thu Nov 18 06:25:06 2021 : WARNING: (8349606) WARNING: Module rlm_sql became unblocked Thu Nov 18 06:25:06 2021 : WARNING: (8349607) WARNING: Module rlm_sql became unblocked This means that your SQL server can't keep up with the load. Add more CPU / disk / memory / replicas in order to fix it.
No amount of poking FreeRADIUS will make your SQL server run faster.
And the customers PPPOE sessions are getting an assigned IP = 0.0.0.0 instead of one of the IP pool. The SQL IP pool module does not assign IP of 0.0.0.0 when the SQL server is down. Either you updated the FreeRADIUS configuration to do that, or FreeRADIUS is *not* returning an IP, and then the NAS is assigning that address itself.
We have some doubts that this could happen because the POPs are not sending the correct AccTerminate packets when rebooting, so it is not freeing up the pools. And also those sessions are not recognized as active because we are using NAS PORT ID as pool key and it changes, maybe would be better tu user the Mac Address as key? It's best to make the SQL databases run faster.
If the POPs aren't sending Accounting-On when rebooting, then fix them so that they do that. This is a separate issue, but still a problem.
A final note: our IP pool is nearly exhausted, we have about 30 free IPs. Could this also give problems? That shouldn't be a problem, unless all of the IPs are used. The server should then *reject* the users requests, as IPs cannot be allocated.
Alan DeKok.
On Nov 24, 2021, at 6:32 AM, Mirko Alberio <mirko.alberio@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.
participants (2)
-
Alan DeKok -
Mirko Alberio