Can't get SSL working properly with openSUSE LDAP client (works with ldapsearch + SSL though)

Hi,
Hope this is the right mailing list to ask this - the
openldap-software@openldap.org list rejected it as off-topic.

I'm experimenting with my first LDAP server, trying to get an OpenSUSE 10.3
client (noisy.foo.lan IP 192.168.0.10) to authenticate to a FreeBSD 5.5 server
(daemon.foo.lan ip 192.168.0.5) via LDAP and I'm having trouble with SSL.
Hope someone can point me in the right direction...

I have the LDAP server (openldap-server-2.3.38 installed from ports) setup on
the FreeBSD box and have generated certificates. There is no SASL support,
I'm using SSL for encryption.

This is the slapd.conf file (/usr/local/etc/openldap/slapd.conf) on the
server:
        include         /usr/local/etc/openldap/schema/core.schema
        include         /usr/local/etc/openldap/schema/cosine.schema
        include         /usr/local/etc/openldap/schema/dyngroup.schema
        include         /usr/local/etc/openldap/schema/nis.schema
        pidfile         /var/run/openldap/slapd.pid
        argsfile        /var/run/openldap/slapd.args
        modulepath      /usr/local/libexec/openldap
        moduleload      back_bdb
        allow bind_v2 bind_anon_dn
        access to attrs=userPassword
            by self write
            by * auth
        access to dn.base=""
             by * read
        access to * by self write
            by * read
        security ssf=1 update_ssf=112 simple_bind=64
        TLSCipherSuite HIGH:MEDIUM:+TLSv1:+SSLv2:+SSLv3
        TLSCACertificateFile /usr/local/etc/openldap/cacert.pem
        TLSCertificateFile /usr/local/etc/openldap/slapd-cert-ldap1.pem
        TLSCertificateKeyFile /usr/local/etc/openldap/slapd-key-ldap1.pem
        TLSVerifyClient never
        database        bdb
        suffix          "dc=daemon,dc=com"
        rootdn          "cn=admin,dc=daemon,dc=com"
        rootpw  {SSHA}xxxxxxxxxxxxxxxxxxxxxxxxxxx
        directory       /var/db/openldap-data
        index   objectClass     eq

I've also setup /etc/openldap/ldap.conf on the suse box. Here are contents of
that conf file:
        BASE            dc=daemon,dc=com
        URI             ldaps://daemon.foo.lan
        TLS_CACERT      /etc/openldap/cacert.pem
        TLS_REQCERT never

I can use ldapsearch -x on that box to list the contents of the ldap server.
On the FreeBSD box, slapd is started with the  parameters -h "ldaps:///"

So it appears that SSL works just fine as far as ldapsearch is concerned. I've
even renamed the cacert file to confirm that ldapsearch fails without the
certificate there.

So far so good.

The next step was to get opensuse to authenticate to the ldap server using
PAM. I restarted slapd on the server with the parameters -h "ldaps:///
ldap:///" so it can use SSL or TLS and use this /etc/ldap.conf file on the
suse box:
        bind_policy     soft
        pam_lookup_policy       yes
        pam_password    md5
        nss_initgroups_ignoreusers      root,ldap
        nss_schema      rfc2307bis
        nss_map_attribute       uniqueMember member
        ssl     start_tls
        ldap_version    3
        pam_filter      objectclass=posixAccount
        nss_base_passwd dc=daemon,dc=com
        nss_base_shadow dc=daemon,dc=com
        nss_base_group  dc=daemon,dc=com
        tls_checkpeer   no
        base            dc=daemon,dc=com
        uri             ldap://daemon.foo.lan
        tls_cacert      /etc/openldap/cacert.pem
        tls_reqcert never
        scope sub
        rootbinddn cn=admin,dc=daemon,dc=com

That seems to work just fine, I can login on the suse box using my username &
password for the FBSD box (I haven't got the home dir automounting from the
server yet, that will be my next challenge).

