Alan, again, thank you very much for the responses. Trying to be clearer, the cpu processes that grow are on the slapd service, but only when the errors start "Error: (382) Ignoring duplicate packet from client" prior to this, with only 2 NAS sending request does not happen, in the more I add one more Juniper NAS, these errors start. About of configuration on FR, I changed minimus of default PID USER PR NI VIRT RES SHR S *%CPU* %MEM TIME+ COMMAND 1660 ldap 20 0 1618712 156540 2956 S *674.5* 1.0 162:54.30 *slapd* 534 root 20 0 125084 65852 65536 S 5.9 0.4 0:33.31 systemd-journal 16851 radiusd 20 0 2608468 27604 4384 S 2.0 0.2 0:05.99 radiusd LDAP works perfectly, but adding NAS to it, these errors start Thu Jul 8 12:13:31 2021 : Info: rlm_ldap (ldap): Opening additional connection (380), 1 of 12 pending slots used Thu Jul 8 12:13:33 2021 : Info: rlm_ldap (ldap): Closing connection (353): Hit idle_timeout, was idle for 22 seconds Thu Jul 8 12:13:33 2021 : Info: rlm_ldap (ldap): Closing connection (373): Hit idle_timeout, was idle for 22 seconds Thu Jul 8 12:13:34 2021 : Info: rlm_ldap (ldap): Closing connection (374): Hit idle_timeout, was idle for 21 seconds Thu Jul 8 12:13:34 2021 : Info: Need 14 more connections to reach 29 spares Thu Jul 8 12:13:34 2021 : Info: rlm_ldap (ldap): Opening additional connection (381), 1 of 14 pending slots used Thu Jul 8 12:13:35 2021 : Info: Need 13 more connections to reach 29 spares Thu Jul 8 12:13:35 2021 : Info: rlm_ldap (ldap): Opening additional connection (382), 1 of 13 pending slots used Thu Jul 8 12:13:36 2021 : Info: Need 10 more connections to reach 29 spares Thu Jul 8 12:13:36 2021 : Info: rlm_ldap (ldap): Opening additional connection (383), 1 of 12 pending slots used Thu Jul 8 12:13:38 2021 : Info: Need 11 more connections to reach 29 spares Thu Jul 8 12:13:38 2021 : Info: rlm_ldap (ldap): Opening additional connection (384), 1 of 11 pending slots used Thu Jul 8 12:13:38 2021 : Info: Need 10 more connections to reach 29 spares Thu Jul 8 12:13:38 2021 : Info: rlm_ldap (ldap): Opening additional connection (385), 2 of 11 pending slots used Thu Jul 8 12:13:39 2021 : Info: Need 9 more connections to reach 29 spares Thu Jul 8 12:13:39 2021 : Info: rlm_ldap (ldap): Opening additional connection (386), 1 of 9 pending slots used Thu Jul 8 12:13:39 2021 : Error: (605) Ignoring duplicate packet from client SMDRUJR01 port 56405 - ID: 169 due to unfinished request in component authorize module ldap Thu Jul 8 12:13:40 2021 : Error: (606) Ignoring duplicate packet from client SMDRUJR01 port 58429 - ID: 29 due to unfinished request in component authorize module ldap Thu Jul 8 12:13:40 2021 : Info: Need 8 more connections to reach 29 spares Thu Jul 8 12:13:40 2021 : Info: rlm_ldap (ldap): Opening additional connection (387), 1 of 8 pending slots used Thu Jul 8 12:13:41 2021 : Info: Need 5 more connections to reach 29 spares Thu Jul 8 12:13:41 2021 : Info: rlm_ldap (ldap): Opening additional connection (388), 1 of 7 pending slots used Thu Jul 8 12:13:42 2021 : Info: Need 3 more connections to reach 29 spares Thu Jul 8 12:13:42 2021 : Info: rlm_ldap (ldap): Opening additional connection (389), 1 of 6 pending slots used Thu Jul 8 12:13:44 2021 : Info: Need 2 more connections to reach 29 spares Thu Jul 8 12:13:44 2021 : Info: rlm_ldap (ldap): Opening additional connection (390), 1 of 5 pending slots used Thu Jul 8 12:13:46 2021 : Info: Need 2 more connections to reach 29 spares Thu Jul 8 12:13:46 2021 : Info: rlm_ldap (ldap): Opening additional connection (391), 1 of 4 pending slots used Thu Jul 8 12:13:57 2021 : Info: rlm_ldap (ldap): Closing connection (361): Hit idle_timeout, was idle for 23 seconds Thu Jul 8 12:13:57 2021 : Info: rlm_ldap (ldap): Closing connection (322): Hit idle_timeout, was idle for 23 seconds Thu Jul 8 12:13:57 2021 : Info: rlm_ldap (ldap): Closing connection (318): Hit idle_timeout, was idle for 22 seconds Thu Jul 8 12:13:57 2021 : Info: rlm_ldap (ldap): Closing connection (356): Hit idle_timeout, was idle for 22 seconds Thu Jul 8 12:11:51 2021 : Error: (374) Ignoring duplicate packet from client ZPCOMRM21 port 33899 - ID: 200 due to unfinished request in component authorize module ldap Thu Jul 8 12:11:53 2021 : Error: Unresponsive child for request 367, in component authorize module ldap Thu Jul 8 12:11:54 2021 : Error: Unresponsive child for request 368, in component authorize module ldap Thu Jul 8 12:11:54 2021 : Error: (374) Ignoring duplicate packet from client ZPCOMRM21 port 33899 - ID: 200 due to unfinished request in component authorize module ldap Thu Jul 8 12:11:54 2021 : Error: Unresponsive child for request 369, in component authorize module ldap Thu Jul 8 12:11:55 2021 : Error: (375) Ignoring duplicate packet from client ZPCOMRM21 port 34052 - ID: 201 due to unfinished request in component authorize module ldap Thu Jul 8 12:11:56 2021 : Error: Unresponsive child for request 370, in component authorize module ldap Thu Jul 8 12:11:58 2021 : Error: (375) Ignoring duplicate packet from client ZPCOMRM21 port 34052 - ID: 201 due to unfinished request in component authorize module ldap Thu Jul 8 12:11:59 2021 : Error: (376) Ignoring duplicate packet from client ZPCOMRM21 port 48955 - ID: 202 due to unfinished request in component authorize module ldap Thu Jul 8 12:12:02 2021 : Error: (376) Ignoring duplicate packet from client ZPCOMRM21 port 48955 - ID: 202 due to unfinished request in component authorize module ldap Thu Jul 8 12:12:06 2021 : Error: (377) Ignoring duplicate packet from client ZPCOMRM21 port 38356 - ID: 203 due to unfinished request in component authorize module ldap Thu Jul 8 12:12:07 2021 : WARNING: (346) WARNING: Module rlm_ldap became unblocked Thu Jul 8 12:12:09 2021 : Error: (377) Ignoring duplicate packet from client ZPCOMRM21 port 38356 - ID: 203 due to unfinished request in component authorize module ldap Thu Jul 8 12:12:10 2021 : WARNING: (345) WARNING: Module rlm_ldap became unblocked Thu Jul 8 12:12:10 2021 : Error: (378) Ignoring duplicate packet from client ZPCOMRM21 port 47111 - ID: 204 due to unfinished request in component authorize module ldap Thu Jul 8 12:12:11 2021 : Error: Unresponsive child for request 372, in component authorize module ldap Thu Jul 8 12:12:13 2021 : Error: (378) Ignoring duplicate packet from client ZPCOMRM21 port 47111 - ID: 204 due to unfinished request in component authorize module ldap Thu Jul 8 12:12:15 2021 : Info: rlm_ldap (ldap): Closing connection (321): Hit idle_timeout, was idle for 25 seconds Thu Jul 8 12:12:15 2021 : WARNING: (347) WARNING: Module rlm_ldap became unblocked Thu Jul 8 12:12:17 2021 : Error: (379) Ignoring duplicate packet from client ZPCOMRM21 port 48758 - ID: 205 due to unfinished request in component authorize module ldap Thu Jul 8 12:12:18 2021 : Error: Unresponsive child for request 373, in component authorize module ldap Thu Jul 8 12:12:20 2021 : Error: (379) Ignoring duplicate packet from client ZPCOMRM21 port 48758 - ID: 205 due to unfinished request in component authorize module ldap Thu Jul 8 12:12:20 2021 : Error: (380) Ignoring duplicate packet from client ZPCOMRM21 port 59594 - ID: 206 due to unfinished request in component authorize module ldap Thu Jul 8 12:12:22 2021 : Info: rlm_ldap (ldap): Opening additional connection (322), 1 of 1 pending slots used Thu Jul 8 12:12:23 2021 : Error: (380) Ignoring duplicate packet from client ZPCOMRM21 port 59594 - ID: 206 due to unfinished request in component authorize module ldap Thu Jul 8 12:12:24 2021 : Error: (381) Ignoring duplicate packet from client SMDRUJR01 port 58429 - ID: 219 due to unfinished request in component <core> module <queue> Thu Jul 8 12:12:25 2021 : WARNING: (348) WARNING: Module rlm_ldap became unblocked Thu Jul 8 12:12:25 2021 : Error: (382) Ignoring duplicate packet from client SMDRUJR01 port 56405 - ID: 52 due to unfinished request in component <core> module <queue> Thu Jul 8 12:12:25 2021 : Error: (383) Ignoring duplicate packet from client SMDRUJR01 port 58429 - ID: 202 due to unfinished request in component <core> module <queue> Thu Jul 8 12:12:25 2021 : Error: (384) Ignoring duplicate packet from client SMDRUJR01 port 56405 - ID: 55 due to unfinished request in component <core> module <queue> Thu Jul 8 12:12:26 2021 : Error: Unresponsive child for request 374, in component authorize module ldap Thu Jul 8 12:12:30 2021 : Error: Unresponsive child for request 375, in component authorize module ldap Thu Jul 8 12:12:30 2021 : Error: (385) Ignoring duplicate packet from client ZPCOMRM21 port 41561 - ID: 207 due to unfinished request in component <core> module <queue> Thu Jul 8 12:12:33 2021 : Error: (385) Ignoring duplicate packet from client ZPCOMRM21 port 41561 - ID: 207 due to unfinished request in component <core> module <queue> Thu Jul 8 12:12:34 2021 : Error: Unresponsive child for request 376, in component authorize module ldap Thu Jul 8 12:12:38 2021 : Error: (386) Ignoring duplicate packet from client SMDRUJR01 port 52605 - ID: 99 due to unfinished request in component <core> module <queue> Thu Jul 8 12:12:39 2021 : Error: (387) Ignoring duplicate packet from client SMDRUJR01 port 56405 - ID: 127 due to unfinished request in component <core> module <queue> Thu Jul 8 12:12:41 2021 : Error: Unresponsive child for request 377, in component authorize module ldap I can see that multiple connections are established from FR to LDAP pto 389 tcp6 1 0 :::389 :::* LISTEN tcp6 0 0 :::22 :::* LISTEN tcp6 0 0 ::1:25 :::* LISTEN tcp6 0 0 ::1:389 ::1:59342 ESTABLISHED tcp6 0 0 ::1:389 ::1:59324 ESTABLISHED tcp6 0 0 ::1:59366 ::1:389 ESTABLISHED tcp6 0 0 ::1:59382 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59336 ESTABLISHED tcp6 0 0 ::1:59352 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59338 ESTABLISHED tcp6 0 0 ::1:389 ::1:59346 ESTABLISHED tcp6 0 0 ::1:389 ::1:59374 ESTABLISHED tcp6 0 0 ::1:59356 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59350 ESTABLISHED tcp6 0 0 ::1:389 ::1:59358 ESTABLISHED tcp6 0 0 ::1:389 ::1:59370 ESTABLISHED tcp6 0 0 ::1:389 ::1:59328 ESTABLISHED tcp6 0 0 ::1:59354 ::1:389 ESTABLISHED tcp6 14 0 ::1:59320 ::1:389 ESTABLISHED tcp6 14 0 ::1:59334 ::1:389 ESTABLISHED tcp6 14 0 ::1:59326 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59326 ESTABLISHED tcp6 14 0 ::1:59328 ::1:389 ESTABLISHED tcp6 0 0 ::1:59380 ::1:389 ESTABLISHED tcp6 0 0 ::1:59364 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59332 ESTABLISHED tcp6 54 0 ::1:389 ::1:59382 ESTABLISHED tcp6 0 0 ::1:389 ::1:59322 ESTABLISHED tcp6 14 0 ::1:59330 ::1:389 ESTABLISHED tcp6 14 0 ::1:59340 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59356 ESTABLISHED tcp6 0 0 ::1:389 ::1:59330 ESTABLISHED tcp6 0 0 ::1:59368 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59360 ESTABLISHED tcp6 0 0 ::1:59378 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59320 ESTABLISHED tcp6 0 0 ::1:389 ::1:59340 ESTABLISHED tcp6 14 0 ::1:59350 ::1:389 ESTABLISHED tcp6 0 0 ::1:59370 ::1:389 ESTABLISHED tcp6 0 0 ::1:59362 ::1:389 ESTABLISHED tcp6 14 0 ::1:59324 ::1:389 ESTABLISHED tcp6 14 0 ::1:59336 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59354 ESTABLISHED tcp6 14 0 ::1:59338 ::1:389 ESTABLISHED tcp6 0 0 ::1:59358 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59348 ESTABLISHED tcp6 0 0 ::1:59342 ::1:389 ESTABLISHED tcp6 0 0 ::1:59376 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59344 ESTABLISHED tcp6 14 0 ::1:59332 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59366 ESTABLISHED tcp6 14 0 ::1:59348 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59372 ESTABLISHED tcp6 14 0 ::1:59344 ::1:389 ESTABLISHED tcp6 14 0 ::1:59322 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59378 ESTABLISHED tcp6 0 0 ::1:389 ::1:59368 ESTABLISHED tcp6 0 0 ::1:59374 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59376 ESTABLISHED tcp6 0 0 ::1:59372 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59362 ESTABLISHED tcp6 0 0 ::1:389 ::1:59334 ESTABLISHED tcp6 0 0 ::1:389 ::1:59364 ESTABLISHED tcp6 14 0 ::1:59346 ::1:389 ESTABLISHED tcp6 0 0 ::1:59360 ::1:389 ESTABLISHED tcp6 0 0 ::1:389 ::1:59380 ESTABLISHED tcp6 0 0 ::1:389 ::1:59352 ESTABLISHED On Thu, Jul 8, 2021 at 10:07 AM Alan DeKok <aland@deployingradius.com> wrote:
On Jul 7, 2021, at 8:23 PM, Nicolás Ciuffolotti via Freeradius-Users < freeradius-users@lists.freeradius.org> wrote:
Sorry about my English, I'm still learning.
Your English is fine.
I have a Red Hat Enterprise Linux Server release 7.9 server and I have package freeradius-3.0.13-15.el7.x86_64 already installed and latest version installed for rhel-7-server-rpms repository I have installed openldap-2.4.44-23.el7_9.x86_64 as well. The LDAP server is active at all times, but when the FR starts receiving connections from NAS, the cpu process grows up and those errors start to be written to the radius log.
Yes, I understood that from your first message. You don't need to repeat it.
The "Module rlm_ldap became unblocked" message comes out because of the following:
* FreeRADIUS receives a packet * FreeRADIUS queries LDAP * nothing happens for 5 seconds * LDAP eventually returns an answer to FreeRADIUS
The solution is simple: Fix LDAP so that it doesn't take 5 seconds to respond to FreeRADIUS.
There is NOTHING you can do to FreeRADIUS to fix the LDAP server.
And there is no reason for FreeRADIUS to use 80-90% CPU. The default configuration is fast, and can handle 20K packets/s at 50% CPU load.
So the question is: What changes did you make in the default configuration? WHY is it using 80-90% CPU?
We can't explain why it's using 80% CPU, because (a) the default configuration doesn't do that, and (b) you haven't described what changes you made.
i.e. You should know what you've changed, and your shouldn't make changes which use 80% CPU.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html