[RADIATOR] AuthBy LDAP2 LDAP hosts

Tue May 2 10:48:59 UTC 2017

Hello,

> On 1 May 2017, at 17.07, rohan.henry cwjamaica.com <rohan.henry at cwjamaica.com> wrote:
> 
> Another Radiator instance is checking next available ldap server (.52 is still down) even with HoldServerConnection enabled. See attached.
> 
> But I do not yet find any difference between this config and the config on other instances that are not working.
> 

configs seemed to be identical regarding LDAP connection settings.

When Trace 4 debugging is enabled and if you look at logs over longer period 
or restart Radiator processes, you will see logs similar to log snippets below:

(Radiator version 4.17 and Perl Net::LDAP library version 0.65)

1. When no open TCP connection to LDAP yet exists, Radiator connects to first available host, 10.40.0.153 in this case:

Tue May  2 13:28:07 2017: DEBUG: Handling request with Handler '', Identifier ''
Tue May  2 13:28:07 2017: DEBUG: Handling with Radius::AuthLDAP2: 
Tue May  2 13:28:07 2017: INFO: Connecting to 10.40.0.153:8389 10.41.0.33:8389
Tue May  2 13:28:07 2017: INFO: Connected to 10.40.0.153:8389
Tue May  2 13:28:07 2017: INFO: Attempting to bind to LDAP server 10.40.0.153:8389
Tue May  2 13:28:07 2017: DEBUG: LDAP got result with filter (cn=mikem) for DN dc=example, dc=com
Tue May  2 13:28:07 2017: DEBUG: LDAP got dn: dc=example, dc=com
Tue May  2 13:28:07 2017: DEBUG: LDAP got cn: mikem
Tue May  2 13:28:07 2017: DEBUG: LDAP got userPassword: **obscured**
Tue May  2 13:28:07 2017: DEBUG: Radius::AuthLDAP2 looks for match with mikem [mikem]
Tue May  2 13:28:07 2017: DEBUG: Radius::AuthLDAP2 ACCEPT: : mikem [mikem]
Tue May  2 13:28:07 2017: DEBUG: AuthBy LDAP2 result: ACCEPT, 
Tue May  2 13:28:07 2017: DEBUG: Access accepted for mikem

2. LDAP server process on 10.40.0.153 is shutdown and Radiator notices it when trying to do an LDAP query. Now Radiator connects to a second LDAP host 10.41.0.33.

Tue May  2 13:28:26 2017: DEBUG: Handling request with Handler '', Identifier ''
Tue May  2 13:28:26 2017: DEBUG: Handling with Radius::AuthLDAP2: 
Tue May  2 13:28:26 2017: INFO: Server side disconnect (server 10.40.0.153:8389).
Tue May  2 13:28:26 2017: INFO: Connecting to 10.40.0.153:8389 10.41.0.33:8389
Tue May  2 13:28:26 2017: INFO: Connected to 10.41.0.33:8389
Tue May  2 13:28:26 2017: INFO: Attempting to bind to LDAP server 10.41.0.33:8389
Tue May  2 13:28:26 2017: DEBUG: LDAP got result with filter (cn=mikem) for DN dc=example, dc=com
Tue May  2 13:28:26 2017: DEBUG: LDAP got dn: dc=example, dc=com
Tue May  2 13:28:26 2017: DEBUG: LDAP got cn: mikem
Tue May  2 13:28:26 2017: DEBUG: LDAP got userPassword: **obscured**
Tue May  2 13:28:26 2017: DEBUG: Radius::AuthLDAP2 looks for match with mikem [mikem]
Tue May  2 13:28:26 2017: DEBUG: Radius::AuthLDAP2 ACCEPT: : mikem [mikem]
Tue May  2 13:28:26 2017: DEBUG: AuthBy LDAP2 result: ACCEPT, 
Tue May  2 13:28:26 2017: DEBUG: Access accepted for mikem

3. LDAP server process on 10.41.0.33 is suspended, now an LDAP query timeouts which leads to a disconnect from 10.41.0.33.

Tue May  2 13:29:00 2017: DEBUG: Handling request with Handler '', Identifier ''
Tue May  2 13:29:00 2017: DEBUG: Handling with Radius::AuthLDAP2: 
Tue May  2 13:29:02 2017: ERR: ldap search for (cn=mikem) failed with error LDAP Timeout.
Tue May  2 13:29:02 2017: ERR: Disconnecting from LDAP server (server 10.41.0.33:8389).
Tue May  2 13:29:02 2017: DEBUG: AuthBy LDAP2 result: IGNORE, User database access error
Tue May  2 13:29:02 2017: DEBUG: Handling with AuthINTERNAL: 
Tue May  2 13:29:02 2017: DEBUG: AuthBy INTERNAL result: ACCEPT, Fixed by DefaultResult
Tue May  2 13:29:02 2017: DEBUG: Access accepted for mikem

