I have a problem with the N-Way replication multimaster. My enviroiment is debian Stretch and slapd (2.4.47+dfsg-3~bpo9+1) from Stretch backports.

I have configured a cluster with 3 nodes. I have configured to replicate the config database and a normal data mdb database. I followed the documentation and the cluster sync work correctly when all nodes are started.

If i made a change in any node, this change is replicated to the others. My problem appears when i make a change whe one node is down. In this case, the other two nodes repli correctly, and when the downed node start this get all pending changes correctly. And in this point occurs the problem. After the start of downed node, the changes mades in this node are not send to the other two nodes. For other way, the changes mades in the other two nodes (no shutdowned) are sended to all nodes correctly.

I tried this config with a two nodes cluster and the behavior was the same, after reboot slapd do not send more updates.

I have checked the olcServerId because i know that a mistake here can produce similar problems. I really think that it is correct.

The cmdlines of the proccess are:

/usr/sbin/slapd -h ldapi:/// ldap://wbsvisionNode1/ ldap://127.0.0.1/ ldaps:/// -g openldap -u openldap -F /etc/ldap/slapd.d
/usr/sbin/slapd -h ldapi:/// ldap://wbsvisionNode2/ ldap://127.0.0.1/ ldaps:/// -g openldap -u openldap -F /etc/ldap/slapd.d
/usr/sbin/slapd -h ldapi:/// ldap://wbsvisionNode3/ ldap://127.0.0.1/ ldaps:/// -g openldap -u openldap -F /etc/ldap/slapd.d

The config database configuración is below:

DN: cn=config
.....
olcServerID: 1 ldap://wbsvisionNode1/
olcServerID: 2 ldap://wbsvisionNode2/
olcServerID: 3 ldap://wbsvisionNode3/

dn: olcDatabase={0}config,cn=config
.......
olcMirrorMode: TRUE

olcSyncUseSubentry: FALSE

olcSyncrepl:

{0}rid=001
provider=ldap://wbsvisionNode1
bindmethod=simple
binddn="cn=admin,cn=config"
credentials="TuoDqAG7UbCJx8H8gfMO"
starttls=no
tls_cert=/etc/pki/certs/wbsagnitio.local.es.pem
tls_key=/etc/pki/private/wbsagnitio.local.es.key
tls_cacert=/etc/pki/certs/wbsagnitio-ca.pem
tls_reqcert=never
searchbase="cn=config"
scope=sub
type=refreshAndPersist
retry="5 5 300 +"
{1}rid=002
provider=ldap://wbsvisionNode2
bindmethod=simple
binddn="cn=admin,cn=config"
credentials="TuoDqAG7UbCJx8H8gfMO"
starttls=no
tls_cert=/etc/pki/certs/wbsagnitio.local.es.pem
tls_key=/etc/pki/private/wbsagnitio.local.es.key
tls_cacert=/etc/pki/certs/wbsagnitio-ca.pem
tls_reqcert=never
searchbase="cn=config"
scope=sub
type=refreshAndPersist
retry="5 5 300 +"
{2}rid=003
provider=ldap://wbsvisionNode3
bindmethod=simple
binddn="cn=admin,cn=config"
credentials="TuoDqAG7UbCJx8H8gfMO"
starttls=no
tls_cert=/etc/pki/certs/wbsagnitio.local.es.pem
tls_key=/etc/pki/private/wbsagnitio.local.es.key
tls_cacert=/etc/pki/certs/wbsagnitio-ca.pem
tls_reqcert=never
searchbase="cn=config"
scope=sub
type=refreshAndPersist
retry="5 5 300 +"
FALSE

------

dn: olcOverlay={0}syncprov,olcDatabase={0}config,cn=config
objectClass: olcSyncProvConfig
objectClass: olcOverlayConfig
olcOverlay: {0}syncprov
olcSpCheckpoint: 1000 1

The data database configuración is below:

