rlm_ldap (ldap): Could not start TLS: Connect error

28 Nov 2013

      Hello list,

in my further tests with FreeRADIUS v3 (rpmbuild from v3.0.x branch) I have a problem with the ldap module and start_tls.

This is definitely working:

-          Ldap connect with ldap utils (ldapsearch -ZZ and so on) via port 389 with starttls

-          Ldap connect with FreeRADIUS 2.1.12 via port 389 (start_tls = yes and require_cert = "demand")

This is not working:

-          FR 3 ldap module isn't able to connect to ldap server via port 389 + start_tls=yes

-          FR debug error:

  # Loaded module rlm_ldap
  # Instantiating module "ldap" from file /etc/raddb/mods-enabled/ldap
  ldap {
        server = "fqdn" (matches CN in ldap server certificate)
        port = 389
        password = "xxx"
        identity = "xxx"
        valuepair_attribute = "radiusVSA"
        read_clients = yes
   user {
        filter = "(&(uid=%{%{Stripped-User-Name}:-%{User-Name}})(objectClass=radiusProfile))"
        scope = "sub"
        base_dn = "xxx"
        access_attribute = "radiusAccountStatus"
        access_positive = yes
   }
   group {
        filter = "(objectClass=groupOfNames)"
        scope = "sub"
        base_dn = "xxx"
        name_attribute = "cn"
        membership_attribute = "memberOf"
        membership_filter = "(member=%{control:Ldap-UserDn})"
        cacheable_name = no
        cacheable_dn = yes
   }
   client {
        filter = "(objectClass=radiusClient)"
        scope = "sub"
        base_dn = "xxx"
    attribute {
        identifier = "radiusClientIdentifier"
        shortname = "radiusClientShortname"
        nas_type = "radiusClientType"
        secret = "radiusClientSecret"
        virtual_server = "radiusClientVirtualServer"
        require_message_authenticator = "radiusClientRequireMa"
    }
   }
   profile {
        filter = "(objectclass=radiusObjectProfile)"
        attribute = "radiusGroupName"
        default = "xxx"
   }
   options {
        ldap_debug = 597
        chase_referrals = yes
        rebind = yes
        net_timeout = 1
        res_timeout = 20
        srv_timelimit = 20
        idle = 60
        probes = 3
        interval = 3
   }
   tls {
        ca_file = "/etc/raddb/certs/rootca_cert.pem"
        start_tls = yes
        require_cert = "demand" (also tested with never, same result)
   }
  }
   accounting {
        reference = "%{tolower:type.%{Acct-Status-Type}}"
   }
   post-auth {
        reference = "."
   }
rlm_ldap (ldap): Initialising connection pool
   pool {
        start = 5
        min = 4
        max = 10
        spare = 3
        uses = 0
        lifetime = 0
        cleanup_delay = 5
        idle_timeout = 60
        spread = no
   }
rlm_ldap (ldap): Opening additional connection (0)
rlm_ldap (ldap): Connecting to fqdn:389
rlm_ldap (ldap): Could not start TLS: Connect error
rlm_ldap (ldap): Opening connection failed (0)
rlm_ldap (ldap): Removing connection pool
/etc/raddb/mods-enabled/ldap[8]: Instantiation failed for module "ldap"

