Ok... so I thought I was losing my mind. I had seen it fail before, and then shortly after posting this message, found it was working.

However, running with olcLogLevel = sync, I see this in the ldap log:

Feb 2 15:32:55 zoot slapd[10509]: slapd starting Feb 2 15:32:55 zoot slapd[10509]: slap_client_connect: URI=ldaps://animal.clarku.edu DN="cn=config" ldap_sasl_bind_s failed (-1)

But I can make changes to one machine and see them go to the other, and the syncrepl lines are clearly not asking for sasl.

From: Aaron Bennett Sent: Thursday, February 02, 2012 3:15 PM To: Aaron Bennett; openldap-technical@openldap.org Subject: RE: 2.4.28 cn=config replication trouble

I'm sorry for wasting your time - this is working after all.

From: openldap-technical-bounces@OpenLDAP.orgmailto:openldap-technical-bounces@OpenLDAP.org [mailto:openldap-technical-bounces@OpenLDAP.org]mailto:[mailto:openldap-technical-bounces@OpenLDAP.org] On Behalf Of Aaron Bennett Sent: Thursday, February 02, 2012 2:20 PM To: openldap-technical@openldap.orgmailto:openldap-technical@openldap.org Subject: 2.4.28 cn=config replication trouble

Hello,

I've got two 2.4.28 boxes and I'm trying to get two-way multimaster replication set up - first for cn=config, and then for the entire tree.

I can attach more of config.ldif if needed, but here are what I think are the relevant snippets:

First thing that leaps out is, of course, the certificate is for ds.clarku.edu and the hosts are called animal.clarku.edu and zoot.clarku.edu; that's needed because I intend to round-robin those two hosts. I have TLS_REQCERT never in ldap.conf on each machine and I can do a successful "ldapsearch -H ldaps://animal.clarku.edu -x -D "cn=config" -W -b cn=config" from each machine to the other.

dn: cn=config objectClass: olcGlobal cn: config olcAllows: bind_v2 olcArgsFile: /var/run/openldap/slapd.args olcAttributeOptions: lang- olcAuthzPolicy: none olcConcurrency: 25 olcConfigDir: /etc/openldap/ldap/slapd.d olcConfigFile: /etc/openldap/slapd.conf olcConnMaxPending: 400 olcConnMaxPendingAuth: 1000 olcGentleHUP: FALSE olcIdleTimeout: 0 olcIndexIntLen: 4 olcIndexSubstrAnyLen: 4 olcIndexSubstrAnyStep: 2 olcIndexSubstrIfMaxLen: 4 olcIndexSubstrIfMinLen: 2 olcLocalSSF: 71 olcLogLevel: stats sync olcPidFile: /var/run/openldap/slapd.pid olcReadOnly: FALSE olcReverseLookup: FALSE olcServerID: 1 ldaps://animal.clarku.edu olcServerID: 2 ldaps://zoot.clarku.edu olcSockbufMaxIncoming: 262143 olcSockbufMaxIncomingAuth: 16777215 olcThreads: 25 olcTLSCACertificatePath: /etc/openldap/nssdb olcTLSCertificateFile: ds.clarku.edu olcTLSVerifyClient: never olcToolThreads: 1 olcWriteTimeout: 0

dn: olcDatabase={0}config,cn=config objectClass: olcDatabaseConfig olcDatabase: {0}config olcAccess: {0}to * by * none olcAddContentAcl: TRUE olcLastMod: TRUE olcMaxDerefDepth: 15 olcMirrorMode: TRUE olcMonitoring: FALSE olcReadOnly: FALSE olcRootDN: cn=config olcRootPW: {SSHA}<PASSWORD> olcSyncrepl: {0}rid=001 provider=ldaps://animal.clarku.edu binddn="cn=config " bindmethod="simple" credentials="<PASSWORD>" searchbase="cn=config" type= refreshAndPersist retry="5 5 300 5" timeout=1 olcSyncrepl: {1}rid=002 provider=ldaps://zoot.clarku.edu binddn="cn=config" bindmethod="simple" credentials="<PASSWORD>" searchbase="cn=config" type=r efreshAndPersist retry="5 5 300 5" timeout=1