dn: olcDatabase={1}mdb,cn=config
objectClass: olcMdbConfig
objectClass: olcDatabaseConfig
olcDatabase: {1}mdb
...
olcDbIndex: objectClass eq
olcDbIndex: entryCSN eq
...
olcLastMod: TRUE

olcSuffix: dc=local,dc=es
.........
olcMirrorMode: TRUE

olcSyncrepl: {0}rid=004
provider=ldap://wbsvisionNode1
bindmethod=simple
binddn="cn=manager,dc=local,dc=es"
credentials="test"
starttls=no
searchbase="dc=local,dc=es"
scope=sub
type=refreshAndPersist
retry="5 5 300 +"

olcSyncrepl: {1}rid=005
provider=ldap://wbsvisionNode2
bindmethod=simple
binddn="cn=manager,dc=local,dc=es"
credentials="test"
starttls=no
searchbase="dc=local,dc=es"
scope=sub
type=refreshAndPersist
retry="5 5 300 +"

olcSyncrepl: {2}rid=006
provider=ldap://wbsvisionNode3
bindmethod=simple
binddn="cn=manager,dc=local,dc=es"
credentials="test"
starttls=no
searchbase="dc=local,dc=es"
scope=sub
type=refreshAndPersist
retry="5 5 300 +"

olcSyncUseSubentry: FALSE

dn: olcOverlay={0}dynlist,olcDatabase={1}mdb,cn=config
objectClass: olcDynamicList
objectClass: olcOverlayConfig
olcOverlay: {0}dynlist
olcDlAttrSet: {0}virtualGroup memberDnURL uniqueMember
olcDlAttrSet: {1}virtualGroup memberUidURL memberUid:uid
olcDlAttrSet: {2}virtualGroup memberSidURL sambaSIDList:sambaSID

dn: olcOverlay={1}lastbind,olcDatabase={1}mdb,cn=config
objectClass: olcLastBindConfig
objectClass: olcOverlayConfig
olcOverlay: {1}lastbind
olcLastBindPrecision: 30

dn: olcOverlay={2}unique,olcDatabase={1}mdb,cn=config
objectClass: olcUniqueConfig
objectClass: olcOverlayConfig
olcOverlay: {2}unique
olcUniqueAttribute: uid
olcUniqueAttribute: uidNumber
olcUniqueAttribute: employeeNumber
olcUniqueBase: dc=local,dc=es

dn: olcOverlay={3}memberof,olcDatabase={1}mdb,cn=config
objectClass: olcMemberOf
objectClass: olcOverlayConfig
olcOverlay: {3}memberof
olcMemberOfDangling: ignore
olcMemberOfGroupOC: groupOfUniqueNames
olcMemberOfMemberAD: uniqueMember
olcMemberOfMemberOfAD: memberOf
olcMemberOfRefInt: TRUE

dn: olcOverlay={4}accesslog,olcDatabase={1}mdb,cn=config
objectClass: olcAccessLogConfig
objectClass: olcOverlayConfig
olcAccessLogDB: cn=accesslog
olcOverlay: {4}accesslog
olcAccessLogOld: (|(objectClass=wbsagnitioGroup)(objectClass=wbsagnitioAccou
nt))
olcAccessLogOldAttr: roles
olcAccessLogOldAttr: objectClass
olcAccessLogOps: writes
olcAccessLogOps: bind
olcAccessLogPurge: 7+00:00 1+00:00

dn: olcOverlay={5}ppolicy,olcDatabase={1}mdb,cn=config
objectClass: olcPPolicyConfig
objectClass: olcOverlayConfig
olcOverlay: {5}ppolicy
olcPPolicyDefault: cn=0-default,ou=passwordpolicies,ou=configuration,dc=loca
l,dc=es
olcPPolicyForwardUpdates: FALSE
olcPPolicyHashCleartext: FALSE
olcPPolicyUseLockout: FALSE

dn: olcOverlay={6}syncprov,olcDatabase={1}mdb,cn=config
objectClass: olcSyncProvConfig
objectClass: olcOverlayConfig
olcOverlay: {6}syncprov
olcSpCheckpoint: 1000 1

