Issue with delta-sync multimaster

[Al <afrunning@gmail.com>]

Hi All,

I just recently migrated to a new OpenLDAP environment, and am
experiencing an occasional issue.  I am using 2.4.35 and Redhat 6 -
x64 with OpenLDAP compiled and packaged locally. I have setup
multimaster using delta-sync with MDB being utilized for both the user
data as well as the access log.  This environment is fronted by a load
balancer, so traffic is directed to a single server.  A couple of
times an hour, I get the following error in the log on the second
server:

--------------------

Apr 25 13:52:19 server2 slapd[15648]: null_callback : error code 0x10
Apr 25 13:52:19 server2 slapd[15648]: syncrepl_message_to_op: rid=011
be_modify cn=USER123,cn=users,cn=domain,cn=com (16)

--------------------

After this error, the second server goes into refresh mode and gets a
fresh copy.  It would appear that this error relates to the ppolicy
overlay as the entries in the access log at the time of error shows
the pwdFailureTime being removed during a password reset. I do see the
pwdFailureTime being set in the access log earlier too, so the data
should be there (even though the error code indicates no such
attribute).

I was luckily able to catch a bunch of debug logging while the issue
occured.  I have attempted to strip out some useful information, but I
have a very large file with more data in it if neccessary.

--------------------

517967bc mdb_modify_internal: 0x000197ed: cn=USER123,cn=users,cn=domain,cn=com
517967bc <= acl_access_allowed: granted to database root
517967bc mdb_modify_internal: replace userPassword
517967bc mdb_modify_internal: replace pwdChangedTime
517967bc mdb_modify_internal: softdel pwdFailureTime
517967bc mdb_modify_internal: replace entryCSN
517967bc mdb_modify_internal: replace modifiersName
517967bc mdb_modify_internal: replace modifyTimestamp
517967bc mdb_modify_internal: delete pwdFailureTime
517967bc mdb_modify_internal: 16 modify/delete: pwdFailureTime: no
such attribute
517967bc mdb_modify: modify failed (16)
517967bc send_ldap_result: conn=-1 op=0 p=3
517967bc send_ldap_result: err=16 matched="" text="modify/delete:
pwdFailureTime: no such attribute"
517967bc null_callback : error code 0x10
517967bc slap_graduate_commit_csn: removing 0x7fc7ec1bc300
20130425172817.060117Z#000000#001#000000
517967bc syncrepl_message_to_op: rid=011 be_modify
cn=USER123,cn=users,cn=domain,cn=com (16)
...
517967bc do_syncrep2: rid=011 delta-sync lost sync on
(reqStart=20130425172817.000023Z,cn=accesslog), switching to REFRESH

--------------------

Here is the important parts of my config - the configs are mirrored -
so its the same on all:

--------------------

dn: olcDatabase={1}mdb,cn=config
objectClass: olcDatabaseConfig
objectClass: olcMdbConfig
olcDatabase: {1}mdb
olcDbDirectory: /u01/openldap/live2/var/openldap-data
olcSuffix: cn=domain,cn=com
olcAddContentAcl: FALSE
olcLastMod: TRUE
olcLimits: {0}dn.base="cn=ldapreplicator,cn=systems,cn=domain,cn=com
 " size.soft=unlimited  size.hard=unlimited  time.soft=unlimited  time.hard=un
 limited
olcMaxDerefDepth: 15
olcReadOnly: FALSE
olcRootDN: cn=Manager,cn=domain,cn=com
olcRootPW:: NONONO
olcSyncUseSubentry: FALSE
olcMirrorMode: TRUE
olcMonitoring: TRUE
olcDbCheckpoint: 512 5
olcDbNoSync: TRUE
olcDbIndex: objectClass eq
olcDbIndex: entryUUID eq
olcDbIndex: entryCSN eq
olcDbIndex: cn pres,eq,sub
olcDbIndex: uid eq
olcDbIndex: uidNumber eq
olcDbIndex: gidNumber eq
olcDbIndex: uniqueMember eq
olcDbIndex: nisNetgroupTriple eq
olcDbIndex: sudoUser eq,sub
olcDbMaxSize: 25000000000
olcDbMode: 0600
structuralObjectClass: olcMdbConfig
entryUUID: a12ed549-25c6-4424-8c4f-fe63eed54ba2
creatorsName: cn=config
createTimestamp: 20111014131247Z
olcSyncrepl: {0}rid=011 provider=ldap://server1.company.com:21389/ bind
 method=simple timeout=1 network-timeout=1 binddn="cn=ldapreplicator,cn=system
 s,cn=domain,cn=com" credentials="NONONONO" keepalive=0:0:0 startt
 ls=critical filter="(objectclass=*)" searchbase="cn=domain,cn=com"
 logfilter="(&(objectClass=auditWriteObject)(reqResult=0))" logbase="cn=access
 log" scope=sub schemachecking=off type=refreshAndPersist interval=00:00:00:05
  retry="30 +" syncdata=accesslog
olcSyncrepl: {1}rid=012 provider=ldap://server2.company.com:21389/ bind
 method=simple timeout=1 network-timeout=1 binddn="cn=ldapreplicator,cn=system
 s,cn=domain,cn=com" credentials="NONONO" keepalive=0:0:0 startt
 ls=critical filter="(objectclass=*)" searchbase="cn=domain,cn=com"
 logfilter="(&(objectClass=auditWriteObject)(reqResult=0))" logbase="cn=access
 log" scope=sub schemachecking=off type=refreshAndPersist interval=00:00:00:05
  retry="30 +" syncdata=accesslog
