[389-users] Random failures on startTLS

[Rich Megginson]

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