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

Connection failures from OS X, appears to be TLS-related

I've been runing 2.2.26 on Ubuntu.  We had been having some odd
performance issues, so I opted to try upgrading to a from-source build
of 2.3.21.  The new server seems to work fine when queried using the
normal CLI utilities like "ldapsearch" and its kin, but fails when
queried from OS X's DirectoryService daemon.  This is what the
connection looks like using a loglevel of 512:

May  5 11:07:15 swozzle slapd[5697]: conn=0 fd=11 ACCEPT from
IP=150.253.42.41:49210 (IP=150.253.10.37:6666)
May  5 11:07:16 swozzle slapd[5697]: conn=0 fd=11 closed (TLS
negotiation failure)
May  5 11:07:16 swozzle slapd[5697]: conn=1 fd=11 ACCEPT from
IP=150.253.42.41:49211 (IP=150.253.10.37:6666)
May  5 11:07:16 swozzle slapd[5697]: conn=1 fd=11 TLS established
tls_ssf=256 ssf=256
May  5 11:07:16 swozzle slapd[5697]: conn=1 op=0 BIND dn="" method=128
May  5 11:07:16 swozzle slapd[5697]: conn=1 op=0 RESULT tag=97 err=0 text=
May  5 11:07:16 swozzle slapd[5697]: conn=1 op=1 SRCH base="" scope=0
deref=0 filter="(objectClass=*)"
May  5 11:07:16 swozzle slapd[5697]: conn=1 op=1 SRCH
attr=supportedSASLMechanisms
May  5 11:07:16 swozzle slapd[5697]: conn=1 op=1 SEARCH RESULT tag=101
err=0 nentries=1 text=
May  5 11:07:16 swozzle slapd[5697]: conn=1 op=2 UNBIND
May  5 11:07:16 swozzle slapd[5697]: conn=1 fd=11 closed
May  5 11:07:16 swozzle slapd[5697]: connection_read(11): no connection!

The part that makes me suspicious of TLS is the first "TLS negotiation
failure" entry.  That did not occur using the 2.2.26 build.

This is the configure string used to build OpenLDAP:

./configure --enable-syslog --enable-bdb --disable-hdb
--disable-monitor --disable-relay --enable-slurpd --with-cyrus-sasl
--with-threads --with-tls

And the TLS-specific arguments from slapd.conf:

swozzle:~ root# grep ^TLS /usr/local/etc/openldap/slapd.conf
TLSCertificateFile /etc/ssl/certs/mcad.edu.rapidssl.cert
TLSCertificateKeyFile /etc/ssl/private/mcad.edu.rapidssl.key
TLSVerifyClient never

More verbose logging of an attempted connection from OS X:

swozzle:~ root# /usr/local/libexec/slapd -d 525 -h 'ldaps://150.253.10.37:6666'

<startup stuff snipped>