4. LDAP server process on 10.40.0.153 is started and Radiator connects again to a first LDAP server 10.40.0.153.

Tue May  2 13:29:21 2017: DEBUG: Handling request with Handler '', Identifier ''
Tue May  2 13:29:21 2017: DEBUG: Handling with Radius::AuthLDAP2: 
Tue May  2 13:29:21 2017: INFO: Connecting to 10.40.0.153:8389 10.41.0.33:8389
Tue May  2 13:29:21 2017: INFO: Connected to 10.40.0.153:8389
Tue May  2 13:29:21 2017: INFO: Attempting to bind to LDAP server 10.40.0.153:8389
Tue May  2 13:29:21 2017: DEBUG: LDAP got result with filter (cn=mikem) for DN dc=example, dc=com
Tue May  2 13:29:21 2017: DEBUG: LDAP got dn: dc=example, dc=com
Tue May  2 13:29:21 2017: DEBUG: LDAP got cn: mikem
Tue May  2 13:29:21 2017: DEBUG: LDAP got userPassword: **obscured**
Tue May  2 13:29:21 2017: DEBUG: Radius::AuthLDAP2 looks for match with mikem [mikem]
Tue May  2 13:29:21 2017: DEBUG: Radius::AuthLDAP2 ACCEPT: : mikem [mikem]
Tue May  2 13:29:21 2017: DEBUG: AuthBy LDAP2 result: ACCEPT, 
Tue May  2 13:29:21 2017: DEBUG: Access accepted for mikem

5. LDAP server process on 10.40.0.153 is suspended, now an LDAP query timeouts which leads to a disconnect from 10.40.0.153.

Tue May  2 13:30:01 2017: DEBUG: Handling request with Handler '', Identifier ''
Tue May  2 13:30:01 2017: DEBUG: Handling with Radius::AuthLDAP2: 
Tue May  2 13:30:03 2017: ERR: ldap search for (cn=mikem) failed with error LDAP Timeout.
Tue May  2 13:30:03 2017: ERR: Disconnecting from LDAP server (server 10.40.0.153:8389).
Tue May  2 13:30:03 2017: DEBUG: AuthBy LDAP2 result: IGNORE, User database access error
Tue May  2 13:30:03 2017: DEBUG: Handling with AuthINTERNAL: 
Tue May  2 13:30:03 2017: DEBUG: AuthBy INTERNAL result: ACCEPT, Fixed by DefaultResult
Tue May  2 13:30:03 2017: DEBUG: Access accepted for mikem

6. LDAP server processes on both hosts 10.40.0.153 and 10.41.0.33 are shutdown and Radiator is unable to connect to neither of them which leads to backing off from trying to connect to LDAP for 10 seconds (FailureBackoffTime configuration option, defaults to 600 seconds)

Tue May  2 13:30:10 2017: DEBUG: Handling request with Handler '', Identifier ''
Tue May  2 13:30:10 2017: DEBUG: Handling with Radius::AuthLDAP2: 
Tue May  2 13:30:10 2017: INFO: Connecting to 10.40.0.153:8389 10.41.0.33:8389
Tue May  2 13:30:10 2017: ERR: Could not open LDAP connection to 10.40.0.153:8389 10.41.0.33:8389. Backing off for 10 seconds.
Tue May  2 13:30:12 2017: DEBUG: AuthBy LDAP2 result: IGNORE, User database access error
Tue May  2 13:30:12 2017: DEBUG: Handling with AuthINTERNAL: 
Tue May  2 13:30:12 2017: DEBUG: AuthBy INTERNAL result: ACCEPT, Fixed by DefaultResult
Tue May  2 13:30:12 2017: DEBUG: Access accepted for mikem

7. Radiator is still backing off from trying to connect to LDAP so request is ignored by AuthBy LDAP2.

Tue May  2 13:30:18 2017: DEBUG: Handling request with Handler '', Identifier ''
Tue May  2 13:30:18 2017: DEBUG: Handling with Radius::AuthLDAP2: 
Tue May  2 13:30:18 2017: DEBUG: AuthBy LDAP2 result: IGNORE, User database access error
Tue May  2 13:30:18 2017: DEBUG: Handling with AuthINTERNAL: 
Tue May  2 13:30:18 2017: DEBUG: AuthBy INTERNAL result: ACCEPT, Fixed by DefaultResult
Tue May  2 13:30:18 2017: DEBUG: Access accepted for mikem

BR
-- 
Tuure Vartiainen <vartiait at open.com.au>

Radiator: the most portable, flexible and configurable RADIUS server
anywhere. SQL, proxy, DBM, files, LDAP, NIS+, password, NT, Emerald,
Platypus, Freeside, TACACS+, PAM, external, Active Directory, EAP, TLS,
TTLS, PEAP, TNC, WiMAX, RSA, Vasco, Yubikey, MOTP, HOTP, TOTP,
DIAMETER etc. Full source on Unix, Windows, MacOSX, Solaris, VMS,
NetWare etc.