0

After converting from freeradius2 to freeradius3 found out rlm_ldap is really chatty:

Fri Feb  2 08:02:51 2018 : Info: rlm_ldap (ldap): Closing connection (79): Hit idle_timeout, was idle for 202 seconds
Fri Feb  2 08:02:51 2018 : Info: rlm_ldap (ldap): Closing connection (80): Hit idle_timeout, was idle for 202 seconds
Fri Feb  2 08:02:51 2018 : Info: rlm_ldap (ldap): Opening additional connection (81), 1 of 32 pending slots used
Fri Feb  2 08:02:51 2018 : Info: Need 2 more connections to reach min connections (3)

I would like radius.log to only have auth msg lines:

Fri Feb  2 08:02:51 2018 : Auth: (3951) Login OK: [user] (from client aphub port 1 cli FA-KE-MA-CA-DD-RE)

But I can't find how to disable logging selectively on a single module.

Follows one hour log from rlm_ldap:

Fri Feb  9 10:06:02 2018 : Info: rlm_ldap (ldap2): Closing connection (1320): Hit idle_timeout, was idle for 430 seconds
Fri Feb  9 10:06:02 2018 : Info: rlm_ldap (ldap2): Closing connection (1319): Hit idle_timeout, was idle for 430 seconds
Fri Feb  9 10:06:02 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1321), 1 of 32 pending slots used
Fri Feb  9 10:06:03 2018 : Info: Need 2 more connections to reach min connections (3)
Fri Feb  9 10:06:03 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1322), 1 of 31 pending slots used
Fri Feb  9 10:06:03 2018 : Info: rlm_ldap (ldap2-secondary): Closing connection (1227): Hit idle_timeout, was idle for 431 seconds
Fri Feb  9 10:06:03 2018 : Info: rlm_ldap (ldap2-secondary): Closing connection (1228): Hit idle_timeout, was idle for 431 seconds
Fri Feb  9 10:06:03 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1229), 1 of 32 pending slots used
Fri Feb  9 10:06:03 2018 : Info: Need 2 more connections to reach min connections (3)
Fri Feb  9 10:06:03 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1230), 1 of 31 pending slots used
Fri Feb  9 10:11:20 2018 : Info: rlm_ldap (ldap2): Closing connection (1322): Hit idle_timeout, was idle for 317 seconds
Fri Feb  9 10:11:20 2018 : Info: rlm_ldap (ldap2): Closing connection (1321): Hit idle_timeout, was idle for 317 seconds
Fri Feb  9 10:11:20 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1323), 1 of 32 pending slots used
Fri Feb  9 10:11:20 2018 : Info: Need 2 more connections to reach min connections (3)
Fri Feb  9 10:11:20 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1324), 1 of 31 pending slots used
Fri Feb  9 10:11:20 2018 : Info: rlm_ldap (ldap2-secondary): Closing connection (1229): Hit idle_timeout, was idle for 317 seconds
Fri Feb  9 10:11:20 2018 : Info: rlm_ldap (ldap2-secondary): Closing connection (1230): Hit idle_timeout, was idle for 317 seconds
Fri Feb  9 10:11:20 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1231), 1 of 32 pending slots used
Fri Feb  9 10:11:20 2018 : Info: Need 2 more connections to reach min connections (3)
Fri Feb  9 10:11:20 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1232), 1 of 31 pending slots used
Fri Feb  9 10:18:22 2018 : Info: rlm_ldap (ldap2): Closing connection (1324): Hit idle_timeout, was idle for 422 seconds
Fri Feb  9 10:18:22 2018 : Info: rlm_ldap (ldap2): Closing connection (1323): Hit idle_timeout, was idle for 422 seconds
Fri Feb  9 10:18:22 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1325), 1 of 32 pending slots used
Fri Feb  9 10:18:23 2018 : Info: Need 2 more connections to reach min connections (3)
Fri Feb  9 10:18:23 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1326), 1 of 31 pending slots used
Fri Feb  9 10:18:23 2018 : Info: rlm_ldap (ldap2-secondary): Closing connection (1231): Hit idle_timeout, was idle for 423 seconds
Fri Feb  9 10:18:23 2018 : Info: rlm_ldap (ldap2-secondary): Closing connection (1232): Hit idle_timeout, was idle for 423 seconds
Fri Feb  9 10:18:23 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1233), 1 of 32 pending slots used
Fri Feb  9 10:18:23 2018 : Info: Need 2 more connections to reach min connections (3)
Fri Feb  9 10:18:23 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1234), 1 of 31 pending slots used
Fri Feb  9 10:22:24 2018 : Info: rlm_ldap (ldap2): Closing connection (1326): Hit idle_timeout, was idle for 241 seconds
Fri Feb  9 10:22:24 2018 : Info: rlm_ldap (ldap2): Closing connection (1325): Hit idle_timeout, was idle for 241 seconds
Fri Feb  9 10:22:24 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1327), 1 of 32 pending slots used
Fri Feb  9 10:22:24 2018 : Info: Need 2 more connections to reach min connections (3)
Fri Feb  9 10:22:24 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1328), 1 of 31 pending slots used
Fri Feb  9 10:22:24 2018 : Info: rlm_ldap (ldap2-secondary): Closing connection (1233): Hit idle_timeout, was idle for 241 seconds
Fri Feb  9 10:22:24 2018 : Info: rlm_ldap (ldap2-secondary): Closing connection (1234): Hit idle_timeout, was idle for 241 seconds
Fri Feb  9 10:22:24 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1235), 1 of 32 pending slots used
Fri Feb  9 10:22:24 2018 : Info: Need 2 more connections to reach min connections (3)
Fri Feb  9 10:22:24 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1236), 1 of 31 pending slots used
Fri Feb  9 10:51:55 2018 : Info: rlm_ldap (ldap2): Closing connection (1328): Hit idle_timeout, was idle for 1771 seconds
Fri Feb  9 10:51:55 2018 : Info: rlm_ldap (ldap2): Closing connection (1327): Hit idle_timeout, was idle for 1771 seconds
Fri Feb  9 10:51:55 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1329), 1 of 32 pending slots used
Fri Feb  9 10:51:55 2018 : Info: Need 2 more connections to reach min connections (3)
Fri Feb  9 10:51:55 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1330), 1 of 31 pending slots used
Fri Feb  9 10:51:55 2018 : Info: rlm_ldap (ldap2-secondary): Closing connection (1235): Hit idle_timeout, was idle for 1771 seconds
Fri Feb  9 10:51:55 2018 : Info: rlm_ldap (ldap2-secondary): Closing connection (1236): Hit idle_timeout, was idle for 1771 seconds
Fri Feb  9 10:51:55 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1237), 1 of 32 pending slots used
Fri Feb  9 10:51:55 2018 : Info: Need 2 more connections to reach min connections (3)
Fri Feb  9 10:51:55 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1238), 1 of 31 pending slots used
Fri Feb  9 10:55:54 2018 : Info: rlm_ldap (ldap2): Closing connection (1330): Hit idle_timeout, was idle for 239 seconds
Fri Feb  9 10:55:54 2018 : Info: rlm_ldap (ldap2): Closing connection (1329): Hit idle_timeout, was idle for 239 seconds
Fri Feb  9 10:55:54 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1331), 1 of 32 pending slots used
Fri Feb  9 10:55:54 2018 : Info: Need 2 more connections to reach min connections (3)
Fri Feb  9 10:55:54 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1332), 1 of 31 pending slots used
Fri Feb  9 10:55:54 2018 : Info: rlm_ldap (ldap2-secondary): Closing connection (1237): Hit idle_timeout, was idle for 239 seconds
Fri Feb  9 10:55:54 2018 : Info: rlm_ldap (ldap2-secondary): Closing connection (1238): Hit idle_timeout, was idle for 239 seconds
Fri Feb  9 10:55:54 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1239), 1 of 32 pending slots used
Fri Feb  9 10:55:54 2018 : Info: Need 2 more connections to reach min connections (3)
Fri Feb  9 10:55:54 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1240), 1 of 31 pending slots used
Fri Feb  9 10:56:14 2018 : Info: Need 1 more connections to reach min connections (3)
Fri Feb  9 10:56:14 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1333), 1 of 30 pending slots used
Fri Feb  9 10:56:14 2018 : Info: Need 1 more connections to reach min connections (3)
Fri Feb  9 10:56:14 2018 : Info: rlm_ldap (ldap2-secondary): Opening additional connection (1241), 1 of 30 pending slots used
Fri Feb  9 10:56:15 2018 : Info: Need 7 more connections to reach 10 spares
Fri Feb  9 10:56:15 2018 : Info: rlm_ldap (ldap2): Opening additional connection (1334), 1 of 29 pending slots used