Below i show the sync log of some operations to show the behavior of my cluster:

TEST 1: 3 Nodes up. Update in node 1 (correct):

Log Node1:

May 7 17:03:22 wbsvisionNode1 slapd[14058]: slap_queue_csn: queueing 0x7fc7e0100a90 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode1 slapd[14058]: slap_queue_csn: queueing 0x7fc7e0108b40 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode1 slapd[14058]: slap_graduate_commit_csn: removing 0x7fc7e0108b40 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode1 slapd[14058]: syncprov_sendresp: to=002, cookie=rid=004,sid=001,csn=20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode1 slapd[14058]: syncprov_sendresp: to=003, cookie=rid=004,sid=001,csn=20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode1 slapd[14058]: slap_graduate_commit_csn: removing 0x7fc7e0100a90 20190507150322.383471Z#000000#001#000000

Log Node2:

May 7 17:03:22 wbsvisionNode2 slapd[1263]: do_syncrep2: rid=004 cookie=rid=004,sid=001,csn=20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode2 slapd[1263]: syncrepl_message_to_entry: rid=004 DN: cn=Usuarios,ou=grupos,dc=local,dc=es, UUID: d6c282a0-00ff-1039-89ae-b1c1eec8fb13
May 7 17:03:22 wbsvisionNode2 slapd[1263]: syncrepl_entry: rid=004 LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_MODIFY) tid 23fff700
May 7 17:03:22 wbsvisionNode2 slapd[1263]: syncrepl_entry: rid=004 be_search (0)
May 7 17:03:22 wbsvisionNode2 slapd[1263]: syncrepl_entry: rid=004 cn=Usuarios,ou=grupos,dc=local,dc=es
May 7 17:03:22 wbsvisionNode2 slapd[1263]: slap_queue_csn: queueing 0x7f80081057c0 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode2 slapd[1263]: syncprov_matchops: skipping original sid 001
May 7 17:03:22 wbsvisionNode2 slapd[1263]: slap_queue_csn: queueing 0x7f8008107700 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode2 slapd[1263]: slap_graduate_commit_csn: removing 0x7f8008107700 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode2 slapd[1263]: syncprov_matchops: skipping original sid 001
May 7 17:03:22 wbsvisionNode2 slapd[1263]: syncprov_sendresp: to=003, cookie=rid=005,sid=002,csn=20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode2 slapd[1263]: slap_graduate_commit_csn: removing 0x7f80081057c0 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode2 slapd[1263]: syncrepl_entry: rid=004 be_modify cn=Usuarios,ou=grupos,dc=local,dc=es (0)
May 7 17:03:22 wbsvisionNode2 slapd[1263]: slap_queue_csn: queueing 0x7f8008105ea0 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode2 slapd[1263]: slap_graduate_commit_csn: removing 0x7f8008105ea0 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode2 slapd[1263]: do_syncrep2: rid=006 cookie=rid=006,sid=003,csn=20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode2 slapd[1263]: do_syncrep2: rid=006 CSN too old, ignoring 20190507150322.383471Z#000000#001#000000 (cn=Usuarios,ou=grupos,dc=local,dc=es)

Log Node3:

