[Date Prev][Date Next] [Chronological] [Thread] [Top]

Re: TLS in 2.0.8 vs 2.0.7, openssl 0.9.6, HP-UX 11, gcc

To: "Kurt D. Zeilenga" <Kurt@OpenLDAP.org>
Subject: Re: TLS in 2.0.8 vs 2.0.7, openssl 0.9.6, HP-UX 11, gcc
From: Allan E Johannesen <aej@WPI.EDU>
Date: Sun, 20 May 2001 10:20:23 -0400 (EDT)
Cc: Allan E Johannesen <aej@WPI.EDU>, openldap-software@OpenLDAP.org
In-reply-to: <5.1.0.14.0.20010519132004.00af0200@127.0.0.1>
References: <15109.7855.413119.773060@hp3com2.wpi.edu> <5.1.0.14.0.20010519132004.00af0200@127.0.0.1>

>>>>> "Kurt" == Kurt D Zeilenga <Kurt@OpenLDAP.org> writes:

Kurt> Make sure your client is not refusing the server certificate.

Here are two subsequent queries to the same server a few seconds apart:

hp3com2:/tools/utilities/openldap/openldap-2.0.8> ldapsearch -ZZ '(uid=aej)'
version: 2

#
# filter: (uid=aej)
# requesting: ALL
#

# 2af586df6800b3389cbe7bcbf2a920df, People, dc=WPI, dc=EDU
dn: wpiuuid=2af586df6800b3389cbe7bcbf2a920df, ou=People, dc=WPI, dc=EDU
mailRoutingAddress: aej@WPI.EDU
eduPersonPrincipalName: aej@WPI.EDU
eduPersonOrgDN: dc=WPI, dc=EDU
uid: aej

# search result
search: 3
result: 0 Success

# numResponses: 2
# numEntries: 1
hp3com2:/tools/utilities/openldap/openldap-2.0.8> ldapsearch -ZZ '(uid=aej)'
ldap_start_tls: Success
hp3com2:/tools/utilities/openldap/openldap-2.0.8> 

This was running the server -d1.  If I run the server -d-1, it succeeds
most of the time (not all the time).  In -d1 it rarely works, but sometimes
sneaks through, as it did above.  Without debugging the server, I'm not sure
I've seen it work.

This seems to be a scarey bug if debugging being present makes it hide.  It
appears to be a timing-related problem.

This is the debugging output of those two requests.  Note that in the
successful one, the server went to key exchange (marked <<< good >>>), but in
the failure, it decided instead to try to get the certificate from the client
(marked <<< bogus >>>).  This has been configured:

# ./configure  --without-cyrus-sasl --enable-kpasswd --without-threads

