1:21 a.m.
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.
11:16 a.m.
--On Thursday, May 09, 2019 11:21 AM +0200 David Tello
<david.tello.wbsgo(a)gmail.com> wrote:
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.
Hi David,
I notice your slapo-syncprov overlays are missing a sessionlog setting. It
is critical that this value be large (approximately the same as the number
of entries in your database). I'd also note that the order in which
overlays (particularly syncprov) are instantiated on a database can matter.
It's generally advised that syncprov be the first instantiated overlay (In
your configuration, it's the 7th overlay on the mdb database with index
{6}). I.e., it should be the overlay at index {0}.
These changes may or may not address your issue, but I note them as they
are items that should be addressed in your configuration.
If you are able to reproduce the issue after fixing the above config items,
I would ask that you file an ITS at <http://www.openldap.org/its>;. Even
better is if you're able to script the reproduction case (it seems rather
straight forward) so we can reproduce it locally to work on a fix.
Regards,
Quanah
--
Quanah Gibson-Mount
Product Architect
Symas Corporation
Packaged, certified, and supported LDAP solutions powered by OpenLDAP:
<http://www.symas.com>
11:04 p.m.
New subject: Antw: Problem with N-Way multimaster replication after an node fail and restore
>> David Tello <david.tello.wbsgo(a)gmail.com> schrieb am
09.05.2019 um 10:21
in
Nachricht
<CADC8=Wxww4kTHyRS3_j+93VXRzc45fDrVLJxFwFTRjcH8QD_gQ(a)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.
2:16 a.m.
Hi Ulrich,
Thank for your aswer. About the serverIDs, i think that are well
configured. I enable all trace in the servers an restart all nodes. I got
the below outs:
Node1:
May 13 11:04:36 wbsvisionNode1 slapd[27787]: olcServerID: value #0:
SID=0x001 (listener=ldap://wbsvisionNode1)
Node2:
May 13 11:05:43 wbsvisionNode2 slapd[17862]: olcServerID: value #1:
SID=0x002 (listener=ldap://wbsvisionNode2)
Node3:
May 13 11:06:27 wbsvisionNode3 slapd[6980]: olcServerID: value #2:
SID=0x003 (listener=ldap://wbsvisionNode3)
I understand that this outputs are the corrects.
I made the changes that Quanah indicated to me and i had the same behavior.
I continue searching...
Regards,
David Tello
El lun., 13 may. 2019 a las 8:04, Ulrich Windl (<
Ulrich.Windl(a)rz.uni-regensburg.de>) escribió:
>>> David Tello <david.tello.wbsgo(a)gmail.com> schrieb
am 09.05.2019 um
10:21
in
Nachricht
<CADC8=Wxww4kTHyRS3_j+93VXRzc45fDrVLJxFwFTRjcH8QD_gQ(a)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.
1477
days inactive
1481
days old
openldap-technical@openldap.org
3 comments
3 participants
participants (3)
-
David Tello -
Quanah Gibson-Mount -
Ulrich Windl