LDAP Server Connections Closing Immediately

[Jonathan Gryak]

Hello All,
It appears that the LDAP pool configuration isn't reusing the LDAP
connections as configured. I am running the following version of FreeRADIUS:

>
> FreeRADIUS Version 3.0.12 (git #34f7ba7), built on Apr  6 2016 at 08:07:17


Below is the debug output of the pool initialization:

> rlm_ldap (ldap): Initialising connection pool
>    pool {
>     start = 5
>     min = 3
>     max = 32
>     spare = 10
>     uses = 0
>     lifetime = 0
>     cleanup_interval = 30
>     idle_timeout = 60
>     retry_delay = 30
>     spread = no
>    }
> rlm_ldap (ldap): Opening additional connection (0), 1 of 32 pending slots
> used
> rlm_ldap (ldap): Connecting to ldap://<server>:389
> rlm_ldap (ldap): Waiting for bind result...
> rlm_ldap (ldap): Bind successful
> rlm_ldap (ldap): Opening additional connection (1), 1 of 31 pending slots
> used
> rlm_ldap (ldap): Connecting to ldap://<server>:389
> rlm_ldap (ldap): Waiting for bind result...
> rlm_ldap (ldap): Bind successful
> rlm_ldap (ldap): Opening additional connection (2), 1 of 30 pending slots
> used
> rlm_ldap (ldap): Connecting to ldap://<server>:389
> rlm_ldap (ldap): Waiting for bind result...
> rlm_ldap (ldap): Bind successful
> rlm_ldap (ldap): Opening additional connection (3), 1 of 29 pending slots
> used
> rlm_ldap (ldap): Connecting to ldap://<server>:389
> rlm_ldap (ldap): Waiting for bind result...
> rlm_ldap (ldap): Bind successful
> rlm_ldap (ldap): Opening additional connection (4), 1 of 28 pending slots
> used
> rlm_ldap (ldap): Connecting to ldap://<server>:389
> rlm_ldap (ldap): Waiting for bind result...
> rlm_ldap (ldap): Bind successful


Debug Output:
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Rebinding to URL
ldap://ForestDnsZones.<domain>/DC=ForestDnsZones,DC=DC=<domain>
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Rebinding to URL
ldap://<domain>/CN=Configuration,DC=DC=<domain>
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
(7)           Search returned no results
(7)         Checking user object's memberOf attributes
(7)           Waiting for bind result...
(7)           Bind successful
(7)           Performing unfiltered search in "<user-DN>", scope "base"
(7)           Waiting for search result...
(7)         No group membership attribute(s) found in user object
rlm_ldap (ldap): Deleting connection (2)
(7)         User is not a member of "BOE"
(7)         Searching for user in group "Admin-Users"
rlm_ldap (ldap): Reserved connection (3)
(7)         Using user DN from request "<user-DN>"
(7)         Checking for user in group objects
(7)           EXPAND
(&(cn=Admin-Users)(objectClass=group)(&(objectClass=group)(member=%{Ldap-UserDn})))
(7)              -->
(&(cn=Admin-Users)(objectClass=group)(&(objectClass=group)(member=)))
(7)           Performing search in "<domain>" with filter
"(&(cn=Admin-Users)(objectClass=group)(&(objectClass=group)(member=)))",
scope "sub"
(7)           Waiting for search result...
rlm_ldap (ldap): Rebinding to URL
ldap://DomainDnsZones.<domain>/DC=DomainDnsZones,DC=DC=<domain>
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Rebinding to URL
ldap://ForestDnsZones.<domain>/DC=ForestDnsZones,DC=DC=<domain>
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Rebinding to URL
ldap://<domain>/CN=Configuration,DC=DC=<domain>
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
(7)           Search returned no results
(7)         Checking user object's memberOf attributes
(7)           Waiting for bind result...
(7)           Bind successful
(7)           Performing unfiltered search in "<user-DN>", scope "base"
(7)           Waiting for search result...
(7)         No group membership attribute(s) found in user object
rlm_ldap (ldap): Deleting connection (3)
(7)         User is not a member of "Admin-Users"
(7)         Searching for user in group "Admin-Computers"
rlm_ldap (ldap): Reserved connection (4)
(7)         Using user DN from request "<user-DN>"
(7)         Checking for user in group objects
(7)           EXPAND
(&(cn=Admin-Computers)(objectClass=group)(&(objectClass=group)(member=%{Ldap-UserDn})))
(7)              -->
(&(cn=Admin-Computers)(objectClass=group)(&(objectClass=group)(member=)))
(7)           Performing search in "<domain>" with filter
"(&(cn=Admin-Computers)(objectClass=group)(&(objectClass=group)(member=)))",
scope "sub"
(7)           Waiting for search result...
rlm_ldap (ldap): Rebinding to URL
ldap://DomainDnsZones.<domain>/DC=DomainDnsZones,DC=DC=<domain>
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Rebinding to URL
ldap://ForestDnsZones.<domain>/DC=ForestDnsZones,DC=DC=<domain>
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Rebinding to URL
ldap://<domain>/CN=Configuration,DC=DC=<domain>
rlm_ldap (ldap): Waiting for bind result...
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
rlm_ldap (ldap): Bind successful
(7)           Search returned no results
(7)         Checking user object's memberOf attributes
(7)           Waiting for bind result...
(7)           Bind successful
(7)           Performing unfiltered search in "<user-DN>", scope "base"
(7)           Waiting for search result...
(7)         No group membership attribute(s) found in user object
rlm_ldap (ldap): Deleting connection (4)

-- 
Jonathan Gryak
Infrastructure Manager

Westport Public Schools
Technology Center
136 Riverside Avenue
Westport, CT 06880
(203) 341-1211