(ITS#8490) changes not written to accesslog, causing replicas to loop syncing

[quanah@openldap.org]

Full_Name: Quanah Gibson-Mount
Version: OpenLDAP 2.4.44
OS: Linux 2.6
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (75.111.52.177)


In a 2-node MMR setup.  Node 1 is getting a lot of write traffic.  Both node 1
and node 2 have 3 replicas each.  At some point, a change is received by node 1,
which writes the change to its accesslog DB and its primary DB.  It's 3 replicas
are all correctly updated.  MMR node 2 receives the change, updates its primary
DB, but *fails* to write the change to the accesslog DB.  However, it *does*
write the CSN update to the accesslog DB successfully.  This causes all of its
replicas to also update their CSN.  Then a change comes in triggering a
constraint violation on the replicas, but fully accepted by their master.

Node 1 records the following change in its accesslog DB:

dn: reqStart=20160901025119.904382Z,cn=accesslog
objectClass: auditModify
structuralObctctClass: auditModify
reqStart: 20160901025119.904382Z
reqEnd: 20160901025119.906625Z
reqType: modify
reqSession: 7780
reqAuthzID: uid=zimbra,cn=admins,cn=zimbra
reqDN: uid=renamed-trackp,ou=people,dc=xxxxxxxx,dc=co,dc=za
reqResult: 0
reqM%3: zimbraMailWhitelistMaxNumEntries:= 0
reqMod: zimbraPrefMailLocalDeliveryDisabled:= FALSE
reqMod: zimbraHideInGal:= TRUE
reqMod: userPassword:= {SSHA}
reqMod: mail:= renamed-trackp@xxxxxxx.co.za
reqMod: displayName:= trackp@xxxxxxxx.co.za
reodod: objectClass:= inetOrgPerson
reqMod: objectClass:= zimbraAccount
reqMod: objectClass:= amavisAccount
reqMod: zimbraMailHost:= store328-dc01.cm.xxxxxxxxxxx
reqMod: zimbraPasswordMustChange:= FALSE
reqMod: cn:= trackp@xxxxxxxxxxxxx.co.za
reqMod: zimbraPasswordModifiedTime:= 20160121142933Z
reqMod: zimbraMailStatus:= enabled
reqMod: zimbraIsDelegatedAdminAccount:= FALSE
reqMod: zimbraPrefOutOfOfficeReplyEnabled:= FALSE
reqMod: zimbraMailBlacklistMaxNumEntries:= 0
reqMod: zimbraAccountStatus:= locked
reqMod: zimbraPrefTimeZoneId:= Africa/Harare
reqMod: zimbraId:= 403c7b67-eea0-4315-9b10-a2853c6cf70b
reqMod: zimbraMailTransport:= lmtp:store328-dc01.cm.xxxxxxxxxx:7025
reqMod: sn:= trackp@xxxxxxxxxxx.co.za
reqMod: zimbraCOSId:= 1daeb979-365f-46b7-bb3f-2ad46f4576c1
reqMod: zimbraCreateTimestamp:= 20160121142933Z
reqMod: zimbraMailDeliveryAddress:= renamed-trackp@xxxxxxx.co.za
reqMod: entryCSN:= 20160901025119.904589Z#000000#002#000000
reqMod: modifiersName:= uid=zimbra,cn=admins,cn=zimbra
reqMod: modifyTimestamp:= 20160901025119Z
reqEntryUUID: 2293af38-5497-1035-8bd6-1d34a55b9433
entryUUID: b46d8728-043a-1036-8ab7-9bf2e127fe3b
creatorsName: cn=config
createTimestamp: 20160901025119Z
entryCSN: 20160901025119.904589Z#000000#002#000000
modifiersName: cn=config
modifyTimestamp: 20160901025119Z


On the other master, we find in the accesslog two sequential CSN updates:

dn: reqStart=20160901025119.904218Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20160901025119.904218Z
reqEnd: 20160901025119.905035Z
reqType: modify
reqSession: 201
reqAuthzID: cn=config
reqDN:
reqResult: 0
reqMod: contextCSN:= 20160901025119.902062Z#000000#002#000000
reqMod: contextCSN:= 20160901015920.689225Z#000000#003#000000
reqEntryUUID: 78143fa2-7af5-48cc-8d5e-6e15f68dd3b2
entryUUID: b46d48a8-043a-1036-81a5-b3dead5e3175
creatorsName: cn=config
createTimestamp: 20160901025119Z
entryCSN: 20160901025119.902062Z#000000#002#000000
modifiersName: cn=config
modifyTimestamp: 20160901025119Z

dn: reqStart=20160901025119.908257Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20160901025119.908257Z
reqEnd: 20160901025119.908439Z
reqType: modify
reqSession: 201
reqAuthzID: cn=config
reqDN:
reqResult: 0
reqMod: contextCSN:= 20160901025119.904589Z#000000#002#000000
reqMod: contextCSN:= 20160901015920.689225Z#000000#003#000000
reqEntryUUID: 78143fa2-7af5-48cc-8d5e-6e15f68dd3b2
entryUUID: b46dcdaa-043a-1036-81a6-b3dead5e3175
creatorsName: cn=config
createTimestamp: 20160901025119Z
entryCSN: 20160901025119.904589Z#000000#002#000000
modifiersName: cn=config
modifyTimestamp: 20160901025119Z


Note the CSN update in the second case is for 20160901025119.904589Z.  Note that
this was the CSN of the change that in node 1 was a real update. The atribute
with a constraint in this case is ZimbraID, which is colliding with the zimbraID
of the original entry it was renamed from.