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



--00c09f76b87ebad978048667feb6
Content-Type: text/plain; charset=ISO-8859-1

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

--00c09f76b87ebad978048667feb6
Content-Type: text/html; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable

<div class=3D"gmail_quote">On Wed, May 12, 2010 at 10:05 AM, Howard Chu <sp=
an dir=3D"ltr">&lt;<a href=3D"mailto:hyc@symas.com";>hyc@symas.com</a>&gt;</=
span> wrote:<br><blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt =
0pt 0.8ex; border-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">
<a href=3D"mailto:online@mark.ziesemer.com"; target=3D"_blank">online@mark.z=
iesemer.com</a> wrote:<br>
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">
Full_Name: Mark A. Ziesemer<br>
Version: 2.4.21<br>
OS: Ubuntu Linux 10.04<br>
URL: <a href=3D"ftp://ftp.openldap.org/incoming/"; target=3D"_blank">ftp://f=
tp.openldap.org/incoming/</a><br>
Submission from: (NULL) (2001:470:1f11:3ae:4d6d:3d3e:faa6:ee3d)<br>
<br>
<br>
Many &quot;connection_read(): no connection!&quot; warnings are written to =
/var/log/debug<br>
and /var/log/syslog by slapd. =A0As stated at<br>
<a href=3D"http://www.openldap.org/lists/openldap-software/200811/msg00079.=
html" target=3D"_blank">http://www.openldap.org/lists/openldap-software/200=
811/msg00079.html</a> , this is<br>
apparently not a problem with slapd, but a client that is disconnecting wit=
hout<br>
first unbinding.<br>
</blockquote>
<br>
This also happens when the connection manager queues up a thread to handle =
a &quot;socket is readable&quot; event on a socket that&#39;s in the proces=
s of closing. Pretty much unavoidable, when a lot of threads are active. I =
don&#39;t see this as a high enough priority to warrant fixing.<br>
</blockquote><div><br>This was not happening under a high load, but with on=
ly 1-2 connections active.<br><br>I might not have focused on it enough in =
the original report, but isn&#39;t this looking like it is probably an issu=
e with the libldap client library (provided by OpenLDAP), rather than the s=
lapd daemon?=A0 Looking at the provided logs, it appears that no do_unbind =
request is received (not sent by the client) when using ldapi:/// with a bi=
nd DN.<br>
<br>If it can&#39;t / won&#39;t be fixed, can the logging of the &quot;conn=
ection_read(): no connection!&quot; event in slapd at least be demoted to a=
 lower level so that it doesn&#39;t fill the default logging output, withou=
t having to change the overall configured logging level and potentially mis=
sing other logged events that do require attention?<br>
=A0<br>
</div><blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex;=
 border-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;"><blockquote=
 class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; border-left: 1px=
 solid rgb(204, 204, 204); padding-left: 1ex;">

This appears to be an issue with the libldap client library provided by Ope=
nLDAP<br>
itself (2.4.21), and not the slapd daemon.<br>
<br>
Issue is reproducible even by just using &quot;ldapsearch -H ldapi:///&quot=
;, but only if<br>
a bind DN is specified (-D) and external authentication is not used.<br>
<br>
Running slapd with logging enabled (-d 8) shows the following 3 sequences -=
<br>
ldapsearch command followed by the slapd logs. =A0Note that the<br>
&quot;connection_read(): no connection!&quot; is only visible on the middle=
 pair.<br>
