I've filed an ITS on the issue and will see if I can replicate it in our lab. This looks exactly like what I am seeing as well. Howard may be able to provide some gdb actions he would like to see as well.
--Quanah
On May 7, 2014, at 2:57 PM, "Paul B. Henson" henson@acm.org wrote:
On Wed, May 07, 2014 at 09:42:12AM -0700, Quanah Gibson-Mount wrote:
One other thing -- Did any of your servers go into refresh mode prior to this loop starting?
Yes, it started logging:
May 5 19:00:38 filmore-dev slapd[7665]: do_syncrep2: rid=001 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 19:01:48 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync lost sync, switching to REFRESH
It continued logging the lost sync messages almost continuously until:
May 5 19:06:16 filmore-dev slapd[7665]: do_syncrep2: rid=002 delta-sync lost sync, switching to REFRESH May 5 19:06:19 filmore-dev slapd[7665]: do_syncrep2: rid=003 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 19:06:26 filmore-dev slapd[7665]: do_syncrep2: rid=002 delta-sync lost sync, switching to REFRESH May 5 19:06:32 filmore-dev slapd[7665]: do_syncrep2: rid=002 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 20:10:32 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync lost sync on (reqStart=20140506031032.000017Z,cn=accesslog), switching to REFRESH May 5 20:10:32 filmore-dev slapd[7665]: do_syncrep2: rid=003 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 21:30:34 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync lost sync on (reqStart=20140506043034.000008Z,cn=accesslog), switching to REFRESH May 5 21:31:26 filmore-dev slapd[7665]: do_syncrep2: rid=003 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 22:10:36 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync lost sync on (reqStart=20140506051035.000019Z,cn=accesslog), switching to REFRESH May 5 22:10:36 filmore-dev slapd[7665]: do_syncrep2: rid=003 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 22:45:33 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync lost sync on (reqStart=20140506054533.000016Z,cn=accesslog), switching to REFRESH May 5 22:45:33 filmore-dev slapd[7665]: do_syncrep2: rid=003 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 23:10:35 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync lost sync on (reqStart=20140506061035.000008Z,cn=accesslog), switching to REFRESH May 5 23:11:27 filmore-dev slapd[7665]: do_syncrep2: rid=003 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 6 02:15:05 filmore-dev slapd[7665]: do_syncrep2: rid=003 delta-sync lost sync on (reqStart=20140506075534.000068Z,cn=accesslog), switching to REFRESH May 6 02:28:40 filmore-dev slapd[7665]: do_syncrep2: rid=003 LDAP_RES_INTERMEDIATE - REFRESH_DELETE
The others had similar logs:
May 5 19:00:40 fosse-dev slapd[7791]: do_syncrep2: rid=002 delta-sync lost sync, switching to REFRESH May 5 19:00:40 fosse-dev slapd[7791]: do_syncrep2: rid=002 delta-sync lost sync, switching to REFRESH [...] May 5 19:10:33 fosse-dev slapd[7791]: do_syncrep2: rid=001 delta-sync lost sync, switching to REFRESH May 5 19:10:36 fosse-dev slapd[7791]: do_syncrep2: rid=001 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=003 delta-sync lost sync on (reqStart=20140506022033.000008Z,cn=accesslog), switching to REFRESH May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=001 delta-sync lost sync on (reqStart=20140506022033.000009Z,cn=accesslog), switching to REFRESH May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=002 delta-sync lost sync on (reqStart=20140506022033.000009Z,cn=accesslog), switching to REFRESH May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=001 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 19:20:33 fosse-dev slapd[7791]: do_syncrep2: rid=002 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 19:21:26 fosse-dev slapd[7791]: do_syncrep2: rid=003 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 21:30:34 fosse-dev slapd[7791]: do_syncrep2: rid=003 delta-sync lost sync on (reqStart=20140506043034.000008Z,cn=accesslog), switching to REFRESH
May 5 19:02:17 shelley-dev slapd[8178]: do_syncrep2: rid=003 delta-sync lost sync, switching to REFRESH May 5 19:02:17 shelley-dev slapd[8178]: do_syncrep2: rid=002 delta-sync lost sync, switching to REFRESH May 5 19:02:17 shelley-dev slapd[8178]: do_syncrep2: rid=001 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 19:02:21 shelley-dev slapd[8178]: do_syncrep2: rid=002 delta-sync lost sync, switching to REFRESH [...] May 5 19:06:19 shelley-dev slapd[8178]: do_syncrep2: rid=002 delta-sync lost sync, switching to REFRESH May 5 19:06:19 shelley-dev slapd[8178]: do_syncrep2: rid=002 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 19:06:19 shelley-dev slapd[8178]: do_syncrep2: rid=003 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 20:10:32 shelley-dev slapd[8178]: do_syncrep2: rid=003 delta-sync lost sync on (reqStart=20140506031032.000017Z,cn=accesslog), switching to REFRESH May 5 20:10:32 shelley-dev slapd[8178]: do_syncrep2: rid=003 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 21:30:34 shelley-dev slapd[8178]: do_syncrep2: rid=003 delta-sync lost sync on (reqStart=20140506043034.000008Z,cn=accesslog), switching to REFRESH May 5 21:30:34 shelley-dev slapd[8178]: do_syncrep2: rid=003 LDAP_RES_INTERMEDIATE - REFRESH_DELETE May 5 22:45:33 shelley-dev slapd[8178]: do_syncrep2: rid=003 delta-sync lost sync on (reqStart=20140506054533.000016Z,cn=accesslog), switching to REFRESH
I don't know if it's related, but right before the loop it was replicating pwdFailureTime time changes around:
dn: reqStart=20140506064532.000030Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20140506064532.000030Z reqEnd: 20140506064532.000033Z reqType: modify reqSession: 3 reqAuthzID: cn=ldaproot,dc=csupomona,dc=edu reqDN: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu reqResult: 0 reqMod: pwdFailureTime:+ 20140506064532Z reqMod: entryCSN:= 20140506064532.612089Z#000000#003#000000 reqMod: modifiersName:= cn=ldaproot,dc=csupomona,dc=edu reqMod: modifyTimestamp:= 20140506064532Z reqEntryUUID: c16729b0-ce1e-4f9d-9123-e0b8f115133c entryUUID: a1e99b9b-64b8-4e79-9451-48cac10ff333 creatorsName: cn=accesslog createTimestamp: 20140506064532Z entryCSN: 20140506064532.612089Z#000000#003#000000 modifiersName: cn=accesslog modifyTimestamp: 20140506064532Z
dn: reqStart=20140506064532.000034Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20140506064532.000034Z reqEnd: 20140506064532.000035Z reqType: modify reqSession: 5048 reqAuthzID: cn=ldaproot,dc=csupomona,dc=edu reqDN: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu reqResult: 0 reqMod: pwdFailureTime:- reqMod: entryCSN:= 20140506064532.680931Z#000000#002#000000 reqMod: modifiersName:= cn=ldaproot,dc=csupomona,dc=edu reqMod: modifyTimestamp:= 20140506064532Z reqEntryUUID: c16729b0-ce1e-4f9d-9123-e0b8f115133c entryUUID: 557c4163-5170-4dc1-84c4-0159797d5538 creatorsName: cn=accesslog createTimestamp: 20140506064532Z entryCSN: 20140506064532.680931Z#000000#002#000000 modifiersName: cn=accesslog modifyTimestamp: 20140506064532Z
dn: reqStart=20140506064532.000040Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20140506064532.000040Z reqEnd: 20140506064532.000043Z reqType: modify reqSession: 3 reqAuthzID: cn=ldaproot,dc=csupomona,dc=edu reqDN: cn=slapd-monitor,ou=user,ou=service,dc=csupomona,dc=edu reqResult: 0 reqMod: pwdFailureTime:+ 20140506064532Z reqMod: entryCSN:= 20140506064532.861668Z#000000#003#000000 reqMod: modifiersName:= cn=ldaproot,dc=csupomona,dc=edu reqMod: modifyTimestamp:= 20140506064532Z reqEntryUUID: c16729b0-ce1e-4f9d-9123-e0b8f115133c entryUUID: c4ba3c02-b67a-4522-8767-8da1fa084916 creatorsName: cn=accesslog createTimestamp: 20140506064532Z entryCSN: 20140506064532.861668Z#000000#003#000000 modifiersName: cn=accesslog modifyTimestamp: 20140506064532Z