8432 – Never ending operation modifications with 3+ MMR nodes

Issue 8432 - Never ending operation modifications with 3+ MMR nodes

Summary: Never ending operation modifications with 3+ MMR nodes

Status:	VERIFIED FIXED

Alias:	None

Product:	OpenLDAP
Classification:	Unclassified
Component:	slapd (show other issues)
Version:	2.4.44
Hardware:	All All

Importance:	--- normal
Target Milestone:	---
Assignee:	OpenLDAP project

URL:
Keywords:

Depends on:
Blocks:

Reported:	2016-06-03 23:06 UTC by Quanah Gibson-Mount
Modified:	2017-06-01 22:09 UTC (History)
CC List:	0 users

See Also:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this issue.

Description Quanah Gibson-Mount 2016-06-03 23:06:32 UTC

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

Comment 1 Quanah Gibson-Mount 2016-06-04 18:32:12 UTC

--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

Comment 2 Howard Chu 2016-06-08 23:19:34 UTC

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/

Comment 3 Howard Chu 2016-06-08 23:58:03 UTC

changed notes
changed state Open to Closed

Comment 4 Quanah Gibson-Mount 2016-06-08 23:59:32 UTC

--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

Comment 5 Quanah Gibson-Mount 2016-06-09 00:29:52 UTC

changed notes
changed state Closed to Open

Comment 6 Howard Chu 2016-06-09 23:18:22 UTC

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/

Comment 7 Quanah Gibson-Mount 2016-10-17 18:00:16 UTC

changed notes
changed state Open to Release
moved from Incoming to Software Bugs

Comment 8 OpenLDAP project 2017-06-01 22:09:14 UTC

Fixed in master
Fixed in RE25
Fixed in RE24 (2.4.45)

Comment 9 Quanah Gibson-Mount 2017-06-01 22:09:14 UTC

changed notes
changed state Release to Closed