OpenLDAP seems to ignore UNBIND (ITS#2112)

[alexandre.aufrere@inet6.fr]

Full_Name: Alexandre Aufrere
Version: 2.0.23
OS: RedHat Linux 7.3
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (62.210.105.37)


Ok, i don't know if this is an OpenLDAP or JNDI bug yet, because it looks very
weird.
I'm getting random "CommunicationException" in my app, using JNDI, under heavy
load.

Digging inside the problem, and enabling OpenLDAP debug (loglevel 256), i found
that the following scenario was happening:
For an unknown reason, JNDI send to OpenLDAP an "UNBIND" order after making a
"SRCH base=..." but _before_ getting the "SEARCH RESULT" reply from OpenLDAP. As
JNDI is not closing the Socket after the UNBIND (maybe for reusing it for
another connection to OpenLDAP), it receives that SEARCH RESULT from OpenLDAP
from a Connexion that he believes is in "free" state, and therefore goes on
Exception.

So i don't know where exactly is the problem: OpenLDAP ignoring the "UNBIND"
order, or JNDI not waiting for a SEARCH RESULT before doing the UNBIND and
setting connexion as "free".

------------------------
Extract from Java trace
------------------------
javax.naming.CommunicationException: Request: 2cancelled; remaining name
'uid=xxxxxxxxxxxxxxxxxxx'
at com.sun.jndi.ldap.LdapRequest.getReplyBer(LdapRequest.java:42)
at com.sun.jndi.ldap.Connection.readReply(Connection.java:270)
at com.sun.jndi.ldap.LdapClient.getSearchReply(LdapClient.java:613)
at com.sun.jndi.ldap.LdapClient.search(LdapClient.java:529)
at com.sun.jndi.ldap.LdapCtx.doSearch(LdapCtx.java:1791)
at com.sun.jndi.ldap.LdapCtx.doSearchOnce(LdapCtx.java:1740)
at com.sun.jndi.ldap.LdapCtx.c_getAttributes(LdapCtx.java:1134)
at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_getAttributes(ComponentDirContext.java:211)
at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.getAttributes(PartialCompositeDirContext.java:119)
at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.getAttributes(PartialCompositeDirContext.java:107)
at javax.naming.directory.InitialDirContext.getAttributes(InitialDirContext.java:119)
at javax.naming.directory.InitialDirContext.getAttributes(InitialDirContext.java:114)

----------------------------
Extract from OpenLDAP debug
----------------------------
Sep 25 14:04:51 xxx slapd[756]: conn=123 op=0 BIND dn="CN=XXXXXXXX" method=128
Sep 25 14:04:51 xxx slapd[756]: conn=123 op=0 RESULT tag=97 err=0 text=
Sep 25 14:04:51 xxx slapd[653]: conn=123 op=1 SRCH base="dc=xxxxx" scope=2
filter="(aliasedObjectName=uid=xxxxxxx)"
Sep 25 14:04:51 xxx slapd[713]: conn=123 op=2 UNBIND
Sep 25 14:04:51 xxx slapd[560]: daemon: conn=126 fd=9 connection from
IP=192.168.50.103:54675 (IP=0.0.0.0:34049) accepted.
Sep 25 14:04:51 xxx slapd[712]: conn=126 op=0 BIND dn="CN=XXXXXXXX" method=128
Sep 25 14:04:51 xxx slapd[712]: conn=126 op=0 RESULT tag=97 err=0 text=
Sep 25 14:04:51 xxx slapd[560]: deferring operation
Sep 25 14:04:51 xxx slapd[756]: conn=126 op=1 SRCH base="uid=xxxx" scope=0
filter="(objectClass=*)"
Sep 25 14:04:51 xxx slapd[560]: daemon: conn=127 fd=17 connection from
IP=192.168.50.103:54676 (IP=0.0.0.0:34049) accepted.
Sep 25 14:04:51 xxx slapd[756]: conn=126 op=1 SEARCH RESULT tag=101 err=0 text=
Sep 25 14:04:51 xxx slapd[653]: conn=123 op=1 SEARCH RESULT tag=101 err=0 text=
Sep 25 14:04:51 xxx slapd[749]: conn=126 op=3 UNBIND