May 7 17:03:22 wbsvisionNode3 slapd[1100]: do_syncrep2: rid=004 cookie=rid=004,sid=001,csn=20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode3 slapd[1100]: syncrepl_message_to_entry: rid=004 DN: cn=Usuarios,ou=grupos,dc=local,dc=es, UUID: d6c282a0-00ff-1039-89ae-b1c1eec8fb13
May 7 17:03:22 wbsvisionNode3 slapd[1100]: syncrepl_entry: rid=004 LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_MODIFY) tid adbb2700
May 7 17:03:22 wbsvisionNode3 slapd[1100]: syncrepl_entry: rid=004 be_search (0)
May 7 17:03:22 wbsvisionNode3 slapd[1100]: syncrepl_entry: rid=004 cn=Usuarios,ou=grupos,dc=local,dc=es
May 7 17:03:22 wbsvisionNode3 slapd[1100]: slap_queue_csn: queueing 0x7f428c1045c0 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode3 slapd[1100]: syncprov_matchops: skipping original sid 001
May 7 17:03:22 wbsvisionNode3 slapd[1100]: slap_queue_csn: queueing 0x7f428c1069e0 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode3 slapd[1100]: slap_graduate_commit_csn: removing 0x7f428c1069e0 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode3 slapd[1100]: syncprov_matchops: skipping original sid 001
May 7 17:03:22 wbsvisionNode3 slapd[1100]: slap_graduate_commit_csn: removing 0x7f428c1045c0 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode3 slapd[1100]: syncprov_sendresp: to=002, cookie=rid=006,sid=003,csn=20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode3 slapd[1100]: syncrepl_entry: rid=004 be_modify cn=Usuarios,ou=grupos,dc=local,dc=es (0)
May 7 17:03:22 wbsvisionNode3 slapd[1100]: slap_queue_csn: queueing 0x7f428c104c90 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode3 slapd[1100]: slap_graduate_commit_csn: removing 0x7f428c104c90 20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode3 slapd[1100]: do_syncrep2: rid=005 cookie=rid=005,sid=002,csn=20190507150322.383471Z#000000#001#000000
May 7 17:03:22 wbsvisionNode3 slapd[1100]: do_syncrep2: rid=005 CSN too old, ignoring 20190507150322.383471Z#000000#001#000000 (cn=Usuarios,ou=grupos,dc=local,dc=es)

TEST 2: 3 Nodes up. Update in node 2 (correct) (later this will be the down node):

Log Node1:

May 7 17:05:31 wbsvisionNode1 slapd[14058]: do_syncrep2: rid=005 cookie=rid=005,sid=002,csn=20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode1 slapd[14058]: syncrepl_message_to_entry: rid=005 DN: cn=Usuarios,ou=grupos,dc=local,dc=es, UUID: d6c282a0-00ff-1039-89ae-b1c1eec8fb13
May 7 17:05:31 wbsvisionNode1 slapd[14058]: syncrepl_entry: rid=005 LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_MODIFY) tid eaffd700
May 7 17:05:31 wbsvisionNode1 slapd[14058]: syncrepl_entry: rid=005 be_search (0)
May 7 17:05:31 wbsvisionNode1 slapd[14058]: syncrepl_entry: rid=005 cn=Usuarios,ou=grupos,dc=local,dc=es
May 7 17:05:31 wbsvisionNode1 slapd[14058]: slap_queue_csn: queueing 0x7fc7d411fdd0 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode1 slapd[14058]: syncprov_matchops: skipping original sid 002
May 7 17:05:31 wbsvisionNode1 slapd[14058]: slap_queue_csn: queueing 0x7fc7d4105fa0 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode1 slapd[14058]: slap_graduate_commit_csn: removing 0x7fc7d4105fa0 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode1 slapd[14058]: syncprov_matchops: skipping original sid 002
May 7 17:05:31 wbsvisionNode1 slapd[14058]: slap_graduate_commit_csn: removing 0x7fc7d411fdd0 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode1 slapd[14058]: syncrepl_entry: rid=005 be_modify cn=Usuarios,ou=grupos,dc=local,dc=es (0)
May 7 17:05:31 wbsvisionNode1 slapd[14058]: slap_queue_csn: queueing 0x7fc7d4121830 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode1 slapd[14058]: syncprov_sendresp: to=003, cookie=rid=004,sid=001,csn=20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode1 slapd[14058]: slap_graduate_commit_csn: removing 0x7fc7d4121830 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode1 slapd[14058]: do_syncrep2: rid=006 cookie=rid=006,sid=003,csn=20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode1 slapd[14058]: do_syncrep2: rid=006 CSN too old, ignoring 20190507150531.748816Z#000000#002#000000 (cn=Usuarios,ou=grupos,dc=local,dc=es)