hp3com2:/tools/utilities/openldap/openldap-2.0.8# servers/slapd/slapd -d1
@(#) $OpenLDAP: slapd 2.0.8-Release (Sun May 20 10:02:13 EDT 2001) $
	aej@hp3com2:/tools/utilities/openldap/openldap-2.0.8/servers/slapd
daemon_init: listen on ldap:///
daemon_init: 1 listeners to open...
ldap_url_parse_ext(ldap:///)
daemon: initialized ldap:///
daemon_init: 1 listeners opened
slapd init: initiated server.
oc_check_allowed type "member"
slapd startup: initiated.
slapd starting
connection_get(7): got connid=0
connection_read(7): checking for input on id=0
ber_get_next
ber_get_next: tag 0x30 len 29 contents:
do_extended
ber_scanf fmt ({a) ber:
send_ldap_extended 0: (0)
send_ldap_response: msgid=1 tag=120 err=0
ber_flush: 14 bytes to sd 7
ber_get_next
ber_get_next on fd 7 failed errno=11 (Resource temporarily unavailable)
connection_get(7): got connid=0
connection_read(7): checking for input on id=0
TLS trace: SSL_accept:before/accept initialization
TLS trace: SSL_accept:SSLv3 read client hello A
TLS trace: SSL_accept:SSLv3 write server hello A
TLS trace: SSL_accept:SSLv3 write certificate A
TLS trace: SSL_accept:SSLv3 write server done A
TLS trace: SSL_accept:SSLv3 flush data
TLS trace: SSL_accept:SSLv3 read client key exchange A <<< good >>>
TLS trace: SSL_accept:SSLv3 read finished A
TLS trace: SSL_accept:SSLv3 write change cipher spec A
TLS trace: SSL_accept:SSLv3 write finished A
TLS trace: SSL_accept:SSLv3 flush data
connection_get(7): got connid=0
connection_read(7): checking for input on id=0
ber_get_next
ber_get_next: tag 0x30 len 12 contents:
do_bind
ber_scanf fmt ({iat) ber:
ber_scanf fmt (o}) ber:
do_bind: version=3 dn="" method=128
send_ldap_result: conn=0 op=1 p=3
send_ldap_response: msgid=2 tag=97 err=0
ber_flush: 14 bytes to sd 7
do_bind: v3 anonymous bind
ber_get_next
ber_get_next: tag 0x30 len 50 contents:
do_search
ber_scanf fmt ({aiiiib) ber:
ber_scanf fmt ({oo}) ber:
ber_scanf fmt ({v}}) ber:
=> ldbm_back_search
dn2entry_r: dn: "DC=WPI,DC=EDU"
=> dn2id( "DC=WPI,DC=EDU" )
=> ldbm_cache_open( "/var/openldap-ldbm/dn2id.dbb", 73, 600 )
<= ldbm_cache_open (opened 0)
<= dn2id 1
=> id2entry_r( 1 )
=> ldbm_cache_open( "/var/openldap-ldbm/id2entry.dbb", 73, 600 )
<= ldbm_cache_open (opened 1)
=> str2entry
<= str2entry(dc=WPI, dc=EDU) -> -1 (0x4009db78)
<= id2entry_r( 1 ) 0x4009db78 (disk)
search_candidates: base="DC=WPI,DC=EDU" s=2 d=0
=> filter_candidates
=> list_candidates 0xa0
=> filter_candidates
=> dn2idl( "@DC=WPI,DC=EDU" )
=> ldbm_cache_open( "/var/openldap-ldbm/dn2id.dbb", 73, 600 )
<= ldbm_cache_open (cache 0)
=> ldbm_cache_open( "/var/openldap-ldbm/nextid.dbb", 73, 600 )
<= ldbm_cache_open (opened 2)
<= filter_candidates 11938
=> filter_candidates
=> list_candidates 0xa1
=> filter_candidates
=> equality_candidates
=> ldbm_cache_open( "/var/openldap-ldbm/objectClass.dbb", 16, 600 )
<= ldbm_cache_open (opened 3)
=> key_read
<= index_read 0 candidates
<= equality_candidates NULL
<= equality_candidates 0
<= filter_candidates 0
=> filter_candidates
=> equality_candidates
=> ldbm_cache_open( "/var/openldap-ldbm/uid.dbb", 16, 600 )
<= ldbm_cache_open (opened 4)
=> key_read
<= index_read 2 candidates
<= equality_candidates 2
<= filter_candidates 2
<= list_candidates 2
<= filter_candidates 2
<= list_candidates 2
<= filter_candidates 2
====> cache_return_entry_r( 1 ): created (0)
=> id2entry_r( 13 )
=> ldbm_cache_open( "/var/openldap-ldbm/id2entry.dbb", 73, 600 )
<= ldbm_cache_open (cache 1)
=> str2entry
<= str2entry(wpiuuid=2af586df6800b3389cbe7bcbf2a920df, ou=People, dc=WPI, dc=EDU) -> -1 (0x4009eb58)
<= id2entry_r( 13 ) 0x4009eb58 (disk)
=> send_search_entry: "wpiuuid=2af586df6800b3389cbe7bcbf2a920df, ou=People, dc=WPI, dc=EDU"
=> string_expand: pattern:  cn=superusers, ou=access, dc=wpi, dc=edu
=> string_expand: expanded: cn=superusers, ou=access, dc=wpi, dc=edu
dn2entry_r: dn: "CN=SUPERUSERS,OU=ACCESS,DC=WPI,DC=EDU"
=> dn2id( "CN=SUPERUSERS,OU=ACCESS,DC=WPI,DC=EDU" )
=> ldbm_cache_open( "/var/openldap-ldbm/dn2id.dbb", 73, 600 )
<= ldbm_cache_open (cache 0)
<= dn2id 5
=> id2entry_r( 5 )
=> ldbm_cache_open( "/var/openldap-ldbm/id2entry.dbb", 73, 600 )
<= ldbm_cache_open (cache 1)
=> str2entry
<= str2entry(cn=SuperUsers, ou=Access, dc=WPI, dc=EDU) -> -1 (0x4009f3c0)
<= id2entry_r( 5 ) 0x4009f3c0 (disk)
====> cache_return_entry_r( 5 ): created (0)
ldbm_back_group: rc=1
=> string_expand: pattern:  cn=superusers, ou=access, dc=wpi, dc=edu
=> string_expand: expanded: cn=superusers, ou=access, dc=wpi, dc=edu
dn2entry_r: dn: "CN=SUPERUSERS,OU=ACCESS,DC=WPI,DC=EDU"
=> dn2id( "CN=SUPERUSERS,OU=ACCESS,DC=WPI,DC=EDU" )
====> cache_find_entry_dn2id("CN=SUPERUSERS,OU=ACCESS,DC=WPI,DC=EDU"): 5 (1 tries)
<= dn2id 5 (in cache)
=> id2entry_r( 5 )
====> cache_find_entry_id( 5 ) "cn=SuperUsers, ou=Access, dc=WPI, dc=EDU" (found) (1 tries)
<= id2entry_r( 5 ) 0x4009f3c0 (cache)
====> cache_return_entry_r( 5 ): returned (0)
ldbm_back_group: rc=1
=> string_expand: pattern:  cn=application,ou=access,dc=wpi,dc=edu
=> string_expand: expanded: cn=application,ou=access,dc=wpi,dc=edu
=> regex_matches: string:   
=> regex_matches: rc: 20 no matches
=> string_expand: pattern:  cn=superusers, ou=access, dc=wpi, dc=edu
=> string_expand: expanded: cn=superusers, ou=access, dc=wpi, dc=edu
dn2entry_r: dn: "CN=SUPERUSERS,OU=ACCESS,DC=WPI,DC=EDU"
=> dn2id( "CN=SUPERUSERS,OU=ACCESS,DC=WPI,DC=EDU" )
====> cache_find_entry_dn2id("CN=SUPERUSERS,OU=ACCESS,DC=WPI,DC=EDU"): 5 (1 tries)
<= dn2id 5 (in cache)
=> id2entry_r( 5 )
====> cache_find_entry_id( 5 ) "cn=SuperUsers, ou=Access, dc=WPI, dc=EDU" (found) (1 tries)
<= id2entry_r( 5 ) 0x4009f3c0 (cache)
====> cache_return_entry_r( 5 ): returned (0)
ldbm_back_group: rc=1
ber_flush: 209 bytes to sd 7
<= send_search_entry
====> cache_return_entry_r( 13 ): created (0)
=> id2entry_r( 253 )
=> ldbm_cache_open( "/var/openldap-ldbm/id2entry.dbb", 73, 600 )
<= ldbm_cache_open (cache 1)
=> str2entry
<= str2entry(wpiuuid=2af586df6800b3389cbe7bcbf2a920df, ou=People, dc=WPI, dc=EDU) -> -1 (0x4009f1b8)
====> cache_add_entry( 253 ): "wpiuuid=2af586df6800b3389cbe7bcbf2a920df, ou=People, dc=WPI, dc=EDU": already in dn cache
<= id2entry_r( 253 ) (cache add failed)
ldbm_search: candidate 253 not found
send_ldap_search_result 0::
send_ldap_response: msgid=3 tag=101 err=0
ber_flush: 14 bytes to sd 7
ber_get_next
ber_get_next: tag 0x30 len 5 contents:
do_unbind
connection_closing: readying conn=0 sd=7 for close
connection_resched: attempting closing conn=0 sd=7
connection_close: conn=0 sd=7
TLS trace: SSL3 alert write:warning:close notify
connection_get(7): got connid=1
connection_read(7): checking for input on id=1
ber_get_next
ber_get_next: tag 0x30 len 29 contents:
do_extended
ber_scanf fmt ({a) ber:
send_ldap_extended 0: (0)
send_ldap_response: msgid=1 tag=120 err=0
ber_flush: 14 bytes to sd 7
ber_get_next
ber_get_next on fd 7 failed errno=11 (Resource temporarily unavailable)
connection_get(7): got connid=1
connection_read(7): checking for input on id=1
TLS trace: SSL_accept:before/accept initialization
TLS trace: SSL_accept:SSLv3 read client hello A
TLS trace: SSL_accept:SSLv3 write server hello A
TLS trace: SSL_accept:SSLv3 write certificate A
TLS trace: SSL_accept:SSLv3 write server done A
TLS trace: SSL_accept:SSLv3 flush data
TLS trace: SSL_accept:error in SSLv3 read client certificate A <<< bogus >>>
TLS trace: SSL_accept:error in SSLv3 read client certificate A
TLS: can't accept.
connection_read(7): TLS accept error error=-1 id=1, closing
connection_closing: readying conn=1 sd=7 for close
connection_close: conn=1 sd=7

Follow-Ups:
- Re: TLS in 2.0.8 vs 2.0.7, openssl 0.9.6, HP-UX 11, gcc
  - From: Allan E Johannesen <aej@WPI.EDU>

References:
- TLS in 2.0.8 vs 2.0.7, openssl 0.9.6, HP-UX 11, gcc
  - From: Allan E Johannesen <aej@WPI.EDU>
- Re: TLS in 2.0.8 vs 2.0.7, openssl 0.9.6, HP-UX 11, gcc
  - From: "Kurt D. Zeilenga" <Kurt@OpenLDAP.org>

Prev by Date: Re: could not link with POSIX Threads
Next by Date: Re: AW: ldapsearch not going through all the entries
Index(es):
- Chronological
- Thread