Now the problem comes when I try to get this part working with SLL instead of
TLS. To do this, I've restarted slapd without the ldap:/// parameter and made
2 changes to /etc/ldap.conf:
<ssl start_tls
>#ssl start_tls
<uri ldap://daemon.foo.lan
> uri ldaps://daemon.foo.lan

Now when I try to login, the suse box shows the following
in /var/log/messages:

 Nov  9 21:22:34 noisy nscd: nss_ldap: failed to bind to LDAP server
 ldaps://daemon.foo.lan: Can't contact LDAP server
 Nov  9 21:22:34 noisy nscd: nss_ldap: failed to bind to LDAP server
 ldaps://daemon.foo.lan: Can't contact LDAP server
 Nov  9 21:22:34 noisy nscd: nss_ldap: could not search LDAP server - Server
is unavailable
 Nov  9 21:22:34 noisy login[4196]: Unable to obtain uid (user=imoore) for
audit system
 Nov  9 21:22:34 noisy login[4196]: User not known to the underlying
authentication module

I'm logging in as the user imoore, which in the ldap server is
        # imoore, People, daemon.com
        dn: uid=imoore,ou=People,dc=daemon,dc=com
        uid: imoore
        cn: Ian Moore
        objectClass: account
        objectClass: posixAccount
        objectClass: top
        loginShell: /bin/csh
        uidNumber: 1001
        gidNumber: 1001
        homeDirectory: /home/imoore
        gecos: Ian Moore

On the server's messages log, I get:
Nov  9 20:22:59 daemon kernel: Connection attempt to TCP 192.168.0.5:389 from
192.168.0.10:20576 flags:0x02
Nov  9 20:22:59 daemon kernel: Connection attempt to TCP 192.168.0.5:389 from
192.168.0.10:20577 flags:0x02

That's the firewall (which is set to allow everthing through btw), logging a
connection attempt from the client on 389, despite ldap.conf stating the URI
as ldaps:///daemon.foo.lan, which is odd.

