Full_Name: Quanah Gibson-Mount Version: 2.4.44 OS: Linux 2.6 URL: ftp://ftp.openldap.org/incoming/ Submission from: (NULL) (75.111.52.177) In MMR node, when there is > 2 nodes, operations can get sent out endlessly. For example, we see this modification occur at 20160603194926.427963Z Jun 3 14:49:22 ldap01 slapd[14014]: syncrepl_message_to_op: rid=100 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:22 ldap01 slapd[14014]: slap_queue_csn: queueing 0x121c8680 20160603194926.417898Z#000000#001#000000 Jun 3 14:49:22 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x9403600 20160527111854.508810Z#000000#004#000000 Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004,csn=20160603194926.417898Z#000000#001#000000 Jun 3 14:49:22 ldap01 slapd[14014]: dsysyncrep2: rid=102 CSN too old, ignoring 20160603194926.417898Z#000000#001#000000 (reqStart=20160603194922.988081Z,cn=accesslog) Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002,csn=20160603194926.417898Z#000000#001#000000 Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=101 CSN too old, ignoring 20160603194926.417898Z#000000#001#000000 (reqStart=20160603194931.992576Z,cn=accesslog) Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=100 cookie=rid=100,sid=001,csn=20160603194926.427963Z#000000#001#000000 Jun 3 14:49:22 ldap01 slapd[14014]: slap_queue_csn: queueing 0x120c1c80 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:22 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x93aae80 20160527095853.061949Z#000000#004#000000 Jun 3 14:49:22 ldap01 slapd[14014]: syncrepl_message_to_op: rid=100 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:22 ldap01 slapd[14014]: slap_queue_csn: queueing 0x1104d080 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:22 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0xac25300 20160527084152.674596Z#000000#004#000000 Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004,nsn=20160603194926.427963Z#000000#001#000000 Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=102 CSN too old, ignoring 20160603194926.427963Z#000000#001#000000 (reqStart=20160603194922.996275Z,cn=accesslog) Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=100 cookie=rid=100,sid=001,csn=20160603194926.433237Z#000000#001#000000 Jun 3 14:49:22 ldap01 slapd[14014]: slap_queue_csn: queueing 0x1116e600 20160603194926.433237Z#000000#001#000000 Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_matchops: skipping origil l sid 001 Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:22 ldap01 slapd[14014]: slap_queue_csn: queueing 0xf0cf380 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:22 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x122e2cc0 20160527095853.613262Z#000000#004#000000 Jun 3 14:49:22 ldap01 slapd[14014]: syncrepl_message_to_op: rid=100 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:22 ldap01 slapd[14014]: slap_queue_csn: queueing 0x1104f280 20160603194926.433237Z#000000#001#000000 Jun 3 14:49:22 ldap01 slapdB1B14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004,csn=20160603194926.433237Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x10aad340 20160527095854.490344Z#000000#004#000000 Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=102 CSN too old, ignoring 20160603194926.433237Z#000000#001#000000 (reqStart=20160603194923.000888Z,cn=accesslog) Jun 3 14:49:23 ldap01 slapd[14014]: conn=183480 op=6644 SRCH base="" scope=0 deref=0 filter="(objectClass=*)" Jun 3 14:49:23 ldap01 slapd[14014]: conn=183480 op=6644 SRCH attr=1.1 Jun 3 14:49:23 ldap01 slapd[14014]: conn=183480 op=6644 SEARCH RESULT tag=101 err=0 etime=0.000307 nentries=1 text= Jun 3 14:49:23 ldap01 slapd[14014]: conn=183479 op=6618 SRCH base="" scope=0 deref=0 filter="(objectClass=*)" Jun 3 14:49:23 ldap01 slapd[14014]: conn=183479 op=6618 SRCH attr=1.1 Jun 3 14:49:23 ldap01 slapd[14014]: conn=183479 op=6618 SEARCH RESULT tag=101 err=0 etime=0.000237 nentries=1 text= Jun 3 14A4A49:23 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x120d7940 20160602173545.246579Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 34%4:49:23 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002,csn=20160603194926.433237Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=101 CSN too old, ignoring 20160603194926.433237Z#000000#001#000000 (reqStart=20160603194932.005634Z,cn=accesslog) Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:23 ldap01 slapd[14014]: slap_queue_csn: queueing 0x10c11fc0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004 Jun 3 14:49:23 ldap01 slapd[14014]: slap_queue_csn: queueing 0x120d6580 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x16c6aec0 20160602173612.801299Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:23 ldap01 slapd[14014]: slap_queue_csn: queueing 0x10dad800 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x12058c40 20160602173638.625104Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncrepl_message_to_op: rid=102 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004 Jun 3 14:49:23 ldap01 slapd[14014]: slap_queue_csn: queueing 0x12058c40 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x120191c0 20160602174110.510583Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:23 ldap01 slapd[14014]: slap_queue_csn: queueing 0x120191c0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 spdpd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:23 lda1 1 slapd[14014]: slap_graduate_commit_csn: removing 0x120c0c00 20160603002555.477495Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncrepl_message_to_op: rid=102 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:23 ldap01 sld[5B14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004 Jun 3 14:49:23 ldap01 slapd[14014]: slap_queue_csn: queueing 0x120c0c00 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0xf0cf380 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:23 ldap01 slapd[14014]: slap_queue_csn: queueing 0xf0cf380 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x115d1d00 20160603002555.477495Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]% s syncrepl_message_to_op: rid=102 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004 Jun 3 14:49:23 ldap01 slapd[14014]: slap_queue_csn: queueing 0x115d1d00 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: conn=198588 op=331 SEARCH RESULT tag=101 err=0 etime=0.000154 nentries=1 text= Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x10c11fc0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:23 ldap01 slapd[14014]: slap_queue_csn: queueing 0x10c11fc0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0xf217bc0 20160603194914.391952Z#000000#001#000000 n n 3 14:49:23 ldap01 slapd[14014]: syncrepl_message_to_op: rid=102 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004 Jun 3 14:49:23 ldap01 slapd[14014]: slap_queue_csn: queueing 0xf217bc0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x10dad800 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:23 ldap01 slapd[14014]: slap_queue_csn: queueing 0x10dad800 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,did=003 Jun 3 14:49:23 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x10dad4c0 20160603194914.391952Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncrepl_message_to_op: rid=102 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:23 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004 Jun 3 14:49:23 ldap01 slapd[14014]: slap_queue_csn: queueing 0x10dad4c0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:23 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cooe%e=rid=100,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x12058c40 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncrepl_message_to_op: rid=102 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:28 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0x12058c40 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x10c11fc0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:28 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0x10c11fc0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x120c0c00 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncrepl_message_to_op: rid=102 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:28 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004 Jun 3 14:49:28 ldap01 apapd[14014]: slap_queue_csn: queueing 0x120c0c00 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x10dad800 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:28 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0x10dad800 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x115d1d00 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncrepl_message_to_op: rid=102 be_modify cn=edge02e.zimbra.com,cn=server2C2Ccn=zimbra (0) Jun 3 14:49:28 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0x115d1d00 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: cn%n=26584 op=49161 SRCH base="" scope=2 deref=0 filter="(&(|(zimbraMailDeliveryAddress=office7@domesticuniform.com)(zimbraMailAlias=office7@domesticuniform.com))(objectClass=zimbraAccount))" Jun 3 14:49:28 ldap01 slapd[14014]: conn=26584 op=49161 SEARCH RESULT tag=101 err=0 etime=0.000212 nentries=0 text= Jun 3 14:49:28 ldap01 slapd[14014]: conn=26591 op=49432 SRCH base="" scope=2 deref=0 filter="(&(zimbraDomainName=domesticuniform.com)(objectClass=zimbraDomain))" Jun 3 14:49: 8 ldap01 slapd[14014]: conn=26591 op=49432 SEARCH RESULT tag=101 err=0 etime=0.000113 nentries=0 text= Jun 3 14:49:28 ldap01 slapd[14014]: conn=26602 op=49397 SRCH base="" scope=2 deref=0 filter="(&(zimbraForeignPrincipal=zmgproxyacct:office7@domesticuniform.com)(objectClass=zimbraAccount))" Jun 3 14:49:28 ldap01 slapd[14014]: conn=26602 op=49397 SEARCH RESULT tag=101 err=0 etime=0.000104 nentries=0 text= Jun 3 14:49:28 ldap01 slapd[14014]: conn=26655 op=36838 MOD dn="uid=shagenbrock,ou=people,dc=zimbra,dc=com" Jun 3 14:49:28 ldap01 slapd[14014]: conn=26655 op=36838 MOD attr=zimbraAuthTokens Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x120191c0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:28 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0x120191c0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0x115da900 20160603194928.195282Z#000000#003#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0xf217bc0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncrepl_message_to_op: rid=102 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:28 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0xf217bc0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0x11257980 20160603194928.195282Z#000000#003#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003,csn=20160603194928.195282Z#000000#003#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003,csn=20160603194928.195282Z#000000#003#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=001, cookie=rid=100,sid=003,csn=20160603194928.195282Z#000000#003#000000 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x11257980 20160603194928.195282Z#000000#003#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0xf0cf380 20160603194926.427963Z#000000#001#000000 Jun 3 14:43A2828 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:28 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0xf0cf380 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x10dad4c0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncrepl_message_to_op: rid=102 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:28 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0x10dad4c0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003%%0 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x10c11fc0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:28 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0x10c11fc0 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x120d6580 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncrepl_message_to_op: rid=102 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:28 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,d%d=004 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0x120d6580 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: conn=184860 op=4552 SRCH base="cn=config,cn=zimbra" scope=0 deref=0 filter="(objectClass=*)" Jun 3 14:49:28 ldap01 slapd[14014]: conn=184860 op=4552 SEARCH RESULT tag=101 err=0 etime=0.001120 nentries=1 text= Jun 3 14:49:28 ldap01 slapd[14014]: conn=184858 op=4439 SRCH base="cn=mbs01.zimbra.com,cn=servers,cn=zimbra" scope=0 deref=0 filr%r="(objectClass=*)" Jun 3 14:49:28 ldap01 slapd[14014]: conn=184858 op=4439 SEARCH RESULT tag=101 err=0 etime=0.000231 nentries=1 text= Jun 3 14:49:28 ldap01 slapd[14014]: conn=184895 op=4430 SRCH base="cn=config,cn=zimbra" scope=0 deref=0 filter="(objectClass=*)" Jun 3 14:49:28 ldap01 slapd[14014]: conn=184895 op=4430 SEARCH RESULT tag=101 err=0 etime=0.001063 nentries=1 text= Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=004, cookie=rid=102,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: syncprov_sendresp: to=002, cookie=rid=100,sid=003 Jun 3 14:49:28 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x10dad800 20160603194926.427963Z#000000#001#000000 Jun 3 14:49:28 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 14:49:28 ldap01 slapd[14014]: do_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 14:49:28 ldap01 slapd[14014]: slap_queue_csn: queueing 0x10dad800 20160603194926.427963Z#000000#001#000000 this literally goes on for HOURS: s.com)(zimbraDomainName=@.synacordomains.com)(zimbraDomainName=synacordomains.com)(zimbraDomainName=@.com)(zimbraDomainName=com)(mbmbraDomainName=@.))))" Jun 3 18:03:17 ldap01 slapd[14014]: conn=202259 op=4 SEARCH RESULT tag=101 err=0 etime=0.000169 nentries=0 text= Jun 3 18:03:17 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 18:03:17 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x18eab480 20160603194926.427963Z#000000#001#000000 Jun 3 18:03:17 ldap01 slapd[14014]: syncrepl_message_to_op: rid=101 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 18:03:17 ldap01 slapd[14014]:o_o_syncrep2: rid=101 cookie=rid=101,sid=002 Jun 3 18:03:17 ldap01 slapd[14014]: slap_queue_csn: queueing 0x18eab480 20160603194926.427963Z#000000#001#000000 Jun 3 18:03:17 ldap01 slapd[14014]: syncprov_matchops: skipping original sid 001 Jun 3 18:03: 7 ldap01 slapd[14014]: slap_graduate_commit_csn: removing 0x18e659c0 20160603194926.427963Z#000000#001#000000 Jun 3 18:03:17 ldap01 slapd[14014]: syncrepl_message_to_op: rid=102 be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) Jun 3 18:03:17 ldap01 slapd[14014]: do_syncrep2: rid=102 cookie=rid=102,sid=004 Jun 3 18:03:17 ldap01 slapd[14014]: slap_queue_csn: queueing 0x18e659c0 20160603194926.427963Z#000000#001#000000 Jun 3 18:03:17 ldap01 slapd[14014]: conn=26580 op=75173 SRCH base="" scope=0 deref=0 filr%r="(objectClass=*)" Jun 3 18:03:17 ldap01 slapd[14014]: conn=26580 op=75173 SRCH attr=1.1
--On Saturday, June 04, 2016 12:06 AM +0000 quanah@openldap.org wrote: > Full_Name: Quanah Gibson-Mount > Version: 2.4.44 > OS: Linux 2.6 > URL: ftp://ftp.openldap.org/incoming/ > Submission from: (NULL) (75.111.52.177) The operation in question shows up in the accesslog DB as of the time I wrote the ITS nearly 40,000 times: zimbra@ldap02e:~/data/q$ grep 'entryCSN: 20160603194926.427963Z#000000#001#000000' ldap-accesslog.bak | wc -l 38601 It is simply a replace op: dn: reqStart=20160603225519.561597Z,cn=accesslog objectClass: auditModify structuralObjectClass: auditModify reqStart: 20160603225519.561597Z reqEnd: 20160603225520.995030Z reqType: modify reqSession: 100 reqAuthzID: cn=config reqDN: cn=edge02e.zimbra.com,cn=servers,cn=zimbra reqResult: 0 reqMod: zimbraReverseProxySSLToUpstreamEnabled:= TRUE reqMod: entryCSN:= 20160603194926.427963Z#000000#001#000000 reqMod: modifiersName:= uid=zimbra,cn=admins,cn=zimbra reqMod: modifyTimestamp:= 20160603194926Z reqEntryUUID: f4eca57a-be0f-1035-9026-e742d2d7a3d7 entryUUID: fe4b54ee-be29-1035-9f38-ef67f10345d6 creatorsName: cn=config createTimestamp: 20160603194926Z entryCSN: 20160603194926.427963Z#000000#001#000000 modifiersName: cn=config modifyTimestamp: 20160603194926Z --Quanah -- Quanah Gibson-Mount Platform Architect Manager, Systems Team Zimbra, Inc. -------------------- Zimbra :: the leader in open source messaging and collaboration A division of Synacor, Inc
quanah@openldap.org wrote: > Full_Name: Quanah Gibson-Mount > Version: 2.4.44 > OS: Linux 2.6 > URL: ftp://ftp.openldap.org/incoming/ > Submission from: (NULL) (75.111.52.177) > > > In MMR node, when there is > 2 nodes, operations can get sent out endlessly. > > For example, we see this modification occur at 20160603194926.427963Z You seem to have a large clock sync problem. > > Jun 3 14:49:22 ldap01 slapd[14014]: syncrepl_message_to_op: rid=100 be_modify > cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) > Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_sendresp: to=002, > cookie=rid=100,sid=003 > Jun 3 14:49:22 ldap01 slapd[14014]: slap_queue_csn: queueing 0x121c8680 > 20160603194926.417898Z#000000#001#000000 > Jun 3 14:49:22 ldap01 slapd[14014]: slap_graduate_commit_csn: removing > 0x9403600 20160527111854.508810Z#000000#004#000000 How did a CSN from 20160527 get queued on 20160603? > Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=102 > cookie=rid=102,sid=004,csn=20160603194926.417898Z#000000#001#000000 > Jun 3 14:49:22 ldap01 slapd[14014]: dsysyncrep2: rid=102 CSN too old, ignoring > 20160603194926.417898Z#000000#001#000000 > (reqStart=20160603194922.988081Z,cn=accesslog) > Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=101 > cookie=rid=101,sid=002,csn=20160603194926.417898Z#000000#001#000000 > Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=101 CSN too old, ignoring > 20160603194926.417898Z#000000#001#000000 > (reqStart=20160603194931.992576Z,cn=accesslog) > Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=100 > cookie=rid=100,sid=001,csn=20160603194926.427963Z#000000#001#000000 > Jun 3 14:49:22 ldap01 slapd[14014]: slap_queue_csn: queueing 0x120c1c80 > 20160603194926.427963Z#000000#001#000000 > Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_matchops: skipping original sid > 001 > Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_sendresp: to=004, > cookie=rid=102,sid=003 > Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_sendresp: to=002, > cookie=rid=100,sid=003 > Jun 3 14:49:22 ldap01 slapd[14014]: slap_graduate_commit_csn: removing > 0x93aae80 20160527095853.061949Z#000000#004#000000 And another one. > Jun 3 14:49:22 ldap01 slapd[14014]: syncrepl_message_to_op: rid=100 be_modify > cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) > Jun 3 14:49:22 ldap01 slapd[14014]: slap_queue_csn: queueing 0x1104d080 > 20160603194926.427963Z#000000#001#000000 > Jun 3 14:49:22 ldap01 slapd[14014]: slap_graduate_commit_csn: removing > 0xac25300 20160527084152.674596Z#000000#004#000000 > Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=102 > cookie=rid=102,sid=004,nsn=20160603194926.427963Z#000000#001#000000 > Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=102 CSN too old, ignoring > 20160603194926.427963Z#000000#001#000000 > (reqStart=20160603194922.996275Z,cn=accesslog) > Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=100 > cookie=rid=100,sid=001,csn=20160603194926.433237Z#000000#001#000000 > Jun 3 14:49:22 ldap01 slapd[14014]: slap_queue_csn: queueing 0x1116e600 > 20160603194926.433237Z#000000#001#000000 > Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_matchops: skipping origil l sid > 001 > Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_sendresp: to=004, > cookie=rid=102,sid=003 > Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_sendresp: to=002, > cookie=rid=100,sid=003 > Jun 3 14:49:22 ldap01 slapd[14014]: do_syncrep2: rid=101 > cookie=rid=101,sid=002 > Jun 3 14:49:22 ldap01 slapd[14014]: slap_queue_csn: queueing 0xf0cf380 > 20160603194926.427963Z#000000#001#000000 > Jun 3 14:49:22 ldap01 slapd[14014]: slap_graduate_commit_csn: removing > 0x122e2cc0 20160527095853.613262Z#000000#004#000000 And another. There are more in the rest of the output you pasted. -- -- Howard Chu CTO, Symas Corp. http://www.symas.com Director, Highland Sun http://highlandsun.com/hyc/ Chief Architect, OpenLDAP http://www.openldap.org/project/
changed notes changed state Open to Closed
--On Thursday, June 09, 2016 1:19 AM +0100 Howard Chu <hyc@symas.com> wrote: > quanah@openldap.org wrote: >> Full_Name: Quanah Gibson-Mount >> Version: 2.4.44 >> OS: Linux 2.6 >> URL: ftp://ftp.openldap.org/incoming/ >> Submission from: (NULL) (75.111.52.177) >> >> >> In MMR node, when there is > 2 nodes, operations can get sent out >> endlessly. >> >> For example, we see this modification occur at 20160603194926.427963Z > > You seem to have a large clock sync problem. >> >> Jun 3 14:49:22 ldap01 slapd[14014]: syncrepl_message_to_op: rid=100 >> be_modify cn=edge02e.zimbra.com,cn=servers,cn=zimbra (0) >> Jun 3 14:49:22 ldap01 slapd[14014]: syncprov_sendresp: to=002, >> cookie=rid=100,sid=003 >> Jun 3 14:49:22 ldap01 slapd[14014]: slap_queue_csn: queueing 0x121c8680 >> 20160603194926.417898Z#000000#001#000000 >> Jun 3 14:49:22 ldap01 slapd[14014]: slap_graduate_commit_csn: removing >> 0x9403600 20160527111854.508810Z#000000#004#000000 > > How did a CSN from 20160527 get queued on 20160603? Because it had been going around non-stop since 5/27 (5/27 is when I did the modification). --Quanah -- Quanah Gibson-Mount Platform Architect Manager, Systems Team Zimbra, Inc. -------------------- Zimbra :: the leader in open source messaging and collaboration A division of Synacor, Inc
changed notes changed state Closed to Open
quanah@zimbra.com wrote: > --On Thursday, June 09, 2016 1:19 AM +0100 Howard Chu <hyc@symas.com> wrote: > >> quanah@openldap.org wrote: >>> Full_Name: Quanah Gibson-Mount >>> Version: 2.4.44 >>> OS: Linux 2.6 >>> URL: ftp://ftp.openldap.org/incoming/ >>> Submission from: (NULL) (75.111.52.177) >>> >>> >>> In MMR node, when there is > 2 nodes, operations can get sent out >>> endlessly. >>> >>> For example, we see this modification occur at 20160603194926.427963Z >> >> You seem to have a large clock sync problem. Summary: after fixing the clock skew, the problem was still present. Analyzing debug logs with sync+stats+packets, we see that the offending mods were propagated by syncprov without a CSN in the sync cookie. Since the cookie contained no CSN, the existing check for "CSN too old, ignoring" was not taking place, so the mods were not being filtered out as they should be. syncprov sends mods out without a CSN in the cookie when the mod's CSN is older than the newest contextCSN. In this particular case, between the time that the provider processed the original mod, and the time it was queued up to be sent to the relevant consumers, this server's own consumers had received newer updates from other providers. So, the mod was older than the current contextCSN and was sent without a cookie CSN. (The usual case for syncprov's behavior is when queued mods get sent out of order; since transmission order is not guaranteed to be the same as write/commit order this is a normal occurrence.) It's possible that regular syncrepl+mmr needs a corresponding fix. I haven't looked at that yet. -- -- Howard Chu CTO, Symas Corp. http://www.symas.com Director, Highland Sun http://highlandsun.com/hyc/ Chief Architect, OpenLDAP http://www.openldap.org/project/
changed notes changed state Open to Release moved from Incoming to Software Bugs
Fixed in master Fixed in RE25 Fixed in RE24 (2.4.45)
changed notes changed state Release to Closed