Re: [389-users] Random failures on startTLS

[Aaron Hagopian <airhead1@xxxxxxxxx>]

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@xxxxxxxxxx> 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@xxxxxxxxxxxxxxxxxxxxxxx
> https://admin.fedoraproject.org/mailman/listinfo/389-users

--
389 users mailing list
389-users@xxxxxxxxxxxxxxxxxxxxxxx
https://admin.fedoraproject.org/mailman/listinfo/389-users

--
389 users mailing list
389-users@xxxxxxxxxxxxxxxxxxxxxxx
https://admin.fedoraproject.org/mailman/listinfo/389-users