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

Re: TLS handshake failure

On 11-08-09 2:45 PM, Rich Megginson wrote:

On 08/09/2011 12:43 PM, Daniel Qian wrote:

On 11-08-09 2:12 PM, Rich Megginson wrote:

On 08/09/2011 11:59 AM, Daniel Qian wrote:

On 11-08-09 12:55 PM, Rich Megginson wrote:

On 08/09/2011 10:15 AM, Daniel Qian wrote:

On 11-08-09 11:21 AM, Rich Megginson wrote:

On 08/09/2011 09:07 AM, Daniel Qian wrote:

On 11-08-09 10:49 AM, Rich Megginson wrote:

On 08/09/2011 08:33 AM, Daniel Qian wrote:

Hi,
I have slapd 2.4.24 and everything works without TLS. but if I add a -Z option to the ldapsearch command I get this:
[root@ldaprov1 cacerts]# ldapsearch -x -LLL -b cn=config -D cn=admin,cn=config -wxxxxxxx -Z -H ldap://ldaprov1.prod cn=config 
ldap_start_tls: Connect error (-11)
ldap_result: Can't contact LDAP server (-1)
slapd.log shows something like this : connection_read(16): TLS accept failure error=-1 id=1006, closing 

Output from openssl debug:
[root@ldaprov1 cacerts]# openssl s_client -connect hostname:389 -showcerts -state -CAfile cacert.pem 
CONNECTED(00000003)
SSL_connect:before/connect initialization
SSL_connect:SSLv2/v3 write client hello A
140225133647680:error:140790E5:SSL routines:SSL23_WRITE:ssl handshake failure:s23_lib.c:177: 
---
no peer certificate available
---
No client certificate CA names sent
---
SSL handshake has read 0 bytes and written 113 bytes
---
New, (NONE), Cipher is (NONE)
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
---
The configurations are as follow (same command as above but without the -Z option):
[root@ldaprov1 cacerts]# ldapsearch -x -LLL -b cn=config -D cn=admin,cn=config -wxxxxxx -H ldap://hostname cn=config 
dn: cn=config
objectClass: olcGlobal
cn: config
olcConfigFile: /etc/openldap/slapd.conf
olcConfigDir: /etc/openldap/slapd.d
olcAllows: bind_v2
olcArgsFile: /var/run/openldap/slapd.args
olcAttributeOptions: lang-
olcAuthzPolicy: none
olcConcurrency: 0
olcConnMaxPending: 100
olcConnMaxPendingAuth: 1000
olcGentleHUP: FALSE
olcIdleTimeout: 0
olcIndexSubstrIfMaxLen: 4
olcIndexSubstrIfMinLen: 2
olcIndexSubstrAnyLen: 4
olcIndexSubstrAnyStep: 2
olcIndexIntLen: 4
olcLocalSSF: 71
olcLogLevel: 9
olcPidFile: /var/run/openldap/slapd.pid
olcReadOnly: FALSE
olcReverseLookup: FALSE
olcSaslSecProps: noplain,noanonymous
olcSockbufMaxIncoming: 262143
olcSockbufMaxIncomingAuth: 16777215
olcThreads: 16
olcTLSCACertificateFile: /etc/openldap/cacerts/cacert.pem
olcTLSCertificateFile: /etc/openldap/cacerts/ldaprov1.crt
olcTLSCertificateKeyFile: /etc/openldap/cacerts/ldaprov1.key
olcTLSVerifyClient: never
olcToolThreads: 1
olcWriteTimeout: 0
I verified the ldap user can read all the TLS files and they are setup fine
[root@ldaprov1 cacerts]# openssl verify -purpose sslserver -CAfile cacert.pem ldaprov1.crt 
ldaprov1.crt: OK


Anyone can tell me what I am missing here?

No, but we're missing
1) platform
2) tls implementation (openssl, moznss, gnutls)
3) output of ldapsearch -x -d 1 -Z ...... rest of arguments .....



Its Fedora 15

ldd /usr/sbin/slapd
        linux-vdso.so.1 =>  (0x00007fff76fff000)
libltdl.so.7 => /usr/lib64/libltdl.so.7 (0x00007f0f29fcd000) 
        libdb-4.8.so => /lib64/libdb-4.8.so (0x00007f0f29c53000)
