[389-users] Random failures on startTLS

[Aaron Hagopian]

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.fedoraproject.org/pipermail/389-users/attachments/20100414/a22c22e2/attachment.html>