(ITS#5465) Delta-Syncrepl cookie problems

[quanah@zimbra.com]

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


I have a replica spitting out the following error in its logs (master and
replica running OpenLDAP 2.3.41):

Apr 11 13:28:03 123-ldap-3 slapd[21846]: syncrepl_message_to_op: rid 100
be_modify uid=xxxxx,ou=people,dc=123,dc=abc,dc=edu (20)

It's syncrepl cookie is:

contextCSN: 20080410145621Z#000000#00#000000

Looking at the accesslog on the master, I see (for this time period):

dn: reqStart=20080410145621.000001Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20080410145621.000001Z
reqEnd: 20080410145621.000003Z
reqType: modify
reqSession: 190486
reqAuthzID: uid=zimbra,cn=admins,cn=zimbra
reqDN: uid=xxxxx,ou=people,dc=123,dc=abc,dc=edu
reqResult: 0
reqMod: zimbraPasswordLockoutFailureTime:+ 20080410145621Z
reqMod: zimbraPasswordLockoutFailureTime:- 20080410145230Z
reqMod: entryCSN:= 20080410145621Z#000000#00#000000
reqMod: modifiersName:= uid=zimbra,cn=admins,cn=zimbra
reqMod: modifyTimestamp:= 20080410145621Z
entryUUID: 06ac9202-9b5a-102c-8816-1596598f2bf0
creatorsName: cn=accesslog
createTimestamp: 20080410145621Z
entryCSN: 20080410145621Z#000000#00#000000
modifiersName: cn=accesslog
modifyTimestamp: 20080410145621Z

dn: reqStart=20080410145621.000027Z,cn=accesslog
objectClass: auditModify
structuralObjectClass: auditModify
reqStart: 20080410145621.000027Z
reqEnd: 20080410145621.000028Z
reqType: modify
reqSession: 190494
reqAuthzID: uid=zimbra,cn=admins,cn=zimbra
reqDN: uid=yyyy_07,ou=people,dc=123,dc=abc,dc=edu
reqResult: 0
reqMod: zimbraPasswordLockoutFailureTime:+ 20080410145621Z
reqMod: entryCSN:= 20080410145621Z#000001#00#000000
reqMod: modifiersName:= uid=zimbra,cn=admins,cn=zimbra
reqMod: modifyTimestamp:= 20080410145621Z
entryUUID: 06ee59c6-9b5a-102c-8817-1596598f2bf0
creatorsName: cn=accesslog
createTimestamp: 20080410145621Z
entryCSN: 20080410145621Z#000001#00#000000
modifiersName: cn=accesslog
modifyTimestamp: 20080410145621Z



So as I understand (delta)syncrepl, the replica knows it already received the
update for uid=xxxxx, and yet it is still trying to process that update, rather
than the next one for uid=yyyy_07.

The entry on the replica has:

dn: uid=xxxxx,ou=people,dc=123,dc=abc,dc=edu
zimbraPasswordLockoutFailureTime: 20080410145515Z
zimbraPasswordLockoutFailureTime: 20080410145516Z
zimbraPasswordLockoutFailureTime: 20080410145519Z
zimbraPasswordLockoutFailureTime: 20080410145539Z
zimbraPasswordLockoutFailureTime: 20080410145547Z
zimbraPasswordLockoutFailureTime: 20080410145548Z
zimbraPasswordLockoutFailureTime: 20080410145621Z

So it's clear that the update took on the replica.  I restarted slapd, and it
started replicating correctly.  So it looks like there's a problem where
internally it thinks it is on a previous cookie to what it has already
committed.

--Quanah