libsasl2.so.2 => /usr/lib64/libsasl2.so.2 (0x00007f0f29a38000) 
        libcrypt.so.1 => /lib64/libcrypt.so.1 (0x00007f0f29801000)
libresolv.so.2 => /lib64/libresolv.so.2 (0x00007f0f295e6000) 
        libssl3.so => /usr/lib64/libssl3.so (0x00007f0f293b0000)
libsmime3.so => /usr/lib64/libsmime3.so (0x00007f0f29183000) 
        libnss3.so => /usr/lib64/libnss3.so (0x00007f0f28e4b000)
libnssutil3.so => /usr/lib64/libnssutil3.so (0x00007f0f28c2b000) 
        libplds4.so => /lib64/libplds4.so (0x00007f0f28a28000)
        libplc4.so => /lib64/libplc4.so (0x00007f0f28824000)
        libnspr4.so => /lib64/libnspr4.so (0x00007f0f285e6000)
libpthread.so.0 => /lib64/libpthread.so.0 (0x00007f0f283cb000) 
        libc.so.6 => /lib64/libc.so.6 (0x00007f0f28032000)
        libdl.so.2 => /lib64/libdl.so.2 (0x00007f0f27e2d000)
        libfreebl3.so => /lib64/libfreebl3.so (0x00007f0f27bcc000)
        libz.so.1 => /lib64/libz.so.1 (0x00007f0f279b5000)
        /lib64/ld-linux-x86-64.so.2 (0x00007f0f2a66a000)


the ldapsearch -d 1 option tells me a lot more:
.....
ldap_msgfree
TLS: file ldaprov1.crt does not end in [.0] - does not appear to be a CA certificate directory file with a properly hashed file name - skipping. TLS: file cacert.pem does not end in [.0] - does not appear to be a CA certificate directory file with a properly hashed file name - skipping. TLS: file ldaprov1.key does not end in [.0] - does not appear to be a CA certificate directory file with a properly hashed file name - skipping. 
.....
I tell slapd to look for specific files but how come it is still checking in a directory?
I don't know. What does /etc/openldap/ldap.conf say? Do you have a ~/.ldaprc or ~/ldaprc for the user "ldap"?
So even for slapd the setting TLS_CACERTDIR in /etc/openldap/ldap.conf takes precedence over olcTLSCACertificateFile in cn=config? I set /etc/openldap/ldap.conf for client only and did not mean it for slapd.
I don't know. Can someone confirm that this is how it works when using openssl or gnutls for crypto? That is, I don't think this problem is specific to moznss.
Now after I removed it from /etc/openldap/ldap.conf, ldapsearch -d 1 is indicating the CA certificate not valid:
TLS: certificate [CA certificate details omitted here...] is not valid - error -8172:Unknown code ___f 20. 
error -8172:Unknown code ___f 20.
tls_write: want=7, written=7
  0000:  15 03 01 00 02 02 30                               ......0
TLS: error: connect - force handshake failure: errno 21 - moznss error -8172 
TLS: can't connect: TLS error -8172:Unknown code ___f 20.
ldap_err2string
ldap_start_tls: Connect error (-11)
        additional info: TLS error -8172:Unknown code ___f 20
Does this mean all the certificates I created on the same server with openssl can not be used by modnss in slapd? I never delt with modnss before 
20 means SEC_ERROR_UNTRUSTED_ISSUER
Can you provide the entire log leading up to this point? you can paste it to fpaste.org if you don't want to spam the list with too much information.
Yes, openldap with moznss should work _exactly_ like openldap with openssl. If this is something that was working before this is a bug that needs to be fixed asap.
I ran the same ldapsearch command from a Centos box which has openssl and the error messages says this :
TLS certificate verification: Error, self signed certificate in certificate chain
which is not true. I have separate CA certificate and server certificate. The server certificate is signed by the CA certificate. 
openssl seems to be complaining about the CA certificate:
#
TLS certificate verification: depth: 1, err: 19, subject: /C=CA/ST=Ontario/L=Toronto/O=Epic Media Group/OU=IT/CN=Epic Media Group root CA/emailAddress=sysadmin@theepicmediagroup.com, issuer: /C=CA/ST=Ontario/L=Toronto/O=Epic Media Group/OU=IT/CN=Epic Media Group root CA/emailAddress=sysadmin@theepicmediagroup.com 
#
TLS certificate verification: Error, self signed certificate in certificate chain
Note that the subject: is the same as the issuer: - that is, it is a self signed certificate (self issued). 