-          openldap debug log:
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on:
Nov 28 11:21:00 radiusv3test slapd[7737]:
Nov 28 11:21:00 radiusv3test slapd[7737]: slap_listener_activate(7):
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 busy
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: >>> slap_listener(ldap:///)
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: listen=7, new connection on 16
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on:
Nov 28 11:21:00 radiusv3test slapd[7737]:
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: added 16r (active) listener=(nil)
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 2 descriptors
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on:
Nov 28 11:21:00 radiusv3test slapd[7737]:  16r
Nov 28 11:21:00 radiusv3test slapd[7737]:
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: read active on 16
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: connection_get(16)
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: connection_get(16): got connid=1003
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: connection_read(16): checking for input on id=1003
Nov 28 11:21:00 radiusv3test slapd[7737]: op tag 0x77, time 1385634060
Nov 28 11:21:00 radiusv3test slapd[7737]: conn=1003 op=0 do_extended
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on:
Nov 28 11:21:00 radiusv3test slapd[7737]: do_extended: oid=1.3.6.1.4.1.1466.20037
Nov 28 11:21:00 radiusv3test slapd[7737]:
Nov 28 11:21:00 radiusv3test slapd[7737]: send_ldap_extended: err=0 oid= len=0
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: send_ldap_response: msgid=1 tag=120 err=0
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on:
Nov 28 11:21:00 radiusv3test slapd[7737]:  16r
Nov 28 11:21:00 radiusv3test slapd[7737]:
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: read active on 16
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: connection_get(16)
Nov 28 11:21:00 radiusv3test slapd[7737]: connection_get(16): got connid=1003
Nov 28 11:21:00 radiusv3test slapd[7737]: connection_read(16): checking for input on id=1003
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on:
Nov 28 11:21:00 radiusv3test slapd[7737]:
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on:
Nov 28 11:21:00 radiusv3test slapd[7737]:  16r
Nov 28 11:21:00 radiusv3test slapd[7737]:
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: read active on 16
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: connection_get(16)
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: connection_get(16): got connid=1003
Nov 28 11:21:00 radiusv3test slapd[7737]: connection_read(16): checking for input on id=1003
Nov 28 11:21:00 radiusv3test slapd[7737]: connection_read(16): TLS accept failure error=-1 id=1003, closing
Nov 28 11:21:00 radiusv3test slapd[7737]: connection_closing: readying conn=1003 sd=16 for close
Nov 28 11:21:00 radiusv3test slapd[7737]: connection_close: conn=1003 sd=16
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: removing 16
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on 1 descriptor
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: activity on:
Nov 28 11:21:00 radiusv3test slapd[7737]:
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=7 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=10 active_threads=0 tvp=zero
Nov 28 11:21:00 radiusv3test slapd[7737]: daemon: epoll: listen=11 active_threads=0 tvp=zero

FreeRADIUS 3:
# ldd /usr/sbin/radiusd
        linux-vdso.so.1 =>  (0x00007fff8c1ff000)
        libfreeradius-server.so => /usr/lib64/freeradius/libfreeradius-server.so (0x00007f224b44b000)
        libfreeradius-radius.so => /usr/lib64/freeradius/libfreeradius-radius.so (0x00007f224b21b000)
        libfreeradius-eap.so => /usr/lib64/freeradius/libfreeradius-eap.so (0x00007f224b011000)
        libpcre.so.0 => /lib64/libpcre.so.0 (0x00007f224ade0000)
        libpcreposix.so.0 => /usr/lib64/libpcreposix.so.0 (0x00007f224abdd000)
        libtalloc.so.2 => /usr/lib64/libtalloc.so.2 (0x00007f224a9d3000)
        libcrypto.so.10 => /usr/lib64/libcrypto.so.10 (0x00007f224a639000)
        libssl.so.10 => /usr/lib64/libssl.so.10 (0x00007f224a3db000)
        libnsl.so.1 => /lib64/libnsl.so.1 (0x00007f224a1c2000)
        libresolv.so.2 => /lib64/libresolv.so.2 (0x00007f2249fa8000)
        libdl.so.2 => /lib64/libdl.so.2 (0x00007f2249da3000)
        libpthread.so.0 => /lib64/libpthread.so.0 (0x00007f2249b86000)
        libreadline.so.6 => /lib64/libreadline.so.6 (0x00007f2249943000)
        libcrypt.so.1 => /lib64/libcrypt.so.1 (0x00007f224970b000)
        libc.so.6 => /lib64/libc.so.6 (0x00007f2249378000)
        /lib64/ld-linux-x86-64.so.2 (0x00007f224b66d000)
        librt.so.1 => /lib64/librt.so.1 (0x00007f2249170000)
        libz.so.1 => /lib64/libz.so.1 (0x00007f2248f59000)
        libgssapi_krb5.so.2 => /lib64/libgssapi_krb5.so.2 (0x00007f2248d15000)
        libkrb5.so.3 => /lib64/libkrb5.so.3 (0x00007f2248a2f000)
        libcom_err.so.2 => /lib64/libcom_err.so.2 (0x00007f224882a000)
        libk5crypto.so.3 => /lib64/libk5crypto.so.3 (0x00007f22485fe000)
        libtinfo.so.5 => /lib64/libtinfo.so.5 (0x00007f22483dd000)
        libfreebl3.so => /lib64/libfreebl3.so (0x00007f2248170000)
        libkrb5support.so.0 => /lib64/libkrb5support.so.0 (0x00007f2247f65000)
        libkeyutils.so.1 => /lib64/libkeyutils.so.1 (0x00007f2247d62000)
        libselinux.so.1 => /lib64/libselinux.so.1 (0x00007f2247b42000)

FreeRADIUS v2.1.12 (default RPM from official CentOS Repo):
# ldd /usr/sbin/radiusd
        linux-vdso.so.1 =>  (0x00007fffa9980000)
        libfreeradius-radius-2.1.12.so => /usr/lib64/freeradius/libfreeradius-radius-2.1.12.so (0x00007fb0297b0000)
        libnsl.so.1 => /lib64/libnsl.so.1 (0x00007fb029591000)
        libresolv.so.2 => /lib64/libresolv.so.2 (0x00007fb029377000)
        libpthread.so.0 => /lib64/libpthread.so.0 (0x00007fb02915a000)
        libcrypt.so.1 => /lib64/libcrypt.so.1 (0x00007fb028f22000)
        libltdl.so.7 => /usr/lib64/libltdl.so.7 (0x00007fb028d19000)
        libssl.so.10 => /usr/lib64/libssl.so.10 (0x00007fb028abc000)
        libcrypto.so.10 => /usr/lib64/libcrypto.so.10 (0x00007fb028721000)
        libc.so.6 => /lib64/libc.so.6 (0x00007fb02838e000)
        /lib64/ld-linux-x86-64.so.2 (0x00007fb029c1e000)
        libfreebl3.so => /lib64/libfreebl3.so (0x00007fb028122000)
        libdl.so.2 => /lib64/libdl.so.2 (0x00007fb027f1d000)
        libgssapi_krb5.so.2 => /lib64/libgssapi_krb5.so.2 (0x00007fb027cd9000)
        libkrb5.so.3 => /lib64/libkrb5.so.3 (0x00007fb0279f3000)
        libcom_err.so.2 => /lib64/libcom_err.so.2 (0x00007fb0277ee000)
        libk5crypto.so.3 => /lib64/libk5crypto.so.3 (0x00007fb0275c2000)
        libz.so.1 => /lib64/libz.so.1 (0x00007fb0273ac000)
        libkrb5support.so.0 => /lib64/libkrb5support.so.0 (0x00007fb0271a0000)
        libkeyutils.so.1 => /lib64/libkeyutils.so.1 (0x00007fb026f9d000)
        libselinux.so.1 => /lib64/libselinux.so.1 (0x00007fb026d7d000)

Thanks in advance for any help and please let me know if further information is needed.

Kind regards,
Tobias Hachmer

rlm_ldap (ldap): Could not start TLS: Connect error

Hachmer, Tobias