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.