Mark A. Ziesemer wrote:
On Wed, May 12, 2010 at 10:05 AM, Howard Chu <hyc@symas.com mailto:hyc@symas.com> wrote:
online@mark.ziesemer.com <mailto: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 was not happening under a high load, but with only 1-2 connections active.
I might not have focused on it enough in the original report, but isn't this looking like it is probably an issue with the libldap client library (provided by OpenLDAP), rather than the slapd daemon? Looking at the provided logs, it appears that no do_unbind request is received (not sent by the client) when using ldapi:/// with a bind DN.
If it can't / won't be fixed, can the logging of the "connection_read(): no connection!" event in slapd at least be demoted to a lower level so that it doesn't fill the default logging output, without having to change the overall configured logging level and potentially missing other logged events that do require attention?
"Fixing" libldap, if there's even a bug there, obviously won't help with other clients using non-OpenLDAP libraries. At any rate, there's nothing that requires an Unbind request to be sent, so there's no bug here.
I don't see messages filling the log. I don't see any issue here at all.
I was only able to reproduce this by performing a Bind with invalid credentials. In the case with correct credentials, there were no extraneous messages. If you're seeing a lot of these cases, then you should think about why you're getting a lot of Binds with invalid passwords. Fix the problem, not the symptom. This ITS will be closed.
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