entryCSN: 20130425161500.179131Z#000000#001#000000
modifiersName: cn=Manager,cn=config
modifyTimestamp: 20130425161500Z

dn: olcOverlay={0}syncprov,olcDatabase={1}mdb,cn=config
objectClass: olcOverlayConfig
objectClass: olcSyncProvConfig
olcOverlay: {0}syncprov
structuralObjectClass: olcSyncProvConfig
entryUUID: 9a4fbba8-fbe8-4f89-a64f-f20d66023a8a
creatorsName: cn=config
createTimestamp: 20111014131247Z
entryCSN: 20130425004117.389246Z#000000#001#000000
modifiersName: cn=Manager,cn=config
modifyTimestamp: 20130425004117Z

dn: olcOverlay={1}accesslog,olcDatabase={1}mdb,cn=config
objectClass: olcOverlayConfig
objectClass: olcAccessLogConfig
olcOverlay: {1}accesslog
olcAccessLogDB: cn=accesslog
olcAccessLogOps: writes
olcAccessLogPurge: 7+00:00 1+00:00
olcAccessLogSuccess: TRUE
structuralObjectClass: olcAccessLogConfig
entryUUID: 7e12de76-e7fd-4fb2-83f5-46bb58363dd9
creatorsName: cn=config
createTimestamp: 20111014131247Z
entryCSN: 20111019170537.715510Z#000000#000#000000
modifiersName: cn=Manager,cn=config
modifyTimestamp: 20111019170537Z

dn: olcOverlay={2}ppolicy,olcDatabase={1}mdb,cn=config
objectClass: olcOverlayConfig
objectClass: olcPPolicyConfig
olcOverlay: {2}ppolicy
olcPPolicyHashCleartext: TRUE
olcPPolicyUseLockout: FALSE
olcPPolicyForwardUpdates: FALSE
structuralObjectClass: olcPPolicyConfig
entryUUID: c9b15bd3-ae80-42f7-b355-31acebcc941f
creatorsName: cn=config
createTimestamp: 20111014131247Z
entryCSN: 20111014131247.731074Z#000000#000#000000
modifiersName: cn=config
modifyTimestamp: 20111014131247Z

dn: olcOverlay={3}memberof,olcDatabase={1}mdb,cn=config
objectClass: olcMemberOf
objectClass: olcOverlayConfig
objectClass: olcConfig
objectClass: top
olcOverlay: {3}memberof
olcMemberOfRefInt: FALSE
olcMemberOfGroupOC: groupOfUniqueNames
olcMemberOfMemberAD: uniquemember
structuralObjectClass: olcMemberOf
entryUUID: 370bc13f-ae2a-4082-945d-7e6778967400
creatorsName: cn=Manager,cn=config
createTimestamp: 20121001170641Z
entryCSN: 20121001170641.572227Z#000000#000#000000
modifiersName: cn=Manager,cn=config
modifyTimestamp: 20121001170641Z

dn: olcDatabase={2}mdb,cn=config
objectClass: olcDatabaseConfig
objectClass: olcMdbConfig
olcDatabase: {2}mdb
olcDbDirectory: /u01/openldap/live2/var/accesslog-data
olcSuffix: cn=accesslog
olcAccess: {0}to dn.subtree="cn=accesslog"  by dn.base="cn=manager,cn=company,
 cn=com" read  by dn.base="cn=ldapreplicator,cn=systems,cn=company,cn=com"
  read  by group/groupOfUniqueNames/uniqueMember.exact="cn=ldap_
 admins,cn=ldap,cn=groups,cn=domain,cn=com" read  by * none
olcAddContentAcl: FALSE
olcLastMod: TRUE
olcLimits: {0}dn.base="cn=ldapreplicator,cn=systems,cn=domain,cn=com
 " size.soft=unlimited  size.hard=unlimited  time.soft=unlimited  time.hard=un
 limited
olcMaxDerefDepth: 15
olcReadOnly: FALSE
olcSyncUseSubentry: FALSE
olcMonitoring: TRUE
olcDbNoSync: TRUE
olcDbIndex: default eq
olcDbIndex: objectClass eq
olcDbIndex: entryCSN eq
olcDbIndex: reqStart eq
olcDbIndex: reqEnd eq
olcDbIndex: reqResult eq
olcDbIndex: reqDN eq
olcDbMaxSize: 25000000000
olcDbMode: 0600
structuralObjectClass: olcMdbConfig
entryUUID: 76907acf-5c8e-4650-9b36-023da1655a81
creatorsName: cn=config
createTimestamp: 20111014131247Z
entryCSN: 20130424144439.664389Z#000000#001#000000
modifiersName: cn=Manager,cn=config
modifyTimestamp: 20130424144439Z

dn: olcOverlay={0}syncprov,olcDatabase={2}mdb,cn=config
objectClass: olcOverlayConfig
objectClass: olcSyncProvConfig
olcOverlay: {0}syncprov
olcSpNoPresent: TRUE
olcSpReloadHint: TRUE
structuralObjectClass: olcSyncProvConfig
entryUUID: d6cadc16-c4f7-4daf-9a6b-9a37db55ca91
creatorsName: cn=config
createTimestamp: 20111014131247Z
entryCSN: 20111014131247.731074Z#000000#000#000000
modifiersName: cn=config
modifyTimestamp: 20111014131247Z

--------------------

Thank you in advance for any help you might be able to offer.

AL