Re: [389-users] Random failures on startTLS

[Aaron Hagopian <airhead1@xxxxxxxxx>]

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@xxxxxxxxx> 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@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

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

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