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