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