Random failures on startTLS

List overview All Threads
Download

newer

older

Memory alloc error

Error when doing "add" and...

Aaron Hagopian

14 Apr 2010 14 Apr '10

11:56 a.m.

I'm having an issue that seems somewhat random or maybe at least load related when trying to change or reset a user's password. We have some java code that creates an unencrypted connection, start's a TLS session, then sends a password change extended operation. This code seems to work fine in regular testing but sometimes randomly, the password change requests fail due to an odd error message

When the failure occurs the error message received from the server is:

[LDAP: error code 1 - Other operations are still pending on the connection.]

Which made me think at first it was using a pooled connection but I have verified that it is not using a pooled connection. The connection is created new then the StartTLS request is made. Looking at the access log for one of these failed connections I see this (3008 is the conn):

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

Which looks like the startTLS failed but why would there be other operations still pending on the connection if that is the only operation that has even been requested. Is it possible the startTLS hasn't finished when the password request is being asked? A successful operation looks like this in the log:

[14/Apr/2010:08:31:05 -0500] conn=3016 fd=66 slot=66 connection from 127.0.0.1 to 127.0.0.1 [14/Apr/2010:08:31:05 -0500] conn=3016 op=0 BIND dn="cn=Manager,dc=hranet,dc=org" method=128 version=3 [14/Apr/2010:08:31:05 -0500] conn=3016 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="cn=manager,dc=hranet,dc=org" [14/Apr/2010:08:31:05 -0500] conn=3016 op=1 EXT oid="1.3.6.1.4.1.1466.20037" name="startTLS" [14/Apr/2010:08:31:05 -0500] conn=3016 op=1 RESULT err=0 tag=120 nentries=0 etime=0 [14/Apr/2010:08:31:05 -0500] conn=3016 SSL 128-bit RC4 [14/Apr/2010:08:31:05 -0500] conn=3016 op=2 BIND dn="uid=lyoung,ou=clients,ou=people,dc=hranet,dc=org" method=128 version=3 [14/Apr/2010:08:31:05 -0500] conn=3016 op=2 RESULT err=0 tag=97 nentries=0 etime=0 dn="uid=lyoung,ou=clients,ou=people,dc=hranet,dc=org" [14/Apr/2010:08:31:05 -0500] conn=3016 op=3 EXT oid="1.3.6.1.4.1.4203.1.11.1" name="passwd_modify_extop" [14/Apr/2010:08:31:05 -0500] conn=3016 op=3 RESULT err=19 tag=120 nentries=0 etime=0 [14/Apr/2010:08:31:05 -0500] conn=3016 op=4 UNBIND [14/Apr/2010:08:31:05 -0500] conn=3016 op=4 fd=66 closed - U1

Is this just a bug with directory server? Any thoughts or ideas are welcomed.

Thanks,

Aaron Hagopian

Attachments:

attachment.html (text/html — 4.1 KB)

Show replies by date

Rich Megginson

14 Apr 14 Apr

noon

Aaron Hagopian wrote:

...

I'm having an issue that seems somewhat random or maybe at least load related when trying to change or reset a user's password. We have some java code that creates an unencrypted connection, start's a TLS session, then sends a password change extended operation. This code seems to work fine in regular testing but sometimes randomly, the password change requests fail due to an odd error message