Lastly (sorry this such a long post, but I'm trying to give all the relevant
information), here is the output of slapd with -d1 debugging when I try to
login on the client using SSL:
 >>> slap_listener(ldaps:///)

 connection_get(11): got connid=1
 connection_read(11): 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
 TLS trace: SSL_accept:error in SSLv3 read client certificate A
 connection_get(11): got connid=1
 connection_read(11): checking for input on id=1
 TLS trace: SSL_accept:SSLv3 read client key exchange A
 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_read(11): unable to get TLS client DN, error=49 id=1
 connection_get(11): got connid=1
 connection_read(11): checking for input on id=1
 ber_get_next
 ber_get_next: tag 0x30 len 46 contents:
 ber_get_next
 do_bind
 ber_scanf fmt ({imt) ber:

 ber_scanf fmt (m}) ber:
 >>> dnPrettyNormal: <cn=admin,dc=daemon,dc=com>

 <<< dnPrettyNormal: <cn=admin,dc=daemon,dc=com>,
 <cn=admin,dc=daemon,dc=com> do_bind: version=3
 dn="cn=admin,dc=daemon,dc=com" method=128
 do_bind: v3 bind: "cn=admin,dc=daemon,dc=com" to
 "cn=admin,dc=daemon,dc=com" send_ldap_result: conn=1 op=0 p=3
 send_ldap_response: msgid=1 tag=97 err=0
 ber_flush: 14 bytes to sd 11
 connection_get(11): got connid=1
 connection_read(11): checking for input on id=1
 ber_get_next
 ber_get_next: tag 0x30 len 86 contents:
 ber_get_next
 do_search

 ber_scanf fmt ({miiiib) ber:
 >>> dnPrettyNormal: <dc=daemon,dc=com>

 <<< dnPrettyNormal: <dc=daemon,dc=com>, <dc=daemon,dc=com>
 ber_scanf fmt ({mm}) ber:
 ber_scanf fmt ({mm}) ber:
 ber_scanf fmt ({M}}) ber:
 => bdb_search
 bdb_dn2entry("dc=daemon,dc=com")
 search_candidates: base="dc=daemon,dc=com" (0x00000001) scope=2
 => bdb_dn2idl("dc=daemon,dc=com")
 => bdb_equality_candidates (objectClass)
 => key_read
 <= bdb_index_read: failed (-30989)
 <= bdb_equality_candidates: id=0, first=0, last=0
 => bdb_equality_candidates (objectClass)
 => key_read
 <= bdb_index_read 3 candidates
 <= bdb_equality_candidates: id=3, first=27, last=29
 => bdb_equality_candidates (uid)
 <= bdb_equality_candidates: (uid) not indexed
 bdb_search_candidates: id=-1 first=27 last=29
 bdb_search: 27 does not match filter
 bdb_search: 28 does not match filter
 => send_search_entry: conn 1 dn="uid=imoore,ou=People,dc=daemon,dc=com"
 ber_flush: 319 bytes to sd 11
 <= send_search_entry: conn 1 exit.
 send_ldap_result: conn=1 op=1 p=3
 send_ldap_response: msgid=2 tag=101 err=0
 ber_flush: 14 bytes to sd 11
 connection_get(11): got connid=1
 connection_read(11): checking for input on id=1
 ber_get_next
 ber_get_next: tag 0x30 len 88 contents:
 ber_get_next
 do_bind
 ber_scanf fmt ({imt) ber:
 ber_scanf fmt (m}) ber:
 => get_ctrls
 ber_scanf fmt ({m) ber:
 => get_ctrls: oid="1.3.6.1.4.1.42.2.27.8.5.1" (noncritical)
 <= get_ctrls: n=1 rc=0 err=""

 >>> dnPrettyNormal: <uid=imoore,ou=People,dc=daemon,dc=com>

 <<< dnPrettyNormal: <uid=imoore,ou=People,dc=daemon,dc=com>,
 <uid=imoore,ou=people,dc=daemon,dc=com> do_bind: version=3
 dn="uid=imoore,ou=People,dc=daemon,dc=com" method=128 slap_global_control:
 unrecognized control: 1.3.6.1.4.1.42.2.27.8.5.1
 bdb_dn2entry("uid=imoore,ou=people,dc=daemon,dc=com")
 do_bind: v3 bind: "uid=imoore,ou=People,dc=daemon,dc=com" to
 "uid=imoore,ou=People,dc=daemon,dc=com" send_ldap_result: conn=1 op=2 p=3
 send_ldap_response: msgid=3 tag=97 err=0
 ber_flush: 14 bytes to sd 11
 connection_get(11): got connid=1
 connection_read(11): checking for input on id=1
 ber_get_next
 ber_get_next: tag 0x30 len 46 contents:
 ber_get_next
 do_bind
 ber_scanf fmt ({imt) ber:

 ber_scanf fmt (m}) ber:
 >>> dnPrettyNormal: <cn=admin,dc=daemon,dc=com>

 <<< dnPrettyNormal: <cn=admin,dc=daemon,dc=com>,
 <cn=admin,dc=daemon,dc=com> do_bind: version=3
 dn="cn=admin,dc=daemon,dc=com" method=128
 do_bind: v3 bind: "cn=admin,dc=daemon,dc=com" to
 "cn=admin,dc=daemon,dc=com" send_ldap_result: conn=1 op=3 p=3
 send_ldap_response: msgid=4 tag=97 err=0
 ber_flush: 14 bytes to sd 11
 connection_get(11): got connid=1
 connection_read(11): checking for input on id=1
 ber_get_next
 ber_get_next: tag 0x30 len 5 contents:
 ber_get_next
 TLS trace: SSL3 alert read:warning:close notify
 ber_get_next on fd 11 failed errno=0 (Undefined error: 0)
 connection_closing: readying conn=1 sd=11 for close
 connection_close: deferring conn=1 sd=11
 do_unbind
 connection_resched: attempting closing conn=1 sd=11
 connection_close: conn=1 sd=11
 TLS trace: SSL3 alert write:warning:close notify

I've run out of ideas to try, so any suggestions would be welcome!

Cheers,
 
Ian