[389-users] Random failures on startTLS
Aaron Hagopian
airhead1 at gmail.com
Wed Apr 14 20:07:59 UTC 2010
Also I'm attaching another block where that error message happened. This
time the ABANDON is not logged right between the startTLS stuff but they are
right before it.
On Wed, Apr 14, 2010 at 2:42 PM, Aaron Hagopian <airhead1 at gmail.com> wrote:
> Do you need something to generate those ABANDON requests too or just a
> simple program that does the startTLS? I'm sure its something in our code
> that's creating the ABANDON requests but not sure exactly what.
>
>
> On Wed, Apr 14, 2010 at 12:41 PM, Rich Megginson <rmeggins at redhat.com>wrote:
>
>> Aaron Hagopian wrote:
>> >
>> > What is the platform?
>> >
>> >
>> > Linux CentOS 5.4 i386
>> >
>> > What is the 389 version?
>> >
>> > rpm -qi 389-ds-base
>> >
>> >
>> > Name : 389-ds-base Relocations: (not
>> relocatable)
>> > Version : 1.2.5 Vendor: Fedora Project
>> > Release : 1.el5 Build Date: Tue 12 Jan
>> > 2010 02:35:50 PM CST
>> > Install Date: Wed 17 Mar 2010 03:54:26 PM CDT Build Host:
>> > x86-04.phx2.fedoraproject.org <http://x86-04.phx2.fedoraproject.org>
>> > Group : System Environment/Daemons Source RPM:
>> > 389-ds-base-1.2.5-1.el5.src.rpm
>> > Size : 5216698 License: GPLv2 with
>> > exceptions
>> > Signature : DSA/SHA1, Wed 13 Jan 2010 11:33:44 AM CST, Key ID
>> > 119cc036217521f6
>> > Packager : Fedora Project
>> > URL : http://port389.org/
>> > Summary : 389 Directory Server (base)
>> > Description :
>> > 389 Directory Server is an LDAPv3 compliant server. The base package
>> > includes
>> > the LDAP server and command line utilities for server administration.
>> >
>> >
>> > What is the client? JNDI?
>> >
>> >
>> > Yes JNDI. Here is a code snippet of what is happening:
>> >
>> > ctx = new InitialLdapContext(env, null);
>> >
>> > // Changing the connection to use SSL/TLS
>> > tls = (StartTlsResponse)ctx.extendedOperation(new
>> > StartTlsRequest());
>> > tlsSession = tls.negotiate();
>> >
>> > PasswordChangeRequest req = new PasswordChangeRequest(dn,
>> > oldPassword, newPassword);
>> > PasswordChangeResponse resp =
>> > (PasswordChangeResponse)ctx.extendedOperation(req);
>> >
>> >
>> > The log item ABANDON targetop=NOTFOUND
>> > msgid=11 is interesting
>> >
>> >
>> > I thought this wasn't that interesting because it was a different
>> > connection there were actually a few of those so if it helps, here are
>> > the rest related to that connection around the same time:
>> >
>> > 14/Apr/2010:08:27:55 -0500] conn=3007 fd=65 slot=65 connection
>> > from 127.0.0.1 to 127.0.0.1
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=0 BIND
>> > dn="cn=Manager,dc=hranet,dc=org" method=128 version=3
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=0 RESULT err=0 tag=97
>> > nentries=0 etime=0 dn="cn=manager,dc=hranet,dc=org"
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=1 SRCH
>> > base="dc=hranet,dc=org" scope=2
>> > filter="(&(uid=microprocessor)(objectClass=user))" attrs=ALL
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=1 RESULT err=0 tag=101
>> > nentries=0 etime=0
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=2 ADD
>> > dn="uid=microprocessor,ou=employees,ou=people,dc=hranet,dc=org"
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=2 RESULT err=0 tag=105
>> > nentries=0 etime=0 csn=4bc5c2db000000170000
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=3 MOD
>> > dn="uid=microprocessor,ou=employees,ou=people,dc=hranet,dc=org"
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=3 RESULT err=0 tag=103
>> > nentries=0 etime=0 csn=4bc5c2db000100170000
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=4 SRCH
>> > base="dc=hranet,dc=org" scope=2 filter="(uid=microprocessor)"
>> > attrs=ALL
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=4 RESULT err=0 tag=101
>> > nentries=1 etime=0
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=5 ABANDON
>> > targetop=NOTFOUND msgid=5
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=6 SRCH
>> > base="dc=hranet,dc=org" scope=2
>> > filter="(&(uid=6224)(objectClass=user))" attrs=ALL
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=8 RESULT err=0 tag=101
>> > nentries=1 etime=0
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=9 ABANDON
>> > targetop=NOTFOUND msgid=9
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=10 SRCH
>> > base="dc=hranet,dc=org" scope=2 filter="(uid=microprocessor)"
>> > attrs=ALL
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=10 RESULT err=0 tag=101
>> > nentries=1 etime=0
>> > [14/Apr/2010:08:27:55 -0500] conn=3008 fd=66 slot=66 connection
>> > from 127.0.0.1 to 127.0.0.1
>> > [14/Apr/2010:08:27:55 -0500] conn=3007 op=11 ABANDON
>> > targetop=NOTFOUND msgid=11
>> > [14/Apr/2010:08:27:55 -0500] conn=3008 op=0 BIND
>> > dn="cn=Manager,dc=hranet,dc=org" method=128 version=3
>> > [14/Apr/2010:08:27:55 -0500] conn=3008 op=1 EXT
>> > oid="1.3.6.1.4.1.1466.20037" name="startTLS"
>> > [14/Apr/2010:08:27:55 -0500] conn=3008 op=1 RESULT err=1 tag=120
>> > nentries=0 etime=0
>> > [14/Apr/2010:08:27:55 -0500] conn=3008 op=2 UNBIND
>> > [14/Apr/2010:08:27:55 -0500] conn=3008 op=2 fd=66 closed - U1
>> > [14/Apr/2010:08:27:55 -0500] conn=3008 op=0 RESULT err=0 tag=97
>> > nentries=0 etime=0 dn="cn=manager,dc=hranet,dc=org"
>> > [14/Apr/2010:08:28:02 -0500] conn=3003 op=17 UNBIND
>> > [14/Apr/2010:08:28:02 -0500] conn=3003 op=17 fd=67 closed - U1
>> > [14/Apr/2010:08:28:02 -0500] conn=3007 op=12 SRCH
>> > base="dc=hranet,dc=org" scope=2 filter="(uid=peter)" attrs=ALL
>> > [14/Apr/2010:08:28:02 -0500] conn=3007 op=12 RESULT err=0 tag=101
>> > nentries=1 etime=0
>> >
>> >
>> >
>> > Thanks,
>> >
>> > Aaron Hagopian
>> Can you provide a small test JNDI program that reproduces this problem?
>> I believe it is a bug in the server, and has something to do with the
>> ABANDON requests not being cleaned up properly, even though the ops are
>> for a different connection.
>> > ------------------------------------------------------------------------
>> >
>> > --
>> > 389 users mailing list
>> > 389-users at lists.fedoraproject.org
>> > https://admin.fedoraproject.org/mailman/listinfo/389-users
>>
>> --
>> 389 users mailing list
>> 389-users at lists.fedoraproject.org
>> https://admin.fedoraproject.org/mailman/listinfo/389-users
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.fedoraproject.org/pipermail/389-users/attachments/20100414/3ff9a300/attachment.html>
-------------- next part --------------
[14/Apr/2010:07:03:55 -0500] conn=2958 op=5 UNBIND
[14/Apr/2010:07:03:55 -0500] conn=2958 op=5 fd=66 closed - U1
[14/Apr/2010:07:03:55 -0500] conn=2960 op=2 SRCH base="dc=hranet,dc=org" scope=2 filter="(&(uid=chowder)(objectClass=user))" attrs=ALL
[14/Apr/2010:07:03:55 -0500] conn=2960 op=2 RESULT err=0 tag=101 nentries=0 etime=0
[14/Apr/2010:07:03:55 -0500] conn=2960 op=3 ADD dn="uid=chowder,ou=employees,ou=people,dc=hranet,dc=org"
[14/Apr/2010:07:03:55 -0500] conn=2960 op=3 RESULT err=0 tag=105 nentries=0 etime=0 csn=4bc5af2b000000170000
[14/Apr/2010:07:03:55 -0500] conn=2960 op=4 MOD dn="uid=chowder,ou=employees,ou=people,dc=hranet,dc=org"
[14/Apr/2010:07:03:55 -0500] conn=2960 op=4 RESULT err=0 tag=103 nentries=0 etime=0 csn=4bc5af2b000200170000
[14/Apr/2010:07:03:55 -0500] conn=2960 op=5 SRCH base="dc=hranet,dc=org" scope=2 filter="(uid=chowder)" attrs=ALL
[14/Apr/2010:07:03:55 -0500] conn=2960 op=5 RESULT err=0 tag=101 nentries=1 etime=0
[14/Apr/2010:07:03:55 -0500] conn=2960 op=6 ABANDON targetop=NOTFOUND msgid=6
[14/Apr/2010:07:03:55 -0500] conn=2960 op=7 SRCH base="dc=hranet,dc=org" scope=2 filter="(&(uid=6218)(objectClass=user))" attrs=ALL
[14/Apr/2010:07:03:55 -0500] conn=2960 op=7 RESULT err=0 tag=101 nentries=1 etime=0
[14/Apr/2010:07:03:55 -0500] conn=2960 op=8 ABANDON targetop=NOTFOUND msgid=8
[14/Apr/2010:07:03:55 -0500] conn=2960 op=9 SRCH base="dc=hranet,dc=org" scope=2 filter="(&(uid=6218)(objectClass=user))" attrs=ALL
[14/Apr/2010:07:03:55 -0500] conn=2960 op=9 RESULT err=0 tag=101 nentries=1 etime=0
[14/Apr/2010:07:03:55 -0500] conn=2960 op=10 SRCH base="dc=hranet,dc=org" scope=2 filter="(uid=chowder)" attrs=ALL
[14/Apr/2010:07:03:55 -0500] conn=2960 op=10 RESULT err=0 tag=101 nentries=1 etime=0
[14/Apr/2010:07:03:55 -0500] conn=2961 fd=65 slot=65 connection from 127.0.0.1 to 127.0.0.1
[14/Apr/2010:07:03:55 -0500] conn=2961 op=0 BIND dn="cn=Manager,dc=hranet,dc=org" method=128 version=3
[14/Apr/2010:07:03:55 -0500] conn=2961 op=1 EXT oid="1.3.6.1.4.1.1466.20037" name="startTLS"
[14/Apr/2010:07:03:55 -0500] conn=2961 op=1 RESULT err=1 tag=120 nentries=0 etime=0
[14/Apr/2010:07:03:55 -0500] conn=2961 op=2 UNBIND
[14/Apr/2010:07:03:55 -0500] conn=2961 op=2 fd=65 closed - U1
[14/Apr/2010:07:03:55 -0500] conn=2961 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=manager,dc=hranet,dc=org"
More information about the 389-users
mailing list