When the failure occurs the error message received from the server is:
[LDAP: error code 1 - Other operations are still pending on the
connection.]
Which made me think at first it was using a pooled connection but I have verified that it is not using a pooled connection. The connection is created new then the StartTLS request is made. Looking at the access log for one of these failed connections I see this (3008 is the conn):
[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"
Which looks like the startTLS failed but why would there be other operations still pending on the connection if that is the only operation that has even been requested. Is it possible the startTLS hasn't finished when the password request is being asked? A successful operation looks like this in the log:
[14/Apr/2010:08:31:05 -0500] conn=3016 fd=66 slot=66 connection
from 127.0.0.1 to 127.0.0.1
[14/Apr/2010:08:31:05 -0500] conn=3016 op=0 BIND
dn="cn=Manager,dc=hranet,dc=org" method=128 version=3
[14/Apr/2010:08:31:05 -0500] conn=3016 op=0 RESULT err=0 tag=97
nentries=0 etime=0 dn="cn=manager,dc=hranet,dc=org"
[14/Apr/2010:08:31:05 -0500] conn=3016 op=1 EXT
oid="1.3.6.1.4.1.1466.20037" name="startTLS"
[14/Apr/2010:08:31:05 -0500] conn=3016 op=1 RESULT err=0 tag=120
nentries=0 etime=0
[14/Apr/2010:08:31:05 -0500] conn=3016 SSL 128-bit RC4
[14/Apr/2010:08:31:05 -0500] conn=3016 op=2 BIND
dn="uid=lyoung,ou=clients,ou=people,dc=hranet,dc=org" method=128
version=3
[14/Apr/2010:08:31:05 -0500] conn=3016 op=2 RESULT err=0 tag=97
nentries=0 etime=0
dn="uid=lyoung,ou=clients,ou=people,dc=hranet,dc=org"
[14/Apr/2010:08:31:05 -0500] conn=3016 op=3 EXT
oid="1.3.6.1.4.1.4203.1.11.1" name="passwd_modify_extop"
[14/Apr/2010:08:31:05 -0500] conn=3016 op=3 RESULT err=19 tag=120
nentries=0 etime=0
[14/Apr/2010:08:31:05 -0500] conn=3016 op=4 UNBIND
[14/Apr/2010:08:31:05 -0500] conn=3016 op=4 fd=66 closed - U1
Is this just a bug with directory server? Any thoughts or ideas are welcomed.

What is the platform? What is the 389 version? rpm -qi 389-ds-base What is the client? JNDI? The log item ABANDON targetop=NOTFOUND msgid=11 is interesting

...

Thanks,

Aaron Hagopian

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

Aaron Hagopian

12:17 p.m.

...

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

Rich Megginson

12:41 p.m.

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

Aaron Hagopian

2:42 p.m.

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@redhat.comwrote:

...

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

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

Aaron Hagopian

3:07 p.m.

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@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@redhat.comwrote:

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

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

Rich Megginson

4:14 p.m.

Aaron Hagopian 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.

It's JNDI itself. JNDI uses ABANDON requests. Are you using persistent search at all? Another 389 user reported similar problems caused by improper handling of JNDI persistent searches + ABANDON requests. Although this looks different, both issues have JNDI and ABANDON in common.

...

On Wed, Apr 14, 2010 at 12:41 PM, Rich Megginson <rmeggins@redhat.com mailto:rmeggins@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>
<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@lists.fedoraproject.org
<mailto:389-users@lists.fedoraproject.org>
> https://admin.fedoraproject.org/mailman/listinfo/389-users

--
389 users mailing list
389-users@lists.fedoraproject.org
<mailto:389-users@lists.fedoraproject.org>
https://admin.fedoraproject.org/mailman/listinfo/389-users

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

Aaron Hagopian

5:04 p.m.

...

It's JNDI itself. JNDI uses ABANDON requests. Are you using persistent search at all? Another 389 user reported similar problems caused by improper handling of JNDI persistent searches + ABANDON requests. Although this looks different, both issues have JNDI and ABANDON in common.

We are not using persistent search at all. I will try to track down what in our code creates the ABANDON requests but might take me a bit. Once successfull I'll get you something that causes the ABANDON to show up followed by a startTLS.

Rich Megginson

5:57 p.m.

Aaron Hagopian wrote:

...

It's JNDI itself.  JNDI uses ABANDON requests.  Are you using
persistent
search at all?  Another 389 user reported similar problems caused by
improper handling of JNDI persistent searches + ABANDON requests.
Although this looks different, both issues have JNDI and ABANDON
in common.
We are not using persistent search at all. I will try to track down what in our code creates the ABANDON requests but might take me a bit.

I think it's JNDI itself - you probably won't find anything explicitly calling an ABANDON request in your code.

...

Once successfull I'll get you something that causes the ABANDON to show up followed by a startTLS.

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

Aaron Hagopian

15 Apr 15 Apr

2:42 p.m.

I am having a hard time programmatically getting the ABANDON requests to show up. In my local environment I cannot reproduce at all (Fedora 12 x86_64) but on all our server environments I see these in the logs. The oddest thing about it is I only see these when running in tomcat on either our CentOS or RHEL machines (i386 and x86_64 platforms). Running a standalone java program does not create the ABANDON requests, only in tomcat. A little research shows that tomcat does have its own implementation of JNDI but that doesn't then explain why in my local environment (running same versions of java/tomcat/389ds) this does not happen. I will try to find any further relevant differences between my local environment and the servers where the messages show up.

For now we are just going SSL all the time on our connections which seems to fix the problem since we no longer need the startTLS.

On Wed, Apr 14, 2010 at 5:57 PM, Rich Megginson rmeggins@redhat.com wrote:

...

Aaron Hagopian wrote:

...
It's JNDI itself.  JNDI uses ABANDON requests.  Are you using
persistent
search at all?  Another 389 user reported similar problems caused by
improper handling of JNDI persistent searches + ABANDON requests.
Although this looks different, both issues have JNDI and ABANDON
in common.
We are not using persistent search at all. I will try to track down what in our code creates the ABANDON requests but might take me a bit.
I think it's JNDI itself - you probably won't find anything explicitly calling an ABANDON request in your code.

...
Once successfull I'll get you something that causes the ABANDON to show up followed by a startTLS.

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

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

Chun Tat David Chu

16 Apr 16 Apr

2:38 p.m.

Aaron,

I read thru the e-mail chain but perhaps I missed it. What exactly is the issue you are having regarding startTLS, ABANDON request and 389 Directory? Is it causing some unexpected behavior?

I too use startTLS in my JNDI client but I don't recall seeing anything that you are experiencing except the persistent search that Rich was talking about.

FYI (For your information), I narrowed down what triggers an ABANDON request within JNDI for persistent search by tracing the JNDI code that came as part of OpenJDK.

- David

2010/4/15 Aaron Hagopian airhead1@gmail.com

...

I am having a hard time programmatically getting the ABANDON requests to show up. In my local environment I cannot reproduce at all (Fedora 12 x86_64) but on all our server environments I see these in the logs. The oddest thing about it is I only see these when running in tomcat on either our CentOS or RHEL machines (i386 and x86_64 platforms). Running a standalone java program does not create the ABANDON requests, only in tomcat. A little research shows that tomcat does have its own implementation of JNDI but that doesn't then explain why in my local environment (running same versions of java/tomcat/389ds) this does not happen. I will try to find any further relevant differences between my local environment and the servers where the messages show up.

For now we are just going SSL all the time on our connections which seems to fix the problem since we no longer need the startTLS.

On Wed, Apr 14, 2010 at 5:57 PM, Rich Megginson rmeggins@redhat.comwrote:

...
Aaron Hagopian wrote:

...
It's JNDI itself.  JNDI uses ABANDON requests.  Are you using
persistent
search at all?  Another 389 user reported similar problems caused by
improper handling of JNDI persistent searches + ABANDON requests.
Although this looks different, both issues have JNDI and ABANDON
in common.
We are not using persistent search at all. I will try to track down what in our code creates the ABANDON requests but might take me a bit.
I think it's JNDI itself - you probably won't find anything explicitly calling an ABANDON request in your code.

...
Once successfull I'll get you something that causes the ABANDON to show up followed by a startTLS.

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

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

Rich Megginson

3:02 p.m.

Chun Tat David Chu wrote:

...

Aaron,

I read thru the e-mail chain but perhaps I missed it. What exactly is the issue you are having regarding startTLS, ABANDON request and 389 Directory? Is it causing some unexpected behavior?

I too use startTLS in my JNDI client but I don't recall seeing anything that you are experiencing except the persistent search that Rich was talking about.

FYI (For your information), I narrowed down what triggers an ABANDON request within JNDI for persistent search by tracing the JNDI code that came as part of OpenJDK.

From looking at the code, it looks as though the only way the error 1 LDAP_OPERATIONS_ERROR Other operations are still pending on the connection can be returned is if there are pending operations that have not completed sending results to the client. In this case, it looks as though new InitialLdapContext() with a javax.naming.Context.SECURITY_AUTHENTICATION of "simple", and a javax.naming.Context.SECURITY_PRINCIPAL of a valid DN, and a javax.naming.Context.SECURITY_CREDENTIALS of a valid password does an LDAP BIND operation, which could be the operation still incomplete when the server receives the startTLS request.

Is it possible that tomcat is accessing the JNDI ldap context from more than one thread at once? One way this might happen is if one thread is attempting to complete reading the bind response, but is swapped out, and another thread issues the starttls request on the same connection.

I have not been able to reproduce this. I've tried python-ldap and a small test program using JNDI, to hammer the server with new InitialLdapContext + starttls requests - running up to 100 at the same time in separate threads. I have not been able to reproduce the error. According to http://www.ietf.org/rfc/rfc4513.txt, it is recommended that the client _not_ send a bind request, that the first operation on the connection should be the startTLS operation. However, I don't know very much about JNDI - I don't know how to turn off that implicit bind operation.

...

David

2010/4/15 Aaron Hagopian <airhead1@gmail.com mailto:airhead1@gmail.com>

I am having a hard time programmatically getting the ABANDON
requests to show up.  In my local environment I cannot reproduce
at all (Fedora 12 x86_64) but on all our server environments I see
these in the logs.  The oddest thing about it is I only see these
when running in tomcat on either our CentOS or RHEL  machines
(i386 and x86_64 platforms).  Running a standalone java program
does not create the ABANDON requests, only in tomcat.  A little
research shows that tomcat does have its own implementation of
JNDI but that doesn't then explain why in my local environment
(running same versions of java/tomcat/389ds) this does not happen.
   I will try to find any further relevant differences between my
local environment and the servers where the messages show up.

For now we are just going SSL all the time on our connections
which seems to fix the problem since we no longer need the startTLS.

On Wed, Apr 14, 2010 at 5:57 PM, Rich Megginson
<rmeggins@redhat.com <mailto:rmeggins@redhat.com>> wrote:

    Aaron Hagopian wrote:
    >
    >
    >     It's JNDI itself.  JNDI uses ABANDON requests.  Are you
    using
    >     persistent
    >     search at all?  Another 389 user reported similar
    problems caused by
    >     improper handling of JNDI persistent searches + ABANDON
    requests.
    >     Although this looks different, both issues have JNDI and
    ABANDON
    >     in common.
    >
    >
    > We are not using persistent search at all.  I will try to
    track down
    > what in our code creates the ABANDON requests but might take
    me a bit.
    I think it's JNDI itself - you probably won't find anything
    explicitly
    calling an ABANDON request in your code.
    >  Once successfull I'll get you something that causes the
    ABANDON to
    > show up followed by a startTLS.
    >
    ------------------------------------------------------------------------
    >
    > --
    > 389 users mailing list
    > 389-users@lists.fedoraproject.org
    <mailto:389-users@lists.fedoraproject.org>
    > https://admin.fedoraproject.org/mailman/listinfo/389-users

    --
    389 users mailing list
    389-users@lists.fedoraproject.org
    <mailto:389-users@lists.fedoraproject.org>
    https://admin.fedoraproject.org/mailman/listinfo/389-users

--
389 users mailing list
389-users@lists.fedoraproject.org
<mailto:389-users@lists.fedoraproject.org>
https://admin.fedoraproject.org/mailman/listinfo/389-users

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

Aaron Hagopian

17 Apr 17 Apr

5:04 p.m.

On Fri, Apr 16, 2010 at 3:02 PM, Rich Megginson rmeggins@redhat.com wrote:

...

Chun Tat David Chu wrote:

...
Aaron,

I read thru the e-mail chain but perhaps I missed it. What exactly is the issue you are having regarding startTLS, ABANDON request and 389 Directory? Is it causing some unexpected behavior?

I too use startTLS in my JNDI client but I don't recall seeing anything that you are experiencing except the persistent search that Rich was talking about.

FYI (For your information), I narrowed down what triggers an ABANDON request within JNDI for persistent search by tracing the JNDI code that came as part of OpenJDK.

From looking at the code, it looks as though the only way the error 1 LDAP_OPERATIONS_ERROR Other operations are still pending on the connection can be returned is if there are pending operations that have not completed sending results to the client. In this case, it looks as though new InitialLdapContext() with a javax.naming.Context.SECURITY_AUTHENTICATION of "simple", and a javax.naming.Context.SECURITY_PRINCIPAL of a valid DN, and a javax.naming.Context.SECURITY_CREDENTIALS of a valid password does an LDAP BIND operation, which could be the operation still incomplete when the server receives the startTLS request.

Is it possible that tomcat is accessing the JNDI ldap context from more than one thread at once? One way this might happen is if one thread is attempting to complete reading the bind response, but is swapped out, and another thread issues the starttls request on the same connection.

I have not been able to reproduce this. I've tried python-ldap and a small test program using JNDI, to hammer the server with new InitialLdapContext + starttls requests - running up to 100 at the same time in separate threads. I have not been able to reproduce the error. According to http://www.ietf.org/rfc/rfc4513.txt, it is recommended that the client _not_ send a bind request, that the first operation on the connection should be the startTLS operation. However, I don't know very much about JNDI - I don't know how to turn off that implicit bind operation.

By not initializing the principle and credentials it will do an anonymous bind. I am initializing these first and then sending the startTLS operation so I will try to just do the bind afterwards and see if that helps. The other threads are using a pool so at first I thought that was the problem but I put on the pool logging to debug level and the startTLS is definitely not using one of the connections from the pool.

In response to David we are using the official sun JVM and not openJDK on our production servers and the ABANDON requests are there too. We are also not using persistent searches, just regular JNDI LdapContext.search() calls. Also these errors do seem related to system load since on normal operations everything works fine so it is possible the connections are being swapped and creating an issue. As I mentioned for now we've moved forward with just using an SSL connection all the time but after we get to a stable point I will move us back to the startTLS and see what else I can dig up.

...

David

2010/4/15 Aaron Hagopian <airhead1@gmail.com <mailto:airhead1@gmail.com

...

I am having a hard time programmatically getting the ABANDON
requests to show up.  In my local environment I cannot reproduce
at all (Fedora 12 x86_64) but on all our server environments I see
these in the logs.  The oddest thing about it is I only see these
when running in tomcat on either our CentOS or RHEL  machines
(i386 and x86_64 platforms).  Running a standalone java program
does not create the ABANDON requests, only in tomcat.  A little
research shows that tomcat does have its own implementation of
JNDI but that doesn't then explain why in my local environment
(running same versions of java/tomcat/389ds) this does not happen.
   I will try to find any further relevant differences between my
local environment and the servers where the messages show up.

For now we are just going SSL all the time on our connections
which seems to fix the problem since we no longer need the startTLS.

On Wed, Apr 14, 2010 at 5:57 PM, Rich Megginson
<rmeggins@redhat.com <mailto:rmeggins@redhat.com>> wrote:

    Aaron Hagopian wrote:
    >
    >
    >     It's JNDI itself.  JNDI uses ABANDON requests.  Are you
    using
    >     persistent
    >     search at all?  Another 389 user reported similar
    problems caused by
    >     improper handling of JNDI persistent searches + ABANDON
    requests.
    >     Although this looks different, both issues have JNDI and
    ABANDON
    >     in common.
    >
    >
    > We are not using persistent search at all.  I will try to
    track down
    > what in our code creates the ABANDON requests but might take
    me a bit.
    I think it's JNDI itself - you probably won't find anything
    explicitly
    calling an ABANDON request in your code.
    >  Once successfull I'll get you something that causes the
    ABANDON to
    > show up followed by a startTLS.
    >

...

    >
    > --
    > 389 users mailing list
    > 389-users@lists.fedoraproject.org
    <mailto:389-users@lists.fedoraproject.org>
    > https://admin.fedoraproject.org/mailman/listinfo/389-users

    --
    389 users mailing list
    389-users@lists.fedoraproject.org
    <mailto:389-users@lists.fedoraproject.org>
    https://admin.fedoraproject.org/mailman/listinfo/389-users



--
389 users mailing list
389-users@lists.fedoraproject.org
<mailto:389-users@lists.fedoraproject.org>
https://admin.fedoraproject.org/mailman/listinfo/389-users

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

5392

Age (days ago)

5395

Last active (days ago)

389-users@lists.fedoraproject.org

12 comments

3 participants

tags (0)

participants (3)

Aaron Hagopian
Chun Tat David Chu
Rich Megginson