limiting fail timeout for an LDAP module

[Zenon Mousmoulas]

Hi,

I am working with a peculiar LDAP backend which, from time to time, will 
take upwards of 10 seconds to respond to a search request. I know that 
is what needs fixing, but let's say I have to live with it for now. 
There is a second LDAP backend which I can use a backup when the first 
one goes nuts. So I'm thinking let's setup two LDAP module instances and 
use them in a redundant group. For this to be usable for EAP 
authentication however, I need to make sure freeradius fails the first 
LDAP module within some (short) time limit. I have thus been trying to 
tweak the first LDAP module instance settings in order to achieve that.

After experimenting with these settings:

options.res_timeout
options.srv_timelimit
pool.start

I found that if I set pool.start=0 and, say, options.res_timeout=2 
freeradius reconnects (retrying the search once) and fails the module 
after a total of 4 seconds:

Fri Feb  3 18:29:43 2017 : Debug: (1) ldap_first_bad: Waiting for search 
result...
Fri Feb  3 18:29:44 2017 : Debug: Waking up in 0.4 seconds.
Fri Feb  3 18:29:44 2017 : Debug: Waking up in 0.7 seconds.
Fri Feb  3 18:29:45 2017 : Debug: Waking up in 1.1 seconds.
Fri Feb  3 18:29:45 2017 : Debug: rlm_ldap: Closing libldap handle 
0x7fa240000cb0
Fri Feb  3 18:29:45 2017 : Debug: rlm_ldap (ldap_first_bad): 
Reconnecting (0)
Fri Feb  3 18:29:45 2017 : Debug: rlm_ldap (ldap_first_bad): Connecting 
to ldaps://xxxxxxxx
Fri Feb  3 18:29:45 2017 : Debug: rlm_ldap (ldap_first_bad): New libldap 
handle 0x7fa238000da0
Fri Feb  3 18:29:45 2017 : Debug: rlm_ldap (ldap_first_bad): Waiting for 
bind result...
Fri Feb  3 18:29:45 2017 : Debug: rlm_ldap (ldap_first_bad): Bind 
successful
Fri Feb  3 18:29:45 2017 : WARNING: (1) ldap_first_bad: Search failed: 
Timed out while waiting for server to respond. Got new socket, 
retrying...
Fri Feb  3 18:29:45 2017 : Debug: (1) ldap_first_bad: Waiting for search 
result...
Fri Feb  3 18:29:46 2017 : Debug: Waking up in 1.6 seconds.
Fri Feb  3 18:29:47 2017 : Debug: rlm_ldap: Closing libldap handle 
0x7fa238000da0
Fri Feb  3 18:29:47 2017 : Debug: rlm_ldap (ldap_first_bad): 
Reconnecting (0)
Fri Feb  3 18:29:47 2017 : Debug: rlm_ldap (ldap_first_bad): Connecting 
to ldaps://xxxxxxxx
Fri Feb  3 18:29:47 2017 : Debug: rlm_ldap (ldap_first_bad): New libldap 
handle 0x7fa238000da0
Fri Feb  3 18:29:47 2017 : Debug: rlm_ldap (ldap_first_bad): Waiting for 
bind result...
Fri Feb  3 18:29:47 2017 : Debug: rlm_ldap (ldap_first_bad): Bind 
successful
Fri Feb  3 18:29:47 2017 : WARNING: (1) ldap_first_bad: Search failed: 
Timed out while waiting for server to respond. Got new socket, 
retrying...
Fri Feb  3 18:29:47 2017 : Debug: (1) ldap_first_bad: Waiting for search 
result...
Fri Feb  3 18:29:48 2017 : Debug: Waking up in 2.5 seconds.
Fri Feb  3 18:29:48 2017 : Error: (1) Ignoring duplicate packet from 
client localhost port 34423 - ID: 11 due to unfinished request in 
component authorize module ldap_first_bad
Fri Feb  3 18:29:48 2017 : Debug: Waking up in 1.9 seconds.
Fri Feb  3 18:29:49 2017 : Debug: rlm_ldap: Closing libldap handle 
0x7fa238000da0
Fri Feb  3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): 
Reconnecting (0)
Fri Feb  3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): Connecting 
to ldaps://xxxxxxxx
Fri Feb  3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): New libldap 
handle 0x7fa238000da0
Fri Feb  3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): Waiting for 
bind result...
Fri Feb  3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): Bind 
successful
Fri Feb  3 18:29:49 2017 : WARNING: (1) ldap_first_bad: Search failed: 
Timed out while waiting for server to respond. Got new socket, 
retrying...
Fri Feb  3 18:29:49 2017 : ERROR: (1) ldap_first_bad: Hit reconnection 
limit
Fri Feb  3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): Released 
connection (0)
Fri Feb  3 18:29:49 2017 : Info: rlm_ldap (ldap_first_bad): Need 1 more 
connections to reach 10 spares
Fri Feb  3 18:29:49 2017 : Info: rlm_ldap (ldap_first_bad): Opening 
additional connection (2), 1 of 30 pending slots used
Fri Feb  3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): Connecting 
to ldaps://xxxxxxxx
Fri Feb  3 18:29:49 2017 : Debug: rlm_ldap (ldap_first_bad): New libldap 
handle 0x7fa2380215b0
Fri Feb  3 18:29:50 2017 : Debug: rlm_ldap (ldap_first_bad): Waiting for 
bind result...
Fri Feb  3 18:29:50 2017 : Debug: rlm_ldap (ldap_first_bad): Bind 
successful
Fri Feb  3 18:29:50 2017 : Debug: (1)       modsingle[authorize]: 
returned from ldap_first_bad (rlm_ldap)
Fri Feb  3 18:29:50 2017 : Debug: (1)       [ldap_first_bad] = fail
Fri Feb  3 18:29:50 2017 : Debug: (1)       modsingle[authorize]: 
calling ldap_backup (rlm_ldap)

I am wondering if this is as good as it gets or if there are other 
things to tweak or to try, to get a shorter timeout in this particular 
case, perhaps avoiding the side effect of start=0 documented therein 
(Set to 0 to allow the server to start without the directory being 
available).

This is on freeradius 3.0.12.

Thanks for any insight,
Z.