Log Node2:

May 7 17:05:31 wbsvisionNode2 slapd[1263]: slap_queue_csn: queueing 0x7f8008106ed0 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode2 slapd[1263]: slap_queue_csn: queueing 0x7f80081050e0 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode2 slapd[1263]: slap_graduate_commit_csn: removing 0x7f80081050e0 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode2 slapd[1263]: syncprov_sendresp: to=003, cookie=rid=005,sid=002,csn=20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode2 slapd[1263]: slap_graduate_commit_csn: removing 0x7f8008106ed0 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode2 slapd[1263]: syncprov_sendresp: to=001, cookie=rid=005,sid=002,csn=20190507150531.748816Z#000000#002#000000

Log Node3:

May 7 17:05:31 wbsvisionNode3 slapd[1100]: do_syncrep2: rid=005 cookie=rid=005,sid=002,csn=20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode3 slapd[1100]: syncrepl_message_to_entry: rid=005 DN: cn=Usuarios,ou=grupos,dc=local,dc=es, UUID: d6c282a0-00ff-1039-89ae-b1c1eec8fb13
May 7 17:05:31 wbsvisionNode3 slapd[1100]: syncrepl_entry: rid=005 LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_MODIFY) tid acbb0700
May 7 17:05:31 wbsvisionNode3 slapd[1100]: syncrepl_entry: rid=005 be_search (0)
May 7 17:05:31 wbsvisionNode3 slapd[1100]: syncrepl_entry: rid=005 cn=Usuarios,ou=grupos,dc=local,dc=es
May 7 17:05:31 wbsvisionNode3 slapd[1100]: slap_queue_csn: queueing 0x7f4288107310 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode3 slapd[1100]: syncprov_matchops: skipping original sid 002
May 7 17:05:31 wbsvisionNode3 slapd[1100]: slap_queue_csn: queueing 0x7f4288109c60 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode3 slapd[1100]: slap_graduate_commit_csn: removing 0x7f4288109c60 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode3 slapd[1100]: syncprov_matchops: skipping original sid 002
May 7 17:05:31 wbsvisionNode3 slapd[1100]: slap_graduate_commit_csn: removing 0x7f4288107310 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode3 slapd[1100]: syncprov_sendresp: to=001, cookie=rid=006,sid=003,csn=20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode3 slapd[1100]: syncrepl_entry: rid=005 be_modify cn=Usuarios,ou=grupos,dc=local,dc=es (0)
May 7 17:05:31 wbsvisionNode3 slapd[1100]: slap_queue_csn: queueing 0x7f42881079f0 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode3 slapd[1100]: slap_graduate_commit_csn: removing 0x7f42881079f0 20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode3 slapd[1100]: do_syncrep2: rid=004 cookie=rid=004,sid=001,csn=20190507150531.748816Z#000000#002#000000
May 7 17:05:31 wbsvisionNode3 slapd[1100]: do_syncrep2: rid=004 CSN too old, ignoring 20190507150531.748816Z#000000#002#000000 (cn=Usuarios,ou=grupos,dc=local,dc=es)

TEST 3: 2 Nodes up. The node 2 is down. Update in node 1:

Log Node1:

May 7 17:10:16 wbsvisionNode1 slapd[14058]: slap_queue_csn: queueing 0x7fc7dc125e50 20190507151016.178467Z#000000#001#000000
May 7 17:10:16 wbsvisionNode1 slapd[14058]: slap_queue_csn: queueing 0x7fc7dc126f40 20190507151016.178467Z#000000#001#000000
May 7 17:10:16 wbsvisionNode1 slapd[14058]: slap_graduate_commit_csn: removing 0x7fc7dc126f40 20190507151016.178467Z#000000#001#000000
May 7 17:10:16 wbsvisionNode1 slapd[14058]: syncprov_sendresp: to=002, cookie=rid=004,sid=001,csn=20190507151016.178467Z#000000#001#000000
May 7 17:10:16 wbsvisionNode1 slapd[14058]: slap_graduate_commit_csn: removing 0x7fc7dc125e50 20190507151016.178467Z#000000#001#000000
May 7 17:10:16 wbsvisionNode1 slapd[14058]: syncprov_sendresp: to=003, cookie=rid=004,sid=001,csn=20190507151016.178467Z#000000#001#000000