Here's the -d1 output: 4f2ae081 do_syncrepl: rid=001 rc -1 retrying (4 retries left) 4f2ae081 slap_listener_activate(9): 4f2ae081 >>> slap_listener(ldaps:///) 4f2ae081 connection_get(15): got connid=1000 4f2ae081 connection_read(15): checking for input on id=1000 TLS: using moznss security dir /etc/openldap/nssdb prefix . TLS: certificate [CN=ds.clarku.edu,OU=ITS,O=Clark University,L=Worcester,ST=Massachusetts,C=US,serialNumber=HUpyuTQIxJ8ShXHOBGZo7j-BC9l4ykNA] is valid 4f2ae081 connection_get(15): got connid=1000 4f2ae081 connection_read(15): checking for input on id=1000 TLS certificate verification: subject: no certificate, issuer: no certificate, cipher: AES-256, security level: high, secret key bits: 256, total key bits: 256, cache hits: 0, cache misses: 1, cache not reusable: 0 4f2ae081 connection_read(15): unable to get TLS client DN, error=49 id=1000 4f2ae081 connection_get(15): got connid=1000 4f2ae081 connection_read(15): checking for input on id=1000 ber_get_next 4f2ae081 ber_get_next on fd 15 failed errno=0 (Success) 4f2ae081 connection_close: conn=1000 sd=15 4f2ae086 =>do_syncrepl rid=001 ldap_create ldap_url_parse_ext(ldaps://animal.clarku.edu) ldap_sasl_bind_s ldap_sasl_bind ldap_send_initial_request ldap_new_connection 1 1 0 ldap_int_open_connection ldap_connect_to_host: TCP animal.clarku.edu:636 4f2ae086 slap_listener_activate(9): 4f2ae086 >>> slap_listener(ldaps:///) 4f2ae086 connection_get(18): got connid=1001 4f2ae086 connection_read(18): checking for input on id=1001 ldap_new_socket: 15 ldap_prepare_socket: 15 ldap_connect_to_host: Trying 140.232.1.12:636 ldap_pvt_connect: fd: 15 tm: -1 async: 0 4f2ae086 connection_get(18): got connid=1001 4f2ae086 connection_read(18): checking for input on id=1001 TLS certificate verification: subject: no certificate, issuer: no certificate, cipher: AES-256, security level: high, secret key bits: 256, total key bits: 256, cache hits: 0, cache misses: 2, cache not reusable: 0 4f2ae086 connection_read(18): unable to get TLS client DN, error=49 id=1001 4f2ae086 connection_get(18): got connid=1001 4f2ae086 connection_read(18): checking for input on id=1001 ber_get_next ber_get_next: tag 0x30 len 31 contents: 4f2ae086 op tag 0x60, time 1328210054 ber_get_next 4f2ae086 conn=1001 op=0 do_bind ber_scanf fmt ({imt) ber: ber_scanf fmt (m}) ber: 4f2ae086 >>> dnPrettyNormal: <cn=config> 4f2ae086 <<< dnPrettyNormal: <cn=config>, <cn=config> 4f2ae086 do_bind: version=3 dn="cn=config" method=128 4f2ae086 do_bind: v3 bind: "cn=config" to "cn=config" 4f2ae086 send_ldap_result: conn=1001 op=0 p=3 4f2ae086 send_ldap_response: msgid=1 tag=97 err=0 ber_flush2: 14 bytes to sd 18 4f2ae086 connection_get(18): got connid=1001 4f2ae086 connection_read(18): checking for input on id=1001 ber_get_next ber_get_next: tag 0x30 len 185 contents: 4f2ae086 op tag 0x63, time 1328210054 ber_get_next 4f2ae086 conn=1001 op=1 do_search ber_scanf fmt ({miiiib) ber: 4f2ae086 >>> dnPrettyNormal: <cn=config> 4f2ae086 <<< dnPrettyNormal: <cn=config>, <cn=config> ber_scanf fmt (m) ber: ber_scanf fmt ({M}}) ber: 4f2ae086 => get_ctrls ber_scanf fmt ({m) ber: ber_scanf fmt (m) ber: 4f2ae086 => get_ctrls: oid="1.3.6.1.4.1.4203.1.9.1.1" (noncritical) ber_scanf fmt ({i) ber: ber_scanf fmt (m) ber: ber_scanf fmt (b) ber: ber_scanf fmt (}) ber: ber_scanf fmt ({m) ber: ber_scanf fmt (b) ber: 4f2ae086 => get_ctrls: oid="2.16.840.1.113730.3.4.2" (critical) 4f2ae086 <= get_ctrls: n=2 rc=0 err="" 4f2ae086 send_ldap_result: conn=1001 op=1 p=3 4f2ae086 send_ldap_result: conn=1001 op=1 p=3 4f2ae086 send_ldap_intermediate: err=0 oid=1.3.6.1.4.1.4203.1.9.1.4 len=2 4f2ae086 send_ldap_response: msgid=2 tag=121 err=0 ber_flush2: 37 bytes to sd 18 TLS: certificate [CN=ds.clarku.edu,OU=ITS,O=Clark University,L=Worcester,ST=Massachusetts,C=US,serialNumber=HUpyuTQIxJ8ShXHOBGZo7j-BC9l4ykNA] is valid TLS certificate verification: subject: CN=ds.clarku.edu,OU=ITS,O=Clark University,L=Worcester,ST=Massachusetts,C=US,serialNumber=HUpyuTQIxJ8ShXHOBGZo7j-BC9l4ykNA, issuer: CN=GeoTrust SSL CA,O="GeoTrust, Inc.",C=US, cipher: AES-256, security level: high, secret key bits: 256, total key bits: 256, cache hits: 0, cache misses: 2, cache not reusable: 0 ldap_open_defconn: successful ldap_send_server_request ber_scanf fmt ({it) ber: ber_scanf fmt ({i) ber: ber_flush2: 33 bytes to sd 15 ldap_result ld 0x7f59cc100910 msgid 1 wait4msg ld 0x7f59cc100910 msgid 1 (timeout 1000000 usec) wait4msg continue ld 0x7f59cc100910 msgid 1 all 1 ** ld 0x7f59cc100910 Connections: * host: animal.clarku.edu port: 636 (default) refcnt: 2 status: Connected last used: Thu Feb 2 14:14:14 2012

