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

[hyc@symas.com]

online@mark.ziesemer.com wrote:
> 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 also happens when the connection manager queues up a thread to handle a 
"socket is readable" event on a socket that's in the process of closing. 
Pretty much unavoidable, when a lot of threads are active. I don't see this as 
a high enough priority to warrant fixing.

> 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
>
>


-- 
   -- Howard Chu
   CTO, Symas Corp.           http://www.symas.com
   Director, Highland Sun     http://highlandsun.com/hyc/
   Chief Architect, OpenLDAP  http://www.openldap.org/project/