Log Node3:

May 7 17:10:15 wbsvisionNode3 slapd[1100]: do_syncrep2: rid=004 cookie=rid=004,sid=001,csn=20190507151016.178467Z#000000#001#000000
May 7 17:10:15 wbsvisionNode3 slapd[1100]: syncrepl_message_to_entry: rid=004 DN: cn=Usuarios,ou=grupos,dc=local,dc=es, UUID: d6c282a0-00ff-1039-89ae-b1c1eec8fb13
May 7 17:10:15 wbsvisionNode3 slapd[1100]: syncrepl_entry: rid=004 LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_MODIFY) tid a6ffd700
May 7 17:10:15 wbsvisionNode3 slapd[1100]: syncrepl_entry: rid=004 be_search (0)
May 7 17:10:15 wbsvisionNode3 slapd[1100]: syncrepl_entry: rid=004 cn=Usuarios,ou=grupos,dc=local,dc=es
May 7 17:10:15 wbsvisionNode3 slapd[1100]: slap_queue_csn: queueing 0x7f42a0124640 20190507151016.178467Z#000000#001#000000
May 7 17:10:15 wbsvisionNode3 slapd[1100]: syncprov_matchops: skipping original sid 001
May 7 17:10:15 wbsvisionNode3 slapd[1100]: slap_queue_csn: queueing 0x7f42a01261a0 20190507151016.178467Z#000000#001#000000
May 7 17:10:15 wbsvisionNode3 slapd[1100]: slap_graduate_commit_csn: removing 0x7f42a01261a0 20190507151016.178467Z#000000#001#000000
May 7 17:10:15 wbsvisionNode3 slapd[1100]: syncprov_matchops: skipping original sid 001
May 7 17:10:15 wbsvisionNode3 slapd[1100]: slap_graduate_commit_csn: removing 0x7f42a0124640 20190507151016.178467Z#000000#001#000000
May 7 17:10:15 wbsvisionNode3 slapd[1100]: syncprov_sendresp: to=002, cookie=rid=006,sid=003,csn=20190507151016.178467Z#000000#001#000000
May 7 17:10:15 wbsvisionNode3 slapd[1100]: syncrepl_entry: rid=004 be_modify cn=Usuarios,ou=grupos,dc=local,dc=es (0)
May 7 17:10:15 wbsvisionNode3 slapd[1100]: slap_queue_csn: queueing 0x7f42a0124810 20190507151016.178467Z#000000#001#000000
May 7 17:10:15 wbsvisionNode3 slapd[1100]: slap_graduate_commit_csn: removing 0x7f42a0124810 20190507151016.178467Z#000000#001#000000

TEST 4: 3 Nodes up. Logs of the sync produced by the Node2 start. The node2 resync correctly the change made in TEST3 (when this node was down).

Log Node1:

May 7 17:13:52 wbsvisionNode1 slapd[14058]: slap_queue_csn: queueing 0x7fc7dc122780 20190507151352.582436Z#000000#001#000000
May 7 17:13:52 wbsvisionNode1 slapd[14058]: slap_graduate_commit_csn: removing 0x7fc7dc122780 20190507151352.582436Z#000000#001#000000
May 7 17:13:52 wbsvisionNode1 slapd[14058]: syncprov_search_response: cookie=rid=004,sid=001,csn=20190507151016.178467Z#000000#001#000000;20190507150531.748816Z#000000#002#000000;20190507150013.014798Z#000000#003#000000

Log Node2:

May 7 17:13:52 wbsvisionNode2 slapd[591]: slapd starting
May 7 17:13:52 wbsvisionNode2 slapd[435]: Starting OpenLDAP: slapd.
May 7 17:13:52 wbsvisionNode2 systemd[1]: Started LSB: OpenLDAP standalone server (Lightweight Directory Access Protocol).
May 7 17:13:52 wbsvisionNode2 slapd[591]: do_syncrep2: rid=001 LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 7 17:13:52 wbsvisionNode2 slapd[591]: do_syncrep2: rid=003 LDAP_RES_INTERMEDIATE - REFRESH_DELETE
May 7 17:13:52 wbsvisionNode2 slapd[591]: do_syncrep2: rid=004 LDAP_RES_INTERMEDIATE - SYNC_ID_SET
May 7 17:13:52 wbsvisionNode2 slapd[591]: do_syncrep2: rid=006 LDAP_RES_INTERMEDIATE - SYNC_ID_SET
May 7 17:13:52 wbsvisionNode2 slapd[591]: syncrepl_message_to_entry: rid=004 DN: cn=Usuarios,ou=grupos,dc=local,dc=es, UUID: d6c282a0-00ff-1039-89ae-b1c1eec8fb13
May 7 17:13:52 wbsvisionNode2 slapd[591]: syncrepl_entry: rid=004 LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD) tid f6021700
May 7 17:13:52 wbsvisionNode2 slapd[591]: syncrepl_entry: rid=004 be_search (0)
May 7 17:13:52 wbsvisionNode2 slapd[591]: syncrepl_entry: rid=004 cn=Usuarios,ou=grupos,dc=local,dc=es
May 7 17:13:52 wbsvisionNode2 slapd[591]: syncrepl_message_to_entry: rid=006 DN: cn=Usuarios,ou=grupos,dc=local,dc=es, UUID: d6c282a0-00ff-1039-89ae-b1c1eec8fb13
May 7 17:13:52 wbsvisionNode2 slapd[591]: syncrepl_entry: rid=006 LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD) tid f501f700
May 7 17:13:52 wbsvisionNode2 slapd[591]: dn_callback : entries have identical CSN cn=Usuarios,ou=grupos,dc=local,dc=es 20190507151016.178467Z#000000#001#000000
May 7 17:13:52 wbsvisionNode2 slapd[591]: syncrepl_entry: rid=006 be_search (0)
May 7 17:13:52 wbsvisionNode2 slapd[591]: syncrepl_entry: rid=006 cn=Usuarios,ou=grupos,dc=local,dc=es
May 7 17:13:52 wbsvisionNode2 slapd[591]: syncrepl_entry: rid=006 entry unchanged, ignored (cn=Usuarios,ou=grupos,dc=local,dc=es)
May 7 17:13:52 wbsvisionNode2 slapd[591]: do_syncrep2: rid=006 LDAP_RES_INTERMEDIATE - REFRESH_PRESENT
May 7 17:13:52 wbsvisionNode2 slapd[591]: do_syncrep2: rid=006 cookie=rid=006,sid=003,csn=20190507151016.178467Z#000000#001#000000;20190507150531.748816Z#000000#002#000000;20190507150013.014798Z#000000#003#000000
May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=006 present UUID d6b883e0-00ff-1039-898f-b1c1eec8fb13, dn dc=local,dc=es
May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=006 present UUID d6b88520-00ff-1039-8990-b1c1eec8fb13, dn ou=personas,dc=local,dc=es
May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=006 present UUID d6b8e51a-00ff-1039-8991-b1c1eec8fb13, dn ou=grupos,dc=local,dc=es
May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=006 present UUID d6b9494c-00ff-1039-8992-b1c1eec8fb13, dn ou=dominios,dc=local,dc=es
May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=006 present UUID d6b9b18e-00ff-1039-8993-b1c1eec8fb13, dn ou=dns,dc=local,dc=es
May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=006 present UUID d6b9eaaa-00ff-1039-8994-b1c1eec8fb13, dn ou=forward,ou=dns,dc=local,dc=es
.................................

Similar lines with other entries.