But I'm not sure if this is the real problem.
That certificate it is complaining about is actually the ROOT CA. But I have another server certificate specified by "olcTLSCertificateFile: /etc/ssl/certs/ldaprov1.crt" in cn=config and its subject and issuer are shown below:
certs]# openssl x509 -noout -issuer -subject -in /etc/ssl/certs/ldaprov1.crt issuer= /C=CA/ST=Ontario/L=Toronto/O=Epic Media Group/OU=IT/CN=Epic Media Group root CA/emailAddress=sysadmin@theepicmediagroup.com subject= /C=CA/ST=Ontario/L=Toronto/O=Epic Media Group/OU=IT/CN=ldaprov1.prod/emailAddress=sysadmin@theepicmediagroup.com 

Its that the client can't seem to get it for some reasons.

#
TLS trace: SSL3 alert write:fatal:unknown CA

Do you have the CA cert on the client machine?
I put the same CA cert on the client machine, both in /etc/ldap.conf(/etc/nss_ldap.conf on Fedora now) and /etc/openldap/ldap.conf
Seems the server certificate defined in olcTLSCertificateFile never gets recognized by the client. 

Centos openssl output pasted - http://fpaste.org/7Hju/
Fedora moznss output pasted - http://fpaste.org/aE19/
If you remove TLS_CACERTDIR from /etc/openldap/ldap.conf and then specify 
olcTLSCACertificateFile: /etc/openldap/cacerts/cacert.pem
olcTLSCertificateFile: /etc/openldap/cacerts/ldaprov1.crt
olcTLSCertificateKeyFile: /etc/openldap/cacerts/ldaprov1.key
That is what I have been doing, or trying to do the whole time. Note the last three lines from the current configuration as shown below from the Centos client:
.prod:/etc/openldap/cacerts]# ldapsearch -x -LLL -b cn=config -D cn=admin,cn=config -wtesting123 -H ldap://ldaprov1.prod cn=config 
dn: cn=config
objectClass: olcGlobal
cn: config
olcConfigFile: /etc/openldap/slapd.conf
olcConfigDir: /etc/openldap/slapd.d
olcAllows: bind_v2
olcArgsFile: /var/run/openldap/slapd.args
olcAttributeOptions: lang-
olcAuthzPolicy: none
olcConcurrency: 0
olcConnMaxPending: 100
olcConnMaxPendingAuth: 1000
olcGentleHUP: FALSE
olcIdleTimeout: 0
olcIndexSubstrIfMaxLen: 4
olcIndexSubstrIfMinLen: 2
olcIndexSubstrAnyLen: 4
olcIndexSubstrAnyStep: 2
olcIndexIntLen: 4
olcLocalSSF: 71
olcLogLevel: 9
olcPidFile: /var/run/openldap/slapd.pid
olcReadOnly: FALSE
olcReverseLookup: FALSE
olcSaslSecProps: noplain,noanonymous
olcSockbufMaxIncoming: 262143
olcSockbufMaxIncomingAuth: 16777215
olcThreads: 16
olcTLSVerifyClient: never
olcToolThreads: 1
olcWriteTimeout: 0
olcTLSCACertificateFile: /etc/ssl/certs/cacert.pem
olcTLSCertificateFile: /etc/ssl/certs/ldaprov1.crt
olcTLSCertificateKeyFile: /etc/ssl/certs/ldaprov1.key

try starting slapd with -d 1


