[Date Prev][Date Next] [Chronological] [Thread] [Top]
Antw: Problem with N-Way multimaster replication after an node fail and restore

To: "David Tello" <david.tello.wbsgo@gmail.com>, <openldap-technical@openldap.org>
Subject: Antw: Problem with N-Way multimaster replication after an node fail and restore
From: "Ulrich Windl" <Ulrich.Windl@rz.uni-regensburg.de>
Date: Mon, 13 May 2019 08:04:02 +0200
Content-disposition: inline
In-reply-to: <CADC8=Wxww4kTHyRS3_j+93VXRzc45fDrVLJxFwFTRjcH8QD_gQ@mail.gmail.com>
References: <CADC8=Wxww4kTHyRS3_j+93VXRzc45fDrVLJxFwFTRjcH8QD_gQ@mail.gmail.com>
>>> David Tello <david.tello.wbsgo@gmail.com> schrieb am 09.05.2019 um 10:21
in
Nachricht
<CADC8=Wxww4kTHyRS3_j+93VXRzc45fDrVLJxFwFTRjcH8QD_gQ@mail.gmail.com>:
> 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/

Are you sure your server IDs are assigned as intended? It is logged like
"slapd[1493]: olcServerID: value " on start.

> 
> *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;20190507
> 150531.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;20190507
> 150531.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;20190507
> 150531.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;20190507
> 150531.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.
Follow-Ups:
- Re: Problem with N-Way multimaster replication after an node fail and restore
  - From: David Tello <david.tello.wbsgo@gmail.com>
References:
- Problem with N-Way multimaster replication after an node fail and restore
  - From: David Tello <david.tello.wbsgo@gmail.com>
Prev by Date: Re: slapindex vs reimport debug messages (mdb_index_read: failed (-30798))
Next by Date: RE: Issue with OpenLDAP as a proxy to multiple Windows DCs backends
Index(es):
- Chronological
- Thread