May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=006 present UUID d6c282a0-00ff-1039-89ae-b1c1eec8fb13, dn cn=Usuarios,ou=grupos,dc=local,dc=es
...............................
May 7 17:13:52 wbsvisionNode2 slapd[591]: slap_queue_csn: queueing 0x7f63d0123740 20190507151016.178467Z#000000#001#000000
May 7 17:13:52 wbsvisionNode2 slapd[591]: syncrepl_entry: rid=004 be_modify cn=Usuarios,ou=grupos,dc=local,dc=es (0)
May 7 17:13:52 wbsvisionNode2 slapd[591]: do_syncrep2: rid=004 LDAP_RES_INTERMEDIATE - REFRESH_PRESENT
May 7 17:13:52 wbsvisionNode2 slapd[591]: do_syncrep2: rid=004 cookie=rid=004,sid=001,csn=20190507151016.178467Z#000000#001#000000;20190507150531.748816Z#000000#002#000000;20190507150013.014798Z#000000#003#000000
May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=004 present UUID d6b883e0-00ff-1039-898f-b1c1eec8fb13, dn dc=local,dc=es
May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=004 present UUID d6b88520-00ff-1039-8990-b1c1eec8fb13, dn ou=personas,dc=local,dc=es
May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=004 present UUID d6b8e51a-00ff-1039-8991-b1c1eec8fb13, dn ou=grupos,dc=local,dc=es
May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=004 present UUID d6b9494c-00ff-1039-8992-b1c1eec8fb13, dn ou=dominios,dc=local,dc=es
May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=004 present UUID d6b9b18e-00ff-1039-8993-b1c1eec8fb13, dn ou=dns,dc=local,dc=es

May 7 17:13:52 wbsvisionNode2 slapd[591]: nonpresent_callback: rid=004 present UUID d6c282a0-00ff-1039-89ae-b1c1eec8fb13, dn cn=Usuarios,ou=grupos,dc=local,dc=es
.............................

Similar lines with other entries.

May 7 17:13:52 wbsvisionNode2 slapd[591]: slap_queue_csn: queueing 0x7f63d0121400 20190507151016.178467Z#000000#001#000000
May 7 17:13:52 wbsvisionNode2 slapd[591]: slap_graduate_commit_csn: removing 0x7f63d0121400 20190507151016.178467Z#000000#001#000000
May 7 17:13:52 wbsvisionNode2 slapd[591]: slap_graduate_commit_csn: removing 0x7f63d0123740 20190507151016.178467Z#000000#001#000000

Log Node3:

May 7 17:13:52 wbsvisionNode3 slapd[1100]: slap_queue_csn: queueing 0x7f428c103b00 20190507151352.329505Z#000000#003#000000
May 7 17:13:52 wbsvisionNode3 slapd[1100]: slap_graduate_commit_csn: removing 0x7f428c103b00 20190507151352.329505Z#000000#003#000000
May 7 17:13:52 wbsvisionNode3 slapd[1100]: syncprov_search_response: cookie=rid=006,sid=003,csn=20190507151016.178467Z#000000#001#000000;20190507150531.748816Z#000000#002#000000;20190507150013.014798Z#000000#003#000000

TEST 5: 3 Nodes up. Change is made in Node2 after resync and this is not sended to the other nodes in the cluster.

Log Node1:

Empty.

Log Node2:

May 7 17:28:35 wbsvisionNode2 slapd[591]: slap_queue_csn: queueing 0x7f63cc121370 20190507152835.873382Z#000000#002#000000
May 7 17:28:35 wbsvisionNode2 slapd[591]: slap_queue_csn: queueing 0x7f63cc125120 20190507152835.873382Z#000000#002#000000
May 7 17:28:35 wbsvisionNode2 slapd[591]: slap_graduate_commit_csn: removing 0x7f63cc125120 20190507152835.873382Z#000000#002#000000
May 7 17:28:35 wbsvisionNode2 slapd[591]: slap_graduate_commit_csn: removing 0x7f63cc121370 20190507152835.873382Z#000000#002#000000

Log Node3:

Empty.