Date: Fri, 16 Nov 2012 16:03:52 -0800 (PST)
From: Henry <hen...@gmail.com>
To: mongodb-user@googlegroups.com
Message-Id: <149fd273-5d20-4980-bee5-653d854702ca@googlegroups.com>
Subject: Mongo replica set *secondary* duplicate key issue...
MIME-Version: 1.0
Content-Type: multipart/mixed; 
	boundary="----=_Part_1886_14608018.1353110632931"

------=_Part_1886_14608018.1353110632931
Content-Type: multipart/alternative; 
	boundary="----=_Part_1887_32748309.1353110632931"

------=_Part_1887_32748309.1353110632931
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit

Hi,

We've been having regular issues in our production environment where we see 
duplicate key errors on our secondaries like this (from rs.status()):
        {
                        "_id" : 14,
                        "name" : "db35:27017",
                        "health" : 1,
                        "state" : 2,
                        "stateStr" : "SECONDARY",
                        "uptime" : 20419,
                        "optime" : {
                                "t" : 1353085117000,
                                "i" : 39
                        },
                        "optimeDate" : ISODate("2012-11-16T16:58:37Z"),
                        "lastHeartbeat" : ISODate("2012-11-16T22:13:55Z"),
                        "pingMs" : 1,
                        "errmsg" : "syncTail: 11000 E11000 duplicate key 
error index: data.aa_b098d94b:_Installation.$deviceToken_1 dup key: { : \"1
581a95a\"}, syncing: { ts: Timestamp 1353085117000|40"
                }

We suspect that when we occasionally kill operations on the primary, the 
operations are still trickling to the secondaries, which results in the 
above situation.  This state prevents the secondaries from continuing to 
sync to the primary.


The situation we suspect that leads to this situation looks something like:
Assume that there's a collection with a uniquely indexed field.  This collection 
exists on a replica set with a primary and a secondary.

Phase 1:
- An op inserting a new row into the collection (containing the uniquely 
indexed field with some value) hits the replica set primary.
- The op gets killed at the primary using killOp.
- The op somehow continues to secondary and is accepted.  (<-- possible 
bug?)
- Collection on secondary now has the row and the primary does not.

Phase 2
- After the above, a new op comes in that inserts a row that's identical to 
the row above -- except for a different object id.
- Op is accepted and indexed by the primary since uniqueness constraint is 
met.
- Op passes on to secondary.
- Op on the secondary results in a duplicate key error since it already has 
that value for the uniquely indexed field.
- This results in the above situation.

Would you please pass this theory on to someone at 10gen that is well versed 
with the replication operations above?  Clearing up these inconsistencies 
results in a fairly large operational overhead.

Thanks in advance.

Henry

------=_Part_1887_32748309.1353110632931
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: quoted-printable

<span style=3D"font-family: arial, sans-serif;">Hi,</span><br style=3D"font=
-family: arial, sans-serif;"><br style=3D"font-family: arial, sans-serif;">=
<span style=3D"font-family: arial, sans-serif;">We've been having regular i=
ssues in our production environment where&nbsp;</span><span style=3D"font-f=
amily: arial, sans-serif;">we see duplicate key errors on our secondaries l=
ike this (from&nbsp;</span><span style=3D"font-family: arial, sans-serif;">=
rs.status()):</span><br style=3D"font-family: arial, sans-serif;"><span sty=
le=3D"font-family: arial, sans-serif;">&nbsp; &nbsp; &nbsp; &nbsp; {</span>=
<br style=3D"font-family: arial, sans-serif;"><span style=3D"font-family: a=
rial, sans-serif;">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; =
&nbsp; &nbsp; &nbsp; &nbsp; "_id" : 14,</span><br style=3D"font-family: ari=
al, sans-serif;"><span style=3D"font-family: arial, sans-serif;">&nbsp; &nb=
sp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; "=
name" : "db35:27017",</span><br style=3D"font-family: arial, sans-serif;"><=
span style=3D"font-family: arial, sans-serif;">&nbsp; &nbsp; &nbsp; &nbsp; =
&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; "health" : 1,</span=
><br style=3D"font-family: arial, sans-serif;"><span style=3D"font-family: =
arial, sans-serif;">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp;=
 &nbsp; &nbsp; &nbsp; &nbsp; "state" : 2,</span><br style=3D"font-family: a=
rial, sans-serif;"><span style=3D"font-family: arial, sans-serif;">&nbsp; &=
nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp;=
 "stateStr" : "SECONDARY",</span><br style=3D"font-family: arial, sans-seri=
f;"><span style=3D"font-family: arial, sans-serif;">&nbsp; &nbsp; &nbsp; &n=
bsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; "uptime" : 204=
19,</span><br style=3D"font-family: arial, sans-serif;"><span style=3D"font=
-family: arial, sans-serif;">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbs=
p; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; "optime" : {</span><br style=3D"font-=
family: arial, sans-serif;"><span style=3D"font-family: arial, sans-serif;"=
>&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbs=
p; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; "t" : 1353085117000,</span><br style=
=3D"font-family: arial, sans-serif;"><span style=3D"font-family: arial, san=
s-serif;">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &n=
bsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; "i" : 39</span><br style=3D"=
font-family: arial, sans-serif;"><span style=3D"font-family: arial, sans-se=
rif;">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp;=
 &nbsp; &nbsp; },</span><br style=3D"font-family: arial, sans-serif;"><span=
 style=3D"font-family: arial, sans-serif;">&nbsp; &nbsp; &nbsp; &nbsp; &nbs=
p; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; "optimeDate" : ISODate(=
"2012-11-16T16:58:37Z"</span><wbr style=3D"font-family: arial, sans-serif;"=
><span style=3D"font-family: arial, sans-serif;">),</span><br style=3D"font=
-family: arial, sans-serif;"><span style=3D"font-family: arial, sans-serif;=
">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nb=
sp; &nbsp; "lastHeartbeat" : ISODate("2012-11-16T22:13:55Z"</span><wbr styl=
e=3D"font-family: arial, sans-serif;"><span style=3D"font-family: arial, sa=
ns-serif;">),</span><br style=3D"font-family: arial, sans-serif;"><span sty=
le=3D"font-family: arial, sans-serif;">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &=
nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; "pingMs" : 1,</span><br sty=
le=3D"font-family: arial, sans-serif;"><span style=3D"font-family: arial, s=
ans-serif;">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; =
&nbsp; &nbsp; &nbsp; "errmsg" : "syncTail: 11000 E11000 duplicate key error=
 index:&nbsp;</span><span style=3D"font-family: arial, sans-serif;">data.aa=
_b098</span><span style=3D"font-family: arial, sans-serif;">d94b:_</span><w=
br style=3D"font-family: arial, sans-serif;"><span style=3D"font-family: ar=
ial, sans-serif;">Installation.$deviceToken_1&nbsp;</span><span style=3D"fo=
nt-family: arial, sans-serif;">dup key: { : \"</span><wbr style=3D"font-fam=
ily: arial, sans-serif;"><span style=3D"font-family: arial, sans-serif;">1<=
/span><span style=3D"font-family: arial, sans-serif;">581a</span><span styl=
e=3D"font-family: arial, sans-serif;">95a\"</span><span style=3D"font-famil=
y: arial, sans-serif;">}, syncing: { ts: Timestamp 1353085117000|40"</span>=
<br style=3D"font-family: arial, sans-serif;"><span style=3D"font-family: a=
rial, sans-serif;">&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; =
}</span><br style=3D"font-family: arial, sans-serif;"><br style=3D"font-fam=
ily: arial, sans-serif;"><span style=3D"font-family: arial, sans-serif;">We=
 suspect that when we occasionally kill operations on the primary,&nbsp;</s=
pan><span style=3D"font-family: arial, sans-serif;">the operations are stil=
l trickling to the secondaries, which results&nbsp;</span><span style=3D"fo=
nt-family: arial, sans-serif;">in the above situation. &nbsp;This state pre=
vents the secondaries from continuing&nbsp;</span><span style=3D"font-famil=
y: arial, sans-serif;">to sync to the primary.</span><br style=3D"font-fami=
ly: arial, sans-serif;"><br style=3D"font-family: arial, sans-serif;"><br s=
tyle=3D"font-family: arial, sans-serif;"><span style=3D"font-family: arial,=
 sans-serif;">The situation we suspect that leads to this situation looks s=
omething like:</span><br style=3D"font-family: arial, sans-serif;"><span st=
yle=3D"font-family: arial, sans-serif;">Assume that there's a collection wi=
th a uniquely indexed field. &nbsp;This&nbsp;</span><span style=3D"font-fam=
ily: arial, sans-serif;">collection exists on a replica set with a primary =
and a secondary.</span><br style=3D"font-family: arial, sans-serif;"><br st=
yle=3D"font-family: arial, sans-serif;"><span style=3D"font-family: arial, =
sans-serif;">Phase 1:</span><br style=3D"font-family: arial, sans-serif;"><=
span style=3D"font-family: arial, sans-serif;">- An op inserting a new row =
into the collection (containing the&nbsp;</span><span style=3D"font-family:=
 arial, sans-serif;">uniquely indexed field with some value) hits the repli=
ca set primary.</span><br style=3D"font-family: arial, sans-serif;"><span s=
tyle=3D"font-family: arial, sans-serif;">- The op gets killed at the primar=
y using killOp.</span><br style=3D"font-family: arial, sans-serif;"><span s=
tyle=3D"font-family: arial, sans-serif;">- The op somehow continues to seco=
ndary and is accepted. &nbsp;(&lt;-- possible bug?)</span><br style=3D"font=
-family: arial, sans-serif;"><span style=3D"font-family: arial, sans-serif;=
">- Collection on secondary now has the row and the primary does not.</span=
><br style=3D"font-family: arial, sans-serif;"><br style=3D"font-family: ar=
ial, sans-serif;"><span style=3D"font-family: arial, sans-serif;">Phase 2</=
span><br style=3D"font-family: arial, sans-serif;"><span style=3D"font-fami=
ly: arial, sans-serif;">- After the above, a new op comes in that inserts a=
 row that's&nbsp;</span><span style=3D"font-family: arial, sans-serif;">ide=
ntical to the row above -- except for a different object id.</span><br styl=
e=3D"font-family: arial, sans-serif;"><span style=3D"font-family: arial, sa=
ns-serif;">- Op is accepted and indexed by the primary since uniqueness con=
straint is met.</span><br style=3D"font-family: arial, sans-serif;"><span s=
tyle=3D"font-family: arial, sans-serif;">- Op passes on to secondary.</span=
><br style=3D"font-family: arial, sans-serif;"><span style=3D"font-family: =
arial, sans-serif;">- Op on the secondary results in a duplicate key error =
since it&nbsp;</span><span style=3D"font-family: arial, sans-serif;">alread=
y has that value for the uniquely indexed field.</span><br style=3D"font-fa=
mily: arial, sans-serif;"><span style=3D"font-family: arial, sans-serif;">-=
 This results in the above situation.</span><br style=3D"font-family: arial=
, sans-serif;"><br style=3D"font-family: arial, sans-serif;"><span style=3D=
"font-family: arial, sans-serif;">Would you please pass this theory on to s=
omeone at&nbsp;</span><span class=3D"il" style=3D"background-color: rgb(255=
, 255, 204); font-family: arial, sans-serif;">10gen</span><span style=3D"fo=
nt-family: arial, sans-serif;">&nbsp;that is well&nbsp;</span><span style=
=3D"font-family: arial, sans-serif;">versed with the replication operations=
 above? &nbsp;Clearing up these&nbsp;</span><span style=3D"font-family: ari=
al, sans-serif;">inconsistencies results in a fairly large operational over=
head.</span><br style=3D"font-family: arial, sans-serif;"><br style=3D"font=
-family: arial, sans-serif;"><span style=3D"font-family: arial, sans-serif;=
">Thanks in advance.</span><br><div><span style=3D"font-family: arial, sans=
-serif;"><br></span></div><div><span style=3D"font-family: arial, sans-seri=
f;">Henry</span></div>
------=_Part_1887_32748309.1353110632931--

------=_Part_1886_14608018.1353110632931--