In the same time slice 19 Auth happened.

473183469
  • 1,350
  • 1
  • 12
  • 23

1 Answers1

1

You could, you know, fix the underlying issue. i.e. Tweak the connection pool settings to that the connection pool isn't constantly creating and destroying connections.

Without knowing why it's creating or destroying connections I can't really suggest which parameters to tune, but if you grep the out the LDAP messages for about an hour's worth of runtime, and add them as an attachment (on pastebin or similar...), I can probably point you in the right direction.

Arran Cudbard-Bell
  • 1,514
  • 1
  • 9
  • 18
  • I didn't allow for a so rational solution. I was trying to hide logs when solving the underlying issue is far more logical. I have so few Auth (19 only in one hour) so I pasted the rlm_ldap log lines verbatim in the question. – 473183469 Feb 09 '18 at 17:57
  • Started by setting `idle_timeout = 900` in pool section. It looks fine. I am bit suspicious because ldapserver has a idle timeout of 120 secs. Not sure if it has to match. – 473183469 Feb 13 '18 at 07:43
  • Unfortunately in v3, if the socket goes away, and you try to issue a query on it, it will result in an error. This should be fixed in a later version of v4, which puts all the socket FDs in an eventing system. – Arran Cudbard-Bell Feb 14 '18 at 10:00
  • Seeing as you have very very low traffic, I'd set min to 1, and spare to 1 so you only keep one connection open. Depending on how the server handles the keepalives it may or may not drop the connection before FreeRADIUS. Easiest way is to check... should be pretty easy to see what it's doing. – Arran Cudbard-Bell Feb 14 '18 at 10:05