(ITS#6548) Many "connection_read(): no connection!" warnings when using ldapi:/// and a bind DN (no external authentication)

[online@mark.ziesemer.com]

Full_Name: Mark A. Ziesemer
Version: 2.4.21
OS: Ubuntu Linux 10.04
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (2001:470:1f11:3ae:4d6d:3d3e:faa6:ee3d)


Many "connection_read(): no connection!" warnings are written to /var/log/debug
and /var/log/syslog by slapd.  As stated at
http://www.openldap.org/lists/openldap-software/200811/msg00079.html , this is
apparently not a problem with slapd, but a client that is disconnecting without
first unbinding.

This appears to be an issue with the libldap client library provided by OpenLDAP
itself (2.4.21), and not the slapd daemon.

Issue is reproducible even by just using "ldapsearch -H ldapi:///", but only if
a bind DN is specified (-D) and external authentication is not used.

Running slapd with logging enabled (-d 8) shows the following 3 sequences -
ldapsearch command followed by the slapd logs.  Note that the
"connection_read(): no connection!" is only visible on the middle pair.


$ ldapsearch -LLL -Y EXTERNAL -H ldapi:/// -b ""
SASL/EXTERNAL authentication started
SASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth
SASL SSF: 0
No such object (32)

slap_listener_activate(9): 
>>> slap_listener(ldapi:///)
connection_get(14): got connid=1000
connection_read(14): checking for input on id=1000
ber_get_next
ber_get_next: tag 0x30 len 24 contents:
op tag 0x60, time 1273546410
ber_get_next
conn=1000 op=0 do_bind
ber_scanf fmt ({imt) ber:
ber_scanf fmt ({m) ber:
ber_scanf fmt (m) ber:
ber_scanf fmt (}}) ber:
>>> dnPrettyNormal: <>
<<< dnPrettyNormal: <>, <>
do_bind: dn () SASL mech EXTERNAL
==>slap_sasl2dn: converting SASL name
gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth to a DN
<==slap_sasl2dn: Converted SASL name to <nothing>
SASL Authorize [conn=1000]:  proxy authorization allowed authzDN=""
send_ldap_sasl: err=0 len=-1
do_bind: SASL/EXTERNAL bind:
dn="gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth" sasl_ssf=0
send_ldap_response: msgid=1 tag=97 err=0
ber_flush2: 14 bytes to sd 14
<== slap_sasl_bind: rc=0
connection_get(14): got connid=1000
connection_read(14): checking for input on id=1000
ber_get_next
ber_get_next: tag 0x30 len 37 contents:
op tag 0x63, time 1273546410
ber_get_next
conn=1000 op=1 do_search
ber_scanf fmt ({miiiib) ber:
>>> dnPrettyNormal: <>
<<< dnPrettyNormal: <>, <>
ber_scanf fmt (m) ber:
ber_scanf fmt ({M}}) ber:
send_ldap_result: conn=1000 op=1 p=3
send_ldap_response: msgid=2 tag=101 err=32
ber_flush2: 14 bytes to sd 14
connection_get(14): got connid=1000
connection_read(14): checking for input on id=1000
ber_get_next
ber_get_next: tag 0x30 len 5 contents:
op tag 0x42, time 1273546410
ber_get_next
conn=1000 op=2 do_unbind
connection_close: conn=1000 sd=14

$ ldapsearch -H ldapi:/// -D "cn=admin,dc=example,dc=com" -b "" -W
Enter LDAP Password: 
ldap_bind: Invalid credentials (49)

slap_listener_activate(9): 
>>> slap_listener(ldapi:///)
connection_get(14): got connid=1001
connection_read(14): checking for input on id=1001
ber_get_next
ber_get_next: tag 0x30 len 44 contents:
op tag 0x60, time 1273546420
ber_get_next
conn=1001 op=0 do_bind
ber_scanf fmt ({imt) ber:
ber_scanf fmt (m}) ber:
>>> dnPrettyNormal: <cn=admin,dc=example,dc=com>
<<< dnPrettyNormal: <cn=admin,dc=example,dc=com>, <cn=admin,dc=example,dc=com>
do_bind: version=3 dn="cn=admin,dc=example,dc=com" method=128
send_ldap_result: conn=1001 op=0 p=3
send_ldap_response: msgid=1 tag=97 err=49
ber_flush2: 14 bytes to sd 14
connection_get(14): got connid=1001
connection_read(14): checking for input on id=1001
ber_get_next
ber_get_next on fd 14 failed errno=0 (Success)
connection_close: conn=1001 sd=14
connection_read(14): no connection!
connection_read(14): no connection!

$ ldapsearch -H ldap:/// -D "cn=admin,dc=example,dc=com" -b "" -W
Enter LDAP Password: 
ldap_bind: Invalid credentials (49)

slap_listener_activate(8): 
>>> slap_listener(ldap:///)
connection_get(14): got connid=1002
connection_read(14): checking for input on id=1002
ber_get_next
ber_get_next: tag 0x30 len 44 contents:
op tag 0x60, time 1273546425
ber_get_next
conn=1002 op=0 do_bind
ber_scanf fmt ({imt) ber:
ber_scanf fmt (m}) ber:
>>> dnPrettyNormal: <cn=admin,dc=example,dc=com>
<<< dnPrettyNormal: <cn=admin,dc=example,dc=com>, <cn=admin,dc=example,dc=com>
do_bind: version=3 dn="cn=admin,dc=example,dc=com" method=128
send_ldap_result: conn=1002 op=0 p=3
send_ldap_response: msgid=1 tag=97 err=49
ber_flush2: 14 bytes to sd 14
connection_get(14): got connid=1002
connection_read(14): checking for input on id=1002
ber_get_next
ber_get_next on fd 14 failed errno=0 (Success)
connection_close: conn=1002 sd=14