daemon: activity on 1 descriptor
daemon: activity on:
daemon: listen=7, new connection on 11
ldap_pvt_gethostbyname_a: host=swozzle, r=0
daemon: added 11r
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on: 11r
daemon: read active on 11
connection_get(11)
connection_get(11): got connid=0
connection_read(11): checking for input on id=0
TLS trace: SSL_accept:before/accept initialization
TLS: can't accept.
connection_read(11): TLS accept failure error=-1 id=0, closing
connection_closing: readying conn=0 sd=11 for close
connection_close: conn=0 sd=11
daemon: removing 11
daemon: select: listen=7 active_threads=0 tvp=NULL
daemon: activity on 1 descriptor
daemon: activity on:
daemon: select: listen=7 active_threads=0 tvp=NULL
daemon: activity on 1 descriptor
daemon: activity on:
daemon: listen=7, new connection on 11
daemon: added 11r
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on: 11r
daemon: read active on 11
connection_get(11)
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
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on: 11r
daemon: read active on 11
connection_get(11)
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
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on: 11r
daemon: read active on 11
connection_get(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 12 contents:
ber_get_next
ber_get_next on fd 11 failed errno=11 (Resource temporarily unavailable)
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on:
daemon: select: listen=7 active_threads=1 tvp=zero
do_bind
ber_scanf fmt ({imt) ber:
ber_scanf fmt (m}) ber:
dnPrettyNormal: <> 
<<< dnPrettyNormal: <>, <>
do_bind: version=3 dn="" method=128
send_ldap_result: conn=1 op=0 p=3
send_ldap_result: err=0 matched="" text=""
send_ldap_response: msgid=1 tag=97 err=0
ber_flush: 14 bytes to sd 11
do_bind: v3 anonymous bind
daemon: activity on 1 descriptor
daemon: activity on: 11r
daemon: read active on 11
connection_get(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 62 contents:
ber_get_next
ber_get_next on fd 11 failed errno=11 (Resource temporarily unavailable)
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on:
daemon: select: listen=7 active_threads=1 tvp=zero
do_search
ber_scanf fmt ({miiiib) ber:
dnPrettyNormal: <> 
<<< dnPrettyNormal: <>, <>
SRCH "" 0 0    0 20 0
ber_scanf fmt (m) ber:
   filter: (objectClass=*)
ber_scanf fmt ({M}}) ber:
   attrs: supportedSASLMechanisms
=> send_search_entry: conn 1 dn=""
ber_flush: 87 bytes to sd 11
conn=1 op=1 ENTRY dn=""
<= send_search_entry: conn 1 exit.
send_ldap_result: conn=1 op=1 p=3
send_ldap_result: err=0 matched="" text=""
send_ldap_response: msgid=2 tag=101 err=0
ber_flush: 14 bytes to sd 11
daemon: activity on 1 descriptor
daemon: activity on: 11r
daemon: read active on 11
connection_get(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 (Success)
connection_read(11): input error=-2 id=1, closing.
connection_closing: readying conn=1 sd=11 for close
connection_close: deferring conn=1 sd=11
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on:
daemon: select: listen=7 active_threads=1 tvp=zero
do_unbind
connection_resched: attempting closing conn=1 sd=11
connection_close: conn=1 sd=11
TLS trace: SSL3 alert write:warning:close notify
daemon: activity on 1 descriptor
daemon: activity on:
daemon: read active on 11
daemon: removing 11
connection_get(11)
connection_get(11): connection not used
connection_read(11): no connection!
daemon: select: listen=7 active_threads=0 tvp=NULL
daemon: activity on 1 descriptor
daemon: activity on:
daemon: listen=7, new connection on 11
daemon: added 11r
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on: 11r
daemon: read active on 11
connection_get(11)
connection_get(11): got connid=2
connection_read(11): checking for input on id=2
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
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on: 11r
daemon: read active on 11
connection_get(11)
connection_get(11): got connid=2
connection_read(11): checking for input on id=2
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=2
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on: 11r
daemon: read active on 11
connection_get(11)
connection_get(11): got connid=2
connection_read(11): checking for input on id=2
ber_get_next
ber_get_next: tag 0x30 len 22 contents:
ber_get_next
ber_get_next on fd 11 failed errno=11 (Resource temporarily unavailable)
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on:
daemon: select: listen=7 active_threads=1 tvp=zero
do_bind
ber_scanf fmt ({imt) ber:
ber_scanf fmt ({m) ber:
ber_scanf fmt (}}) ber:
dnPrettyNormal: <> 
<<< dnPrettyNormal: <>, <>
do_sasl_bind: dn () mech CRAM-MD5
==> sasl_bind: dn="" mech=CRAM-MD5 datalen=0
send_ldap_sasl: err=14 len=42
send_ldap_response: msgid=1 tag=97 err=14
ber_flush: 58 bytes to sd 11
<== slap_sasl_bind: rc=14
daemon: activity on 1 descriptor
daemon: activity on: 11r
daemon: read active on 11
connection_get(11)
connection_get(11): got connid=2
connection_read(11): checking for input on id=2
ber_get_next
ber_get_next: tag 0x30 len 65 contents:
ber_get_next
ber_get_next on fd 11 failed errno=11 (Resource temporarily unavailable)
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on:
daemon: select: listen=7 active_threads=1 tvp=zero
do_bind
ber_scanf fmt ({imt) ber:
ber_scanf fmt ({m) ber:
ber_scanf fmt (m) ber:
ber_scanf fmt (}}) ber:
dnPrettyNormal: <> 
<<< dnPrettyNormal: <>, <>
do_sasl_bind: dn () mech CRAM-MD5
==> sasl_bind: dn="" mech=<continuing> datalen=41
SASL Canonicalize [conn=2]: authcid="osxproxy"
slap_sasl_getdn: conn 2 id=osxproxy [len=8]
=> ldap_dn2bv(16)
<= ldap_dn2bv(uid=osxproxy,cn=CRAM-MD5,cn=auth)=0
slap_sasl_getdn: u:id converted to uid=osxproxy,cn=CRAM-MD5,cn=auth
dnNormalize: <uid=osxproxy,cn=CRAM-MD5,cn=auth> 
=> ldap_bv2dn(uid=osxproxy,cn=CRAM-MD5,cn=auth,0)
<= ldap_bv2dn(uid=osxproxy,cn=CRAM-MD5,cn=auth)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(uid=osxproxy,cn=cram-md5,cn=auth)=0
<<< dnNormalize: <uid=osxproxy,cn=cram-md5,cn=auth>
==>slap_sasl2dn: converting SASL name uid=osxproxy,cn=cram-md5,cn=auth to a DN
slap_authz_regexp: converting SASL name uid=osxproxy,cn=cram-md5,cn=auth
<==slap_sasl2dn: Converted SASL name to <nothing>
SASL Canonicalize [conn=2]: slapAuthcDN="uid=osxproxy,cn=cram-md5,cn=auth"
SASL [conn=2] Failure: no secret in database
send_ldap_result: conn=2 op=1 p=3
send_ldap_result: err=49 matched="" text="SASL(-13): user not found:
no secret in database"
send_ldap_response: msgid=2 tag=97 err=49
ber_flush: 62 bytes to sd 11
<== slap_sasl_bind: rc=49

<shutting down daemon by hitting ctrl-c>

daemon: shutdown requested and initiated.
daemon: closing 7
connection_closing: readying conn=2 sd=11 for close
connection_close: conn=2 sd=11
TLS trace: SSL3 alert write:warning:close notify
daemon: removing 11
slapd shutdown: waiting for 0 threads to terminate
slapd shutdown: initiated
====> bdb_cache_release_all
slapd destroy: freeing system resources.
slapd stopped.



Note that the SASL failure is expected, as we have LDAPv3 enabled on
the clients (as they won't let us turn on SSL otherwise) but we do not
store plaintext passwords in the directory.  On the 2.2.26 build of
slapd, a failed SASL bind was followed immediately by a successful
simple bind.

Any ideas what may be going wrong?

Thanks!

-Ben