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
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/
On Wed, May 12, 2010 at 10:05 AM, Howard Chu <hyc@symas.com> wrote: > 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? > 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/ > -- Mark A. Ziesemer www.ziesemer.com
changed state Open to Closed
Hi! Do we have any chance that this bug will be rectified recently? I believe a communication issue like this should do taken as being important. It makes the log check a huge pain, and I don't think ,,hiding'' the log is a real solution. Thank You, Gergely Kral
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 -- -- Howard Chu CTO, Symas Corp. http://www.symas.com Director, Highland Sun http://highlandsun.com/hyc/ Chief Architect, OpenLDAP http://www.openldap.org/project/
On Sun, Jun 13, 2010 at 5:20 PM, Howard Chu <hyc@symas.com> wrote: > 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. > As stated by one of the other OpenLDAP engineers in the above link, the recommendation was to "fix whatever client is disconnecting without unbinding". In this case, the client is the OpenLDAP libraries. Please at least re-consider for fixing, even in a "help wanted" or "pending" status, rather than just closing. Either the client library should be fixed to send an unbind before disconnecting in all circumstances (i.e. ldapi:/// as well as ldap:///), or it should be confirmed and documented that the unbind is not necessary, in which case the server should be fixed to not output the "connection_read(): no connection!" events at the default logging level. I don't see messages filling the log. I don't see any issue here at all. > I'm not the only one seeing this. My link to the OpenLDAP mailing list above, as well as Gergely's inquiry into this ITS are 2 directly related occurrences observed by others. 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. While this may be true, in any production environment, you can almost be guaranteed that there will be login attempts with invalid credentials - even just due to users mistyping their password on occasion, using CAPS lock, etc. Again, the log entry should either be suppressed at the default logging level (preferred), or at least re-worded to something more meaningful, e.g. "Received invalid login attempt; disconnecting client". However, even then, this should be made to work the same regardless of protocol used for consistency. This may not be a high priority or interesting issue to fix, but please don't simply ignore what seems to be a very reasonable request. If this issue is not addressed, the effect becomes training other users and admins to ignore the logs if they regularly contain trivial updates at the default level - which I hope we can agree is not a good practice. 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/ -- Mark A. Ziesemer www.ziesemer.com
Hello folks, I've never used a jitterbug, so I hope this email goes to the right place and doesn't spam up the system. I've been experiencing the same problem as Mark. I use OpenLDAP 2.4.23 packaged in Debian. I have a few processes that connect to ldapi:/// socket and do anonymous binds, there are one or two "no connection!" log messages each time these processes run. None of my remote connections produce these messages. This happens at very low volume, when slapd is idle. When slapd gets more utilization, maybe one or two requests per second, the noise stops. I've spent a few hours looking at the source of OpenLDAP slapd and libldap, also Perl Net::LDAP (the client most often generating these log entries on my system). The source code for OpenLDAP looks very clean, but I'm no C expert, and I'm lost in the asynchronous nature of the connection.c. FYI, Net::LDAP doesn't use libldap - it's all Perl, no native libraries. After hundreds of tests and various olcLogLevel settings I've finally stumbled upon something that solves the problem... usleep(1); I know this has to be the lamest bug report ever, but it works, please bear with me. The first thing that tipped me to try 'usleep' was that with olcLogLevel set to "trace packets args conns stats", I get the following output: connection_get(14) connection_get(14): got connid=1007 connection_read(14): checking for input on id=1007 * op tag 0x42, time 1283917507 * ber_get_next on fd 14 failed errno=0 (Success) connection_read(14): input error=-2 id=1007, closing. connection_closing: readying conn=1007 sd=14 for close connection_close: deferring conn=1007 sd=14 conn=1007 op=2 do_unbind conn=1007 op=2 UNBIND connection_resched: attempting closing conn=1007 sd=14 connection_close: conn=1007 sd=14 daemon: removing 14 conn=1007 fd=14 closed daemon: activity on 1 descriptor daemon: activity on: daemon: epoll: listen=8 active_threads=0 tvp=zero daemon: epoll: listen=9 active_threads=0 tvp=zero connection_get(14) connection_get(14): connection not used connection_get(14) connection_get(14): connection not used connection_read(14): no connection! connection_read(14) error connection_read(14): no connection! The two lines I marked with asterisks are the output from the connection_input function, "op tag 0x42..." should be printed after "ber_get_next on fd 14 failed...", but it's not - so evidently this function is reentrant, the input loop is processing both the UNBIND request and the client closing the socket at the same time, and unfortunately the socket close processing came first so that connection_input thread tears down the connection. Now with the perl scripts I tried adding a microsecond sleep just after they unbind and before they exit, it worked - haven't seen any "no connection!" logs from them for hours. As for the libldap-client and ldapsearch commands, everytime I executed a simple 'ldapsearch -x -H ldapi:///' I'd get two "no connection!" log messages. I tried the same braindead usleep(1) solution and it worked. The following is the diff of what I changed to libldap, ldap_free_connection function in request.c: if ( unbind ) { ldap_send_unbind( ld, lc->lconn_sb, NULL, NULL ); + Debug( LDAP_DEBUG_TRACE, + "ldap_free_connection: sleeping after unbind\n", + 0, 0, 0 ); + usleep(1); } Here's the last bits of output from ldapsearch with -d3 after applying this brutal "fix" to libldap: ldap_free_connection 1 1 ldap_send_unbind ber_flush2: 7 bytes to sd 3 ldap_write: want=7, written=7 0000: 30 05 02 01 03 42 00 0....B. ldap_free_connection: sleeping after unbind ldap_free_connection: actually freed Notice the bytes getting flushed between unbind, my dumb sleep, and "actually freed". Without the sleep it seems slapd may process the close before the unbind. -- Gerald Turner Email: gturner@unzane.com JID: gturner@jabber.unzane.com GPG: 0xFA8CD6D5 21D9 B2E8 7FE7 F19E 5F7D 4D0C 3FA0 810F FA8C D6D5
changed notes changed state Closed to Test moved from Incoming to Software Bugs
changed notes changed state Test to Release
changed notes changed state Release to Closed
fixed in master fixed in RE24