Replication Failing with TLS ... Sneaky Little Config Error

I have set up OpenLDAP per the nice tutorial at https://help.ubuntu.com/lts/serverguide/openldap-server.html and on my previous run-throughs, I succeeded at setting up replication via TLS. But now that I'm implementing on the dedicated hardware, I am not able to replicate via TLS.

SOLUTION: It turns out the solution was to add a space to an LDIF file ...

On PROVIDER I will see, for example:

Mar 14 16:13:15 ldap0 slapd[1536]: conn=1392 fd=49 ACCEPT from IP=10.10.3.117:60277 (IP=0.0.0.0:389)
Mar 14 16:13:15 ldap0 slapd[1536]: conn=1392 op=0 BIND dn="" method=128
Mar 14 16:13:15 ldap0 slapd[1536]: conn=1392 op=0 RESULT tag=97 err=0 text=
Mar 14 16:13:15 ldap0 slapd[1536]: conn=1392 op=1 SRCH base="dc=qxxxxxxxxd,dc=com" scope=2 deref=0 filter="(&(objectClass=posixAccount)(uidNumber=2043))"
Mar 14 16:13:15 ldap0 slapd[1536]: conn=1392 op=1 SRCH attr=uid userPassword uidNumber gidNumber cn homeDirectory loginShell gecos description objectClass
Mar 14 16:13:15 ldap0 slapd[1536]: <= bdb_equality_candidates: (uidNumber) not indexed
Mar 14 16:13:15 ldap0 slapd[1536]: conn=1392 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text=
Mar 14 16:13:15 ldap0 slapd[1536]: conn=1392 op=2 SRCH base="dc=qxxxxxxxxd,dc=com" scope=2 deref=0 filter="(&(objectClass=posixAccount)(uid=djh))"
Mar 14 16:13:15 ldap0 slapd[1536]: conn=1392 op=2 SRCH attr=uid userPassword uidNumber gidNumber cn homeDirectory loginShell gecos description objectClass
Mar 14 16:13:15 ldap0 slapd[1536]: conn=1392 op=2 SEARCH RESULT tag=101 err=0 nentries=1 text=
Mar 14 16:13:16 ldap0 slapd[1536]: conn=1392 op=3 UNBIND

While on CONSUMER:

Mar 14 16:13:15 ldap1 slapd[3672]: @(#) $OpenLDAP: slapd (Ubuntu) (Sep 15 2015 18:19:13) $#012#011buildd@lgw01-53:/build/openldap-2QUgtL/openldap-2.4.31/debian/build/servers/slapd
Mar 14 16:13:16 ldap1 slapd[3673]: slapd starting
Mar 14 16:13:16 ldap1 slapd[3673]: do_syncrepl: rid=317 rc -1 retrying
Mar 14 16:13:16 ldap1 sudo: pam_unix(sudo:session): session closed for user root
Mar 14 16:13:23 ldap1 slapd[3673]: conn=1000 fd=13 ACCEPT from IP=10.10.5.3:15197 (IP=0.0.0.0:389)
Mar 14 16:13:23 ldap1 slapd[3673]: conn=1000 fd=13 closed (connection lost)

I *CAN* to TLS from consumer to master:

0-16:18 djh@ldap1 ~$ ldapsearch -LLL -x -ZZ -H ldap://ldap0.mtv.qxxxxxxxxd.com uid=djh cn
dn: uid=djh,ou=People,dc=qxxxxxxxxd,dc=com
cn: djh

So, I increase olcLogLevel to add sync:

Mar 14 16:22:09 ldap1 slapd[4133]: @(#) $OpenLDAP: slapd (Ubuntu) (Sep 15 2015 18:19:13) $#012#011buildd@lgw01-53:/build/openldap-2QUgtL/openldap-2.4.31/debian/build/servers/slapd
Mar 14 16:22:10 ldap1 slapd[4134]: slapd starting
Mar 14 16:22:10 ldap1 sudo: pam_unix(sudo:session): session closed for user root
Mar 14 16:22:10 ldap1 slapd[4134]: do_syncrep2: rid=317 cookie=rid=317,csn=20160314224255.836334Z#000000#000#000000
Mar 14 16:22:10 ldap1 slapd[4134]: slap_queue_csn: queing 0x7f0c5c114995 20160314224255.836334Z#000000#000#000000
Mar 14 16:22:10 ldap1 slapd[4134]: slap_graduate_commit_csn: removing 0x7f0c5c114d10 20160314224255.836334Z#000000#000#000000
Mar 14 16:22:10 ldap1 slapd[4134]: do_syncrepl: rid=317 rc -1 retrying

THAT is the contextCSN on the provider!

0-16:24 djh@ldap0 ~$ ldapsearch -z1 -LLLQY EXTERNAL -H ldapi:/// -s base -b dc=qxxxxxxxxd,dc=com contextCSN # provider
dn: dc=qxxxxxxxxd,dc=com
contextCSN: 20160314224255.836334Z#000000#000#000000

0-16:22 djh@ldap1 ~$ ldapsearch -z1 -LLLQY EXTERNAL -H ldapi:/// -s base -b dc=qxxxxxxxxd,dc=com contextCSN # consumer
dn: dc=qxxxxxxxxd,dc=com
contextCSN: 20160314224152.708568Z#000000#000#000000

As best I can tell, the connection works, the replication works, but the consumer is not asking for TLS.

0-16:29 djh@ldap1 ~$ sudo ldapsearch -Q -Y EXTERNAL -H ldapi:/// -LLL -b cn=config olcDatabase={1}hdb olcSyncRepl
dn: olcDatabase={1}hdb,cn=config
olcSyncrepl: {0}rid=317 provider=ldap://ldap0.mtv.qxxxxxxxxd.com bindmethod=si
mple binddn="cn=admin,dc=qxxxxxxxxd,dc=com" credentials=secret searchbase
="dc=qxxxxxxxxd,dc=com" logbase="cn=accesslog" logfilter="(&(objectClass=audi
tWriteObject)(reqResult=0))" schemachecking=on type=refreshAndPersist retry="
60 +" syncdata=accesslogstarttls=critical tls_reqcert=demand

If I rip out starttls=critical tls_reqcert=demand then sync works no problem.

If I enable logging on the PROVIDER I see:

Mar 14 16:35:46 ldap0 slapd[6838]: @(#) $OpenLDAP: slapd (Ubuntu) (Sep 15 2015 18:19:13) $#012#011buildd@lgw01-53:/build/openldap-2QUgtL/openldap-2.4.31/debian/build/servers/slapd
Mar 14 16:35:46 ldap0 slapd[6839]: slapd starting
Mar 14 16:35:46 ldap0 sudo: pam_unix(sudo:session): session closed for user root
Mar 14 16:35:49 ldap0 slapd[6839]: conn=1000 fd=27 ACCEPT from IP=10.10.5.3:17876 (IP=0.0.0.0:389)
Mar 14 16:35:49 ldap0 slapd[6839]: conn=1000 fd=27 closed (connection lost)
Mar 14 16:35:55 ldap0 slapd[6839]: conn=1001 fd=27 ACCEPT from IP=10.10.3.117:60312 (IP=0.0.0.0:389)
Mar 14 16:35:55 ldap0 slapd[6839]: conn=1001 op=0 BIND dn="cn=admin,dc=qxxxxxxxxd,dc=com" method=128
Mar 14 16:35:55 ldap0 slapd[6839]: conn=1001 op=0 BIND dn="cn=admin,dc=qxxxxxxxxd,dc=com" mech=SIMPLE ssf=0
Mar 14 16:35:55 ldap0 slapd[6839]: conn=1001 op=0 RESULT tag=97 err=0 text=
Mar 14 16:35:55 ldap0 slapd[6839]: conn=1001 op=1 SRCH base="cn=accesslog" scope=2 deref=0 filter="(&(objectClass=auditWriteObject)(reqResult=0))"
Mar 14 16:35:55 ldap0 slapd[6839]: conn=1001 op=1 SRCH attr=targetDN changeType changes newRDN deleteOldRDN newSuperior entryCSN
Mar 14 16:35:55 ldap0 slapd[6839]: Entry reqStart=20160314224152.000005Z,cn=accesslog CSN 20160314224152.708568Z#000000#000#000000 older or equal to ctx 20160314224152.708568Z#000000#000#000000
Mar 14 16:35:55 ldap0 slapd[6839]: syncprov_search_response: cookie=rid=317,csn=20160314224255.836334Z#000000#000#000000
Mar 14 16:35:55 ldap0 slapd[6839]: conn=1001 op=2 UNBIND
Mar 14 16:35:55 ldap0 slapd[6839]: conn=1001 fd=27 closed

So .......... it looks like ... sync works until it doesn't because ... we're not binding consumer to provider TLS because .. ?

WAIT A GOSH DARN SECOND HERE ....

0-16:41 djh@ldap1 ~$ sudo ldapsearch -Q -Y EXTERNAL -H ldapi:/// -LLL -b cn=config olcDatabase={1}hdb olcSyncRepl
dn: olcDatabase={1}hdb,cn=config
olcSyncrepl: {0}rid=317 provider=ldap://ldap0.mtv.qxxxxxxxxd.com bindmethod=si
mple binddn="cn=admin,dc=qxxxxxxxxd,dc=com" credentials=secret searchbase
="dc=qxxxxxxxxd,dc=com" logbase="cn=accesslog" logfilter="(&(objectClass=audi
tWriteObject)(reqResult=0))" schemachecking=on type=refreshAndPersist retry="
60 +" syncdata=accesslogstarttls=critical tls_reqcert=demand

Yeah ...

0-16:43 djh@ldap1 ~$ cat consumer_sync_tls.ldif
dn: olcDatabase={1}hdb,cn=config
replace: olcSyncRepl
olcSyncRepl: rid=317 provider=ldap://ldap0.mtv.qxxxxxxxxd.com bindmethod=simple binddn="cn=admin,dc=qxxxxxxxxd,dc=com"
credentials=secret searchbase="dc=qxxxxxxxxd,dc=com" logbase="cn=accesslog"
logfilter="(&(objectClass=auditWriteObject)(reqResult=0))" schemachecking=on
type=refreshAndPersist retry="60 +" syncdata=accesslog
starttls=critical tls_reqcert=demand

0-16:43 djh@ldap1 ~$ sudo ldapmodify -Y EXTERNAL -H ldapi:/// -f consumer_sync_tls.ldif
SASL/EXTERNAL authentication started
SASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth
SASL SSF: 0
modifying entry "olcDatabase={1}hdb,cn=config"

No errors ...

*edit consumer_sync_tls.ldif, add a space to the end of the line ending in syncdata=accesslog*

0-16:45 djh@ldap1 ~$ sudo ldapmodify -Y EXTERNAL -H ldapi:/// -f consumer_sync_tls.ldif
SASL/EXTERNAL authentication started
SASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth
SASL SSF: 0
modifying entry "olcDatabase={1}hdb,cn=config"

Same result, no errors, aaand:

0-16:46 djh@ldap1 ~$ ldapsearch -z1 -LLLQY EXTERNAL -H ldapi:/// -s base -b dc=qxxxxxxxxd,dc=com contextCSN # consumer
dn: dc=qxxxxxxxxd,dc=com
contextCSN: 20160314224255.836334Z#000000#000#000000

Well, I just paid some dues.

I want to add olcLogLevel config perhaps? Would that have helped me here?

Thanks ...

-danny

http://dannyman.toldme.com