** ld 0x7f59cc100910 Outstanding Requests: * msgid 1, origid 1, status InProgress outstanding referrals 0, parent count 0 ld 0x7f59cc100910 request count 1 (abandoned 0) ** ld 0x7f59cc100910 Response Queue: Empty ld 0x7f59cc100910 response count 0 ldap_chkResponseList ld 0x7f59cc100910 msgid 1 all 1 ldap_chkResponseList returns ld 0x7f59cc100910 NULL ldap_int_select read1msg: ld 0x7f59cc100910 msgid 1 all 1 ber_get_next ber_get_next: tag 0x30 len 12 contents: read1msg: ld 0x7f59cc100910 msgid 1 message type bind ber_scanf fmt ({eAA) ber: read1msg: ld 0x7f59cc100910 0 new referrals read1msg: mark request completed, ld 0x7f59cc100910 msgid 1 request done: ld 0x7f59cc100910 msgid 1 res_errno: 0, res_error: <>, res_matched: <> ldap_free_request (origid 1, msgid 1) ldap_parse_result ber_scanf fmt ({iAA) ber: ber_scanf fmt (}) ber: ldap_msgfree ldap_search_ext put_filter: "(objectclass=*)" put_filter: simple put_simple_filter: "objectclass=*" ldap_send_initial_request ldap_send_server_request ber_scanf fmt ({it) ber: ber_scanf fmt ({) ber: ber_flush2: 188 bytes to sd 15 4f2ae086 =>do_syncrep2 rid=001 ldap_result ld 0x7f59cc100910 msgid 2 wait4msg ld 0x7f59cc100910 msgid 2 (timeout 1000000 usec) wait4msg continue ld 0x7f59cc100910 msgid 2 all 0 ** ld 0x7f59cc100910 Connections: * host: animal.clarku.edu port: 636 (default) refcnt: 2 status: Connected last used: Thu Feb 2 14:14:14 2012

** ld 0x7f59cc100910 Outstanding Requests: * msgid 2, origid 2, status InProgress outstanding referrals 0, parent count 0 ld 0x7f59cc100910 request count 1 (abandoned 0) ** ld 0x7f59cc100910 Response Queue: Empty ld 0x7f59cc100910 response count 0 ldap_chkResponseList ld 0x7f59cc100910 msgid 2 all 0 ldap_chkResponseList returns ld 0x7f59cc100910 NULL ldap_int_select read1msg: ld 0x7f59cc100910 msgid 2 all 0 ber_get_next ber_get_next: tag 0x30 len 35 contents: read1msg: ld 0x7f59cc100910 msgid 2 message type intermediate ldap_parse_intermediate ber_scanf fmt ({) ber: ber_scanf fmt (a) ber: ber_scanf fmt (O) ber: ber_scanf fmt (t{) ber: ber_scanf fmt (}) ber: ldap_msgfree ldap_result ld 0x7f59cc100910 msgid 2 wait4msg ld 0x7f59cc100910 msgid 2 (timeout 0 usec) wait4msg continue ld 0x7f59cc100910 msgid 2 all 0 ** ld 0x7f59cc100910 Connections: * host: animal.clarku.edu port: 636 (default) refcnt: 2 status: Connected last used: Thu Feb 2 14:14:14 2012

** ld 0x7f59cc100910 Outstanding Requests: * msgid 2, origid 2, status InProgress outstanding referrals 0, parent count 0 ld 0x7f59cc100910 request count 1 (abandoned 0) ** ld 0x7f59cc100910 Response Queue: Empty ld 0x7f59cc100910 response count 0 ldap_chkResponseList ld 0x7f59cc100910 msgid 2 all 0 ldap_chkResponseList returns ld 0x7f59cc100910 NULL ldap_int_select 4f2ae08a connection_get(15): got connid=0 4f2ae08a =>do_syncrepl rid=001 4f2ae08a =>do_syncrep2 rid=001 ldap_result ld 0x7f59cc100910 msgid 2 wait4msg ld 0x7f59cc100910 msgid 2 (timeout 0 usec) wait4msg continue ld 0x7f59cc100910 msgid 2 all 0 ** ld 0x7f59cc100910 Connections: * host: animal.clarku.edu port: 636 (default) refcnt: 2 status: Connected last used: Thu Feb 2 14:14:14 2012

** ld 0x7f59cc100910 Outstanding Requests: * msgid 2, origid 2, status InProgress outstanding referrals 0, parent count 0 ld 0x7f59cc100910 request count 1 (abandoned 0) ** ld 0x7f59cc100910 Response Queue: Empty ld 0x7f59cc100910 response count 0 ldap_chkResponseList ld 0x7f59cc100910 msgid 2 all 0 ldap_chkResponseList returns ld 0x7f59cc100910 NULL ldap_int_select read1msg: ld 0x7f59cc100910 msgid 2 all 0 ber_get_next ldap_err2string 4f2ae08a do_syncrep2: rid=001 (-1) Can't contact LDAP server ldap_err2string 4f2ae08a connection_get(15): got connid=0 ldap_free_request (origid 2, msgid 2) ldap_free_connection 1 1 ldap_free_connection: actually freed

Thanks for your time - any help is appreciated.

- Aaron

--- Aaron Bennett Manager of Systems Administration Clark University ITS

-----Original Message----- From: Quanah Gibson-Mount [mailto:quanah@zimbra.com] Sent: Thursday, February 02, 2012 4:02 PM To: Aaron Bennett; openldap-technical@openldap.org Subject: RE: 2.4.28 cn=config replication trouble

All binds are SASL binds. You're probably using SASL SIMPLE, which most people don't think of as "SASL" when compared to things like SASL GSSAPI or SASL DIGEST-MD5.

--Quanah

Quanah -- thank you. I am in fact using bindmethod=simple, which I did not realize meant SASL SIMPLE.

I still don't understand why, although replication is working, I see all these sasl bind fails in the sync log:

Feb 2 15:55:33 animal slapd[9301]: slap_client_connect: URI=ldaps://zoot.clarku.edu DN="cn=config" ldap_sasl_bind_s failed (-1)

Do you need to see -d1 output?

Thanks for your time,

Aaron

-----Original Message----- From: Quanah Gibson-Mount [mailto:quanah@zimbra.com] Sent: Thursday, February 02, 2012 5:03 PM To: Aaron Bennett; openldap-technical@openldap.org Subject: RE: 2.4.28 cn=config replication trouble

Let me correct that. All binds use the ldap_sasl_bind_s function, but a simple bind isn't specifically a SASL bind. In any case, your consumer clearly is unable to bind to the master to replicate one of the configurations you've configured, most likely for the cn=config replication bit, given that the bind DN for it is cn=config.

I know, I inititially thought so, too... but the servers are replicating. If you look at the output with logging set to "stats sync", here's what happens on each box immediately after slapd starts:

Feb 3 09:41:58 animal slapd[28953]: slapd starting Feb 3 09:41:58 animal slapd[28953]: slap_client_connect: URI=ldaps://zoot.clarku.edu DN="cn=replicator,ou=services,dc=clarku,dc=edu" ldap_sasl_bind_s failed (-1) Feb 3 09:41:58 animal slapd[28953]: slap_client_connect: URI=ldaps://zoot.clarku.edu DN="cn=config" ldap_sasl_bind_s failed (-1) Feb 3 09:41:58 animal slapd[28953]: do_syncrepl: rid=002 rc -1 retrying (4 retries left) Feb 3 09:41:58 animal slapd[28953]: do_syncrepl: rid=002 rc -1 retrying (4 retries left) Feb 3 09:42:03 animal slapd[28953]: conn=1000 fd=19 ACCEPT from IP=140.232.1.15:53074 (IP=0.0.0.0:636) Feb 3 09:42:03 animal slapd[28953]: conn=1001 fd=20 ACCEPT from IP=140.232.1.15:53075 (IP=0.0.0.0:636) Feb 3 09:42:03 animal slapd[28953]: do_syncrep2: rid=002 LDAP_RES_INTERMEDIATE - REFRESH_DELETE Feb 3 09:42:03 animal slapd[28953]: do_syncrep2: rid=002 LDAP_RES_INTERMEDIATE - REFRESH_DELETE Feb 3 09:42:03 animal slapd[28953]: conn=1001 fd=20 TLS established tls_ssf=256 ssf=256 Feb 3 09:42:03 animal slapd[28953]: conn=1000 fd=19 TLS established tls_ssf=256 ssf=256 Feb 3 09:42:03 animal slapd[28953]: conn=1001 op=0 BIND dn="cn=config" method=128 Feb 3 09:42:03 animal slapd[28953]: conn=1001 op=0 BIND dn="cn=config" mech=SIMPLE ssf=0 Feb 3 09:42:03 animal slapd[28953]: conn=1000 op=0 BIND dn="cn=replicator,ou=services,dc=clarku,dc=edu" method=128 Feb 3 09:42:03 animal slapd[28953]: conn=1001 op=0 RESULT tag=97 err=0 text= Feb 3 09:42:03 animal slapd[28953]: conn=1000 op=0 BIND dn="cn=Replicator,ou=Services,dc=clarku,dc=edu" mech=SIMPLE ssf=0

And the other box during that sequence:

Feb 3 09:41:58 zoot slapd[3321]: conn=1008 fd=13 ACCEPT from IP=140.232.1.12:37620 (IP=0.0.0.0:636) Feb 3 09:41:58 zoot slapd[3321]: conn=1009 fd=16 ACCEPT from IP=140.232.1.12:37621 (IP=0.0.0.0:636) Feb 3 09:41:58 zoot slapd[3321]: conn=1009 fd=16 TLS established tls_ssf=256 ssf=256 Feb 3 09:41:58 zoot slapd[3321]: conn=1008 fd=13 TLS established tls_ssf=256 ssf=256 Feb 3 09:41:58 zoot slapd[3321]: conn=1009 fd=16 closed (connection lost) Feb 3 09:41:58 zoot slapd[3321]: conn=1008 fd=13 closed (connection lost) Feb 3 09:42:03 zoot slapd[3321]: conn=1010 fd=19 ACCEPT from IP=140.232.1.12:37622 (IP=0.0.0.0:636) Feb 3 09:42:03 zoot slapd[3321]: conn=1011 fd=16 ACCEPT from IP=140.232.1.12:37623 (IP=0.0.0.0:636) Feb 3 09:42:03 zoot slapd[3321]: conn=1010 fd=19 TLS established tls_ssf=256 ssf=256 Feb 3 09:42:03 zoot slapd[3321]: conn=1011 fd=16 TLS established tls_ssf=256 ssf=256 Feb 3 09:42:03 zoot slapd[3321]: conn=1010 op=0 BIND dn="cn=replicator,ou=services,dc=clarku,dc=edu" method=128 Feb 3 09:42:03 zoot slapd[3321]: conn=1011 op=0 BIND dn="cn=config" method=128 Feb 3 09:42:03 zoot slapd[3321]: conn=1011 op=0 BIND dn="cn=config" mech=SIMPLE ssf=0 Feb 3 09:42:03 zoot slapd[3321]: conn=1010 op=0 BIND dn="cn=Replicator,ou=Services,dc=clarku,dc=edu" mech=SIMPLE ssf=0

(animal is 140.232.1.12, zoot is 140.232.1.15)

When animal is failing the slapd_client_connect for both dn's (one for cn=config, one for the directory data), I see zoot accept the connection and then zoot sees animal drop it, and then five seconds later it connects successfully.