got the following from the log:

Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on 1 descriptor
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on:
Aug  9 19:27:27 ldaprov2 slapd[28972]:
Aug  9 19:27:27 ldaprov2 slapd[28972]: slap_listener_activate(7):
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=7 busy
Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=8 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=9 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=10 active_threads=0 tvp=zero 
Aug  9 19:27:27 ldaprov2 slapd[28972]: >>> slap_listener(ldap:///)
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on 1 descriptor
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on:
Aug  9 19:27:27 ldaprov2 slapd[28972]:
Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=7 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=8 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=9 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=10 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: listen=7, new connection on 14 
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on 1 descriptor
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on:
Aug  9 19:27:27 ldaprov2 slapd[28972]:  14r
Aug  9 19:27:27 ldaprov2 slapd[28972]:
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: read active on 14
Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: added 14r (active) listener=(nil) Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=7 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=8 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=9 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=10 active_threads=0 tvp=zero 
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on 1 descriptor
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on:
Aug  9 19:27:27 ldaprov2 slapd[28972]:
Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=7 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=8 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=9 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=10 active_threads=0 tvp=zero 
Aug  9 19:27:27 ldaprov2 slapd[28972]: connection_get(14)
Aug  9 19:27:27 ldaprov2 slapd[28972]: connection_get(14): got connid=1003
Aug 9 19:27:27 ldaprov2 slapd[28972]: connection_read(14): checking for input on id=1003 
Aug  9 19:27:27 ldaprov2 slapd[28972]: op tag 0x77, time 1312932447
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on 1 descriptor
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on:
Aug  9 19:27:27 ldaprov2 slapd[28972]:
Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=7 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=8 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=9 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=10 active_threads=0 tvp=zero 
Aug  9 19:27:27 ldaprov2 slapd[28972]: conn=1003 op=0 do_extended
Aug 9 19:27:27 ldaprov2 slapd[28972]: conn=1003 op=0 EXT oid=1.3.6.1.4.1.1466.20037 Aug 9 19:27:27 ldaprov2 slapd[28972]: do_extended: oid=1.3.6.1.4.1.1466.20037 
Aug  9 19:27:27 ldaprov2 slapd[28972]: conn=1003 op=0 STARTTLS
Aug  9 19:27:27 ldaprov2 slapd[28972]: send_ldap_extended: err=0 oid= len=0
Aug 9 19:27:27 ldaprov2 slapd[28972]: send_ldap_response: msgid=1 tag=120 err=0 Aug 9 19:27:27 ldaprov2 slapd[28972]: conn=1003 op=0 RESULT oid= err=0 text= Aug 9 19:27:27 ldaprov2 slapd[28972]: conn=1003 fd=14 ACCEPT from IP=10.10.2.44:54439 (IP=0.0.0.0:389) 
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on 1 descriptor
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on:
Aug  9 19:27:27 ldaprov2 slapd[28972]:  14r
Aug  9 19:27:27 ldaprov2 slapd[28972]:
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: read active on 14
Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=7 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=8 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=9 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=10 active_threads=0 tvp=zero 
Aug  9 19:27:27 ldaprov2 slapd[28972]: connection_get(14)
Aug  9 19:27:27 ldaprov2 slapd[28972]: connection_get(14): got connid=1003
Aug 9 19:27:27 ldaprov2 slapd[28972]: connection_read(14): checking for input on id=1003 
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on 1 descriptor
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on:
Aug  9 19:27:27 ldaprov2 slapd[28972]:
Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=7 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=8 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=9 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=10 active_threads=0 tvp=zero 
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on 1 descriptor
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on:
Aug  9 19:27:27 ldaprov2 slapd[28972]:  14r
Aug  9 19:27:27 ldaprov2 slapd[28972]:
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: read active on 14
Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=7 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=8 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=9 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=10 active_threads=0 tvp=zero 
Aug  9 19:27:27 ldaprov2 slapd[28972]: connection_get(14)
Aug  9 19:27:27 ldaprov2 slapd[28972]: connection_get(14): got connid=1003
Aug 9 19:27:27 ldaprov2 slapd[28972]: connection_read(14): checking for input on id=1003 Aug 9 19:27:27 ldaprov2 slapd[28972]: connection_read(14): TLS accept failure error=-1 id=1003, closing Aug 9 19:27:27 ldaprov2 slapd[28972]: connection_closing: readying conn=1003 sd=14 for close 
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on 1 descriptor
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: activity on:
Aug  9 19:27:27 ldaprov2 slapd[28972]:
Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=7 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=8 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=9 active_threads=0 tvp=zero Aug 9 19:27:27 ldaprov2 slapd[28972]: daemon: epoll: listen=10 active_threads=0 tvp=zero 
Aug  9 19:27:27 ldaprov2 slapd[28972]: connection_close: conn=1003 sd=14
Aug  9 19:27:27 ldaprov2 slapd[28972]: daemon: removing 14
Aug 9 19:27:27 ldaprov2 slapd[28972]: conn=1003 fd=14 closed (TLS negotiation failure)