Error: Ignoring duplicate packet from client
Nicolás Ciuffolotti
nicolas.ciuffolotti at cotesma.com.ar
Thu Jul 8 17:41:01 CEST 2021
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 at deployingradius.com>
wrote:
> On Jul 7, 2021, at 8:23 PM, Nicolás Ciuffolotti via Freeradius-Users <
> freeradius-users at 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
More information about the Freeradius-Users
mailing list