<br>
<br>
$ ldapsearch -LLL -Y EXTERNAL -H ldapi:/// -b &quot;&quot;<br>
SASL/EXTERNAL authentication started<br>
SASL username: gidNumber=3D0+uidNumber=3D0,cn=3Dpeercred,cn=3Dexternal,cn=
=3Dauth<br>
SASL SSF: 0<br>
No such object (32)<br>
<br>
slap_listener_activate(9):<br>
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;"><blockquote class=
=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid=
 rgb(204, 204, 204); padding-left: 1ex;">
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">
slap_listener(ldapi:///)<br>
</blockquote></blockquote></blockquote>
connection_get(14): got connid=3D1000<br>
connection_read(14): checking for input on id=3D1000<br>
ber_get_next<br>
ber_get_next: tag 0x30 len 24 contents:<br>
op tag 0x60, time 1273546410<br>
ber_get_next<br>
conn=3D1000 op=3D0 do_bind<br>
ber_scanf fmt ({imt) ber:<br>
ber_scanf fmt ({m) ber:<br>
ber_scanf fmt (m) ber:<br>
ber_scanf fmt (}}) ber:<br>
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;"><blockquote class=
=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid=
 rgb(204, 204, 204); padding-left: 1ex;">
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">
dnPrettyNormal:&lt;&gt;<br>
</blockquote></blockquote></blockquote>
&lt;&lt;&lt; =A0dnPrettyNormal:&lt;&gt;,&lt;&gt;<br>
do_bind: dn () SASL mech EXTERNAL<br>
=3D=3D&gt;slap_sasl2dn: converting SASL name<br>
gidNumber=3D0+uidNumber=3D0,cn=3Dpeercred,cn=3Dexternal,cn=3Dauth to a DN<b=
r>
&lt;=3D=3Dslap_sasl2dn: Converted SASL name to&lt;nothing&gt;<br>
SASL Authorize [conn=3D1000]: =A0proxy authorization allowed authzDN=3D&quo=
t;&quot;<br>
send_ldap_sasl: err=3D0 len=3D-1<br>
do_bind: SASL/EXTERNAL bind:<br>
dn=3D&quot;gidNumber=3D0+uidNumber=3D0,cn=3Dpeercred,cn=3Dexternal,cn=3Daut=
h&quot; sasl_ssf=3D0<br>
send_ldap_response: msgid=3D1 tag=3D97 err=3D0<br>
ber_flush2: 14 bytes to sd 14<br>
&lt;=3D=3D slap_sasl_bind: rc=3D0<br>
connection_get(14): got connid=3D1000<br>
connection_read(14): checking for input on id=3D1000<br>
ber_get_next<br>
ber_get_next: tag 0x30 len 37 contents:<br>
op tag 0x63, time 1273546410<br>
ber_get_next<br>
conn=3D1000 op=3D1 do_search<br>
ber_scanf fmt ({miiiib) ber:<br>
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;"><blockquote class=
=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid=
 rgb(204, 204, 204); padding-left: 1ex;">
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">
dnPrettyNormal:&lt;&gt;<br>
</blockquote></blockquote></blockquote>
&lt;&lt;&lt; =A0dnPrettyNormal:&lt;&gt;,&lt;&gt;<br>
ber_scanf fmt (m) ber:<br>
ber_scanf fmt ({M}}) ber:<br>
send_ldap_result: conn=3D1000 op=3D1 p=3D3<br>
send_ldap_response: msgid=3D2 tag=3D101 err=3D32<br>
ber_flush2: 14 bytes to sd 14<br>
connection_get(14): got connid=3D1000<br>
connection_read(14): checking for input on id=3D1000<br>
ber_get_next<br>
ber_get_next: tag 0x30 len 5 contents:<br>
op tag 0x42, time 1273546410<br>
ber_get_next<br>
conn=3D1000 op=3D2 do_unbind<br>
connection_close: conn=3D1000 sd=3D14<br>
<br>
$ ldapsearch -H ldapi:/// -D &quot;cn=3Dadmin,dc=3Dexample,dc=3Dcom&quot; -=
b &quot;&quot; -W<br>
Enter LDAP Password:<br>
ldap_bind: Invalid credentials (49)<br>
<br>
slap_listener_activate(9):<br>
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;"><blockquote class=
=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid=
 rgb(204, 204, 204); padding-left: 1ex;">
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">
slap_listener(ldapi:///)<br>
</blockquote></blockquote></blockquote>
connection_get(14): got connid=3D1001<br>
connection_read(14): checking for input on id=3D1001<br>
ber_get_next<br>
ber_get_next: tag 0x30 len 44 contents:<br>
op tag 0x60, time 1273546420<br>
ber_get_next<br>
conn=3D1001 op=3D0 do_bind<br>
ber_scanf fmt ({imt) ber:<br>
ber_scanf fmt (m}) ber:<br>
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;"><blockquote class=
=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid=
 rgb(204, 204, 204); padding-left: 1ex;">
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">
dnPrettyNormal:&lt;cn=3Dadmin,dc=3Dexample,dc=3Dcom&gt;<br>
</blockquote></blockquote></blockquote>
&lt;&lt;&lt; =A0dnPrettyNormal:&lt;cn=3Dadmin,dc=3Dexample,dc=3Dcom&gt;,&lt=
;cn=3Dadmin,dc=3Dexample,dc=3Dcom&gt;<br>
do_bind: version=3D3 dn=3D&quot;cn=3Dadmin,dc=3Dexample,dc=3Dcom&quot; meth=
od=3D128<br>
send_ldap_result: conn=3D1001 op=3D0 p=3D3<br>
send_ldap_response: msgid=3D1 tag=3D97 err=3D49<br>
ber_flush2: 14 bytes to sd 14<br>
connection_get(14): got connid=3D1001<br>
connection_read(14): checking for input on id=3D1001<br>
ber_get_next<br>
ber_get_next on fd 14 failed errno=3D0 (Success)<br>
connection_close: conn=3D1001 sd=3D14<br>
connection_read(14): no connection!<br>
connection_read(14): no connection!<br>
<br>
$ ldapsearch -H ldap:/// -D &quot;cn=3Dadmin,dc=3Dexample,dc=3Dcom&quot; -b=
 &quot;&quot; -W<br>
Enter LDAP Password:<br>
ldap_bind: Invalid credentials (49)<br>
<br>
slap_listener_activate(8):<br>
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;"><blockquote class=
=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid=
 rgb(204, 204, 204); padding-left: 1ex;">
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">
slap_listener(ldap:///)<br>
</blockquote></blockquote></blockquote>
connection_get(14): got connid=3D1002<br>
connection_read(14): checking for input on id=3D1002<br>
ber_get_next<br>
ber_get_next: tag 0x30 len 44 contents:<br>
op tag 0x60, time 1273546425<br>
ber_get_next<br>
conn=3D1002 op=3D0 do_bind<br>
ber_scanf fmt ({imt) ber:<br>
ber_scanf fmt (m}) ber:<br>
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;"><blockquote class=
=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; border-left: 1px solid=
 rgb(204, 204, 204); padding-left: 1ex;">
<blockquote class=3D"gmail_quote" style=3D"margin: 0pt 0pt 0pt 0.8ex; borde=
r-left: 1px solid rgb(204, 204, 204); padding-left: 1ex;">
dnPrettyNormal:&lt;cn=3Dadmin,dc=3Dexample,dc=3Dcom&gt;<br>
</blockquote></blockquote></blockquote>
&lt;&lt;&lt; =A0dnPrettyNormal:&lt;cn=3Dadmin,dc=3Dexample,dc=3Dcom&gt;,&lt=
;cn=3Dadmin,dc=3Dexample,dc=3Dcom&gt;<br>
do_bind: version=3D3 dn=3D&quot;cn=3Dadmin,dc=3Dexample,dc=3Dcom&quot; meth=
od=3D128<br>
send_ldap_result: conn=3D1002 op=3D0 p=3D3<br>
send_ldap_response: msgid=3D1 tag=3D97 err=3D49<br>
ber_flush2: 14 bytes to sd 14<br>
connection_get(14): got connid=3D1002<br>
connection_read(14): checking for input on id=3D1002<br>
ber_get_next<br>
ber_get_next on fd 14 failed errno=3D0 (Success)<br>
connection_close: conn=3D1002 sd=3D14<br>
<br>
<br>
</blockquote>
<br>
<br>
-- <br>
 =A0-- Howard Chu<br>
 =A0CTO, Symas Corp. =A0 =A0 =A0 =A0 =A0 <a href=3D"http://www.symas.com"; t=
arget=3D"_blank">http://www.symas.com</a><br>
 =A0Director, Highland Sun =A0 =A0 <a href=3D"http://highlandsun.com/hyc/"; =
target=3D"_blank">http://highlandsun.com/hyc/</a><br>
 =A0Chief Architect, OpenLDAP =A0<a href=3D"http://www.openldap.org/project=
/" target=3D"_blank">http://www.openldap.org/project/</a><br>
</blockquote></div><br>--<br>Mark A. Ziesemer<br><a href=3D"http://www.zies=
emer.com">www.ziesemer.com</a><br>
<br>

--00c09f76b87ebad978048667feb6--