[389-users] Random failures on startTLS

Aaron Hagopian <airhead1@xxxxxxxxx> · Wed, 14 Apr 2010 11:56:17 -0500

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