[Date Prev][Date Next]
[Chronological]
[Thread]
[Top]
Re: (ITS#6548) Many "connection_read(): no connection!" warnings when using ldapi:/// and a bind DN (no external authentication)
- To: openldap-its@OpenLDAP.org
- Subject: Re: (ITS#6548) Many "connection_read(): no connection!" warnings when using ldapi:/// and a bind DN (no external authentication)
- From: hyc@symas.com
- Date: Sun, 13 Jun 2010 22:20:49 GMT
- Auto-submitted: auto-generated (OpenLDAP-ITS)
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/