Hi,
 
I have setup an LDAP proxy using OpenLDAP 2.4.23 running on CentOS release 6.2 Linux 2.6.32-220.4.2.el6.x86_64. Every second search operation on a connection returns an error:
 
SEARCH RESULT tag=101 err=1 nentries=0 text=000004DC: LdapErr: DSID-0C0906E8, comment: In order to perform this operation a successful bind must be completed on the connection., data 0, v1db1
 
database                ldap
readonly                on
suffix                  "dc=example,dc=com"
# Recreate cached connection before it can be dropped by the Active Directory. Default Active Directory timeout MaxConnIdleTime=900
idle-timeout            899
rebind-as-user          yes
uri                     "ldap://169.254.253.228/ ldap://169.254.239.115/ ldap://169.254.245.81/ ldap://169.254.239.91/"
 
 
Here is an extract of the LDAP log, filtered on one connection:
 
Jan 22 16:41:17 vmldapproxy1 slapd[1851]: conn=1035 fd=29 ACCEPT from IP=172.16.10.126:3579 (IP=0.0.0.0:389)
Jan 22 16:41:17 vmldapproxy1 slapd[1851]: conn=1035 op=0 BIND dn="cn=sa_srv,ou=service accounts,dc=example,dc=com" method=128
Jan 22 16:41:17 vmldapproxy1 slapd[1851]: conn=1035 op=0 BIND dn="cn=sa_srv,ou=service accounts,dc=example,dc=com" mech=SIMPLE ssf=0
Jan 22 16:41:17 vmldapproxy1 slapd[1851]: conn=1035 op=0 RESULT tag=97 err=0 text=
Jan 22 17:21:46 vmldapproxy1 slapd[1851]: conn=1035 op=1 SRCH base="dc=example,dc=com" scope=2 deref=3 filter="(|(cn=foobar)(uid=foobar)(sn=foobar)(givenName=foobar)(mail=foobar))"
Jan 22 17:21:46 vmldapproxy1 slapd[1851]: conn=1035 op=1 SRCH attr=FullName userPassword MailServer mail CalendarDomain MailFile uid ServerName EncryptIncomingMail ListName MailSystem objectClass member NetUserName SametimeServer uniqueMember DB2UserName MailDomain NotesDN AltFullName HTTPPasswordChangeDate modifyTimestamp Location CertificateThumbprint MailAddress HTTPPasswordForceChange Policy MessageStorage NewMailFile LTPA-UsrNm NewMailServer AltFullNameLanguage CN
Jan 22 17:21:46 vmldapproxy1 slapd[1851]: conn=1035 op=1 SEARCH RESULT tag=101 err=0 nentries=0 text=
Jan 22 17:23:31 vmldapproxy1 slapd[1851]: conn=1035 op=2 SRCH base="dc=example,dc=com" scope=2 deref=3 filter="(|(cn=foo.bar@example.com)(uid=foo.bar@example.com)(sn=foo.bar@example.com)(givenName=foo.bar@example.com)(mail=foo.bar@example.com))"
Jan 22 17:23:31 vmldapproxy1 slapd[1851]: conn=1035 op=2 SRCH attr=FullName userPassword MailServer mail CalendarDomain MailFile uid ServerName EncryptIncomingMail ListName MailSystem objectClass member NetUserName SametimeServer uniqueMember DB2UserName MailDomain NotesDN AltFullName HTTPPasswordChangeDate modifyTimestamp Location CertificateThumbprint MailAddress HTTPPasswordForceChange Policy MessageStorage NewMailFile LTPA-UsrNm NewMailServer AltFullNameLanguage CN
Jan 22 17:23:31 vmldapproxy1 slapd[1851]: conn=1035 op=2 SEARCH RESULT tag=101 err=1 nentries=0 text=000004DC: LdapErr: DSID-0C0906E8, comment: In order to perform this operation a successful bind must be completed on the connection., data 0, v1db1
 
Every subsequent search operation going forward generates the same error.
 
The time difference between the bind (op=0) and the first successful search (op=1) is 40 minutes 29 seconds. The time between op=1 and the first failed search op=2 is 1 minute 45 seconds. This behaviour is consistent for all connections, and appears independent of time. Therefore I’m not seeing how timeouts factor into this issue.
 
Appears a few folks have posted about this, here and elsewhere, but I could not find any suitable explanation that resolved the issue. Hoping someone can help me out.
 
Thanks, and regards,
Bryce Powell