[SERVER-6671] oplog is not strictly idempotent when unique index is present Created: 31/Jul/12  Updated: 11/Jul/16  Resolved: 09/Oct/12

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: 2.0.6, 2.2.0-rc0
Fix Version/s: 2.2.1, 2.3.0

Type: Bug Priority: Critical - P2
Reporter: Ben Becker Assignee: Eric Milkie
Resolution: Done Votes: 2
Labels: index, oplog, replication, unique
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Any replicated environment


Attachments: File SERVER-6671.js    
Issue Links:
Depends
depends on SERVER-7229 test failure in replset8.js Closed
Duplicate
is duplicated by SERVER-9059 Fatal Assertion on replication Closed
Related
is related to SERVER-7186 Batched oplog application increases f... Closed
Operating System: ALL
Participants:

 Description   

Given a replica set which has collection 'c' with a unique index on 'a', consider the following sequence of events:

    db.c.update({ _id:0 }, { $set:{ a:1 } });
    db.c.update({ _id:0 }, { $set:{ a:2 } });
    db.c.update({ _id:1 }, { $set:{ a:1 } });

If a secondary node encounters an error during replication (e.g. by killing the getMore op or network disconnect), it may try to reapply the same operations. In the above case, attempting to reapply the operations will fail on the secondary nodes due to {_id:1} already having a unique index value on

{a:1}

.

On version 2.0.2, the issue is manifested by secondarys halting replication due to syncTail encountering E11000 on the secondary node(s). On version master (~2.2.0-rc0, git hash 73b97070259a0e30d5ed35880b11b32078620e42), the following fassert() is hit:

Tue Jul 31 14:18:05 [repl writer worker 1] build index test.testUniqueReplication { _id: 1 }
Tue Jul 31 14:18:05 [repl writer worker 1] build index done.  scanned 0 total records. 0 secs
Tue Jul 31 14:18:05 [repl writer worker 1] info: creating collection test.testUniqueReplication on add index
Tue Jul 31 14:18:05 [repl writer worker 1] build index test.testUniqueReplication { a: 1.0 }
Tue Jul 31 14:18:05 [repl writer worker 1] build index done.  scanned 0 total records. 0 secs
Tue Jul 31 14:18:23 [conn2292] end connection 127.0.0.1:56268 (11 connections now open)
Tue Jul 31 14:18:23 [initandlisten] connection accepted from 127.0.0.1:56281 #2294 (12 connections now open)
Tue Jul 31 14:18:27 [conn2293] end connection 127.0.0.1:56269 (11 connections now open)
Tue Jul 31 14:18:27 [initandlisten] connection accepted from 127.0.0.1:56282 #2295 (12 connections now open)
Tue Jul 31 14:18:53 [conn2294] end connection 127.0.0.1:56281 (11 connections now open)
Tue Jul 31 14:18:53 [initandlisten] connection accepted from 127.0.0.1:56293 #2296 (12 connections now open)
Tue Jul 31 14:18:57 [conn2295] end connection 127.0.0.1:56282 (11 connections now open)
Tue Jul 31 14:18:57 [initandlisten] connection accepted from 127.0.0.1:56294 #2297 (12 connections now open)
Tue Jul 31 14:18:58 [repl writer worker 1] CMD: drop test.testUniqueReplication
Tue Jul 31 14:18:58 [repl writer worker 1] build index test.testUniqueReplication { _id: 1 }
Tue Jul 31 14:18:58 [repl writer worker 1] build index done.  scanned 0 total records. 0 secs
Tue Jul 31 14:18:58 [repl writer worker 1] info: creating collection test.testUniqueReplication on add index
Tue Jul 31 14:18:58 [repl writer worker 1] build index test.testUniqueReplication { a: 1.0 }
Tue Jul 31 14:18:58 [repl writer worker 1] build index done.  scanned 0 total records. 0 secs
Tue Jul 31 14:19:12 [repl writer worker 1] ERROR: writer worker caught exception: E11000 duplicate key error index: test.testUniqueReplication.$a_1  dup key: { : 1.0 } on: { ts: Timestamp 1343769552000|191, h: 7269005229324720756, op: "u"
, ns: "test.testUniqueReplication", o2: { _id: 0.0 }, o: { $set: { a: 1.0 } } }
Tue Jul 31 14:19:12 [repl writer worker 1]   Fatal Assertion 16360
0x9ccdd3 0x98211d 0x83b398 0x71e326 0x5bda6b 0x7f8c40d60e9a 0x7f8c4027e4bd 
 ./mongod(_ZN5mongo15printStackTraceERSo+0x23) [0x9ccdd3]
 ./mongod(_ZN5mongo13fassertFailedEi+0x4d) [0x98211d]
 ./mongod(_ZN5mongo7replset14multiSyncApplyERKSt6vectorINS_7BSONObjESaIS2_EEPNS0_8SyncTailE+0xf8) [0x83b398]
 ./mongod(_ZN5mongo10threadpool6Worker4loopEv+0x4d6) [0x71e326]
 ./mongod() [0x5bda6b]
 /lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a) [0x7f8c40d60e9a]
 /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f8c4027e4bd]
Tue Jul 31 14:19:12 [repl writer worker 1] 
 
***aborting after fassert() failure



 Comments   
Comment by auto [ 05/Oct/12 ]

Author:

{u'date': u'2012-10-04T15:04:31-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 end batch early if oplog version change is detected
Branch: v2.2
https://github.com/mongodb/mongo/commit/edd2fa6fea3f52e1e9ac06f26a7f60d5758adae9

Comment by auto [ 04/Oct/12 ]

Author:

{u'date': u'2012-10-04T15:04:31-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 end batch early if oplog version change is detected
Branch: master
https://github.com/mongodb/mongo/commit/f059e5ff3ca997032d59f63bbc9cae109a73d92f

Comment by auto [ 04/Oct/12 ]

Author:

{u'date': u'2012-10-03T08:49:45-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 split lines for easier debugging
Branch: v2.2
https://github.com/mongodb/mongo/commit/8e660532455d1165ff039068336c3dcb1cd5ad5f

Comment by auto [ 04/Oct/12 ]

Author:

{u'date': u'2012-10-03T08:32:40-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 add a 'v' version field to each oplog document

The version field will allow us to detect the primary's version.
We need to know which version because only newer primary oplog streams
should prevent a secondary from enforcing unique index constraints
in initial sync or recovering states. The version field will also be
useful in the future when we want to make schema changes in the oplog.
Branch: v2.2
https://github.com/mongodb/mongo/commit/ee081e1df9792e6435568b16d4710a9443ca3657

Comment by auto [ 03/Oct/12 ]

Author:

{u'date': u'2012-10-03T08:49:45-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 split lines for easier debugging
Branch: master
https://github.com/mongodb/mongo/commit/f59fbbaeec03e453af1db1cb1cfdb00cb7780e48

Comment by auto [ 03/Oct/12 ]

Author:

{u'date': u'2012-10-03T08:32:40-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 add a 'v' version field to each oplog document

The version field will allow us to detect the primary's version.
We need to know which version because only newer primary oplog streams
should prevent a secondary from enforcing unique index constraints
in initial sync or recovering states. The version field will also be
useful in the future when we want to make schema changes in the oplog.
Branch: master
https://github.com/mongodb/mongo/commit/206094501a570a75b2fae5a5eb515dc5b55182bb

Comment by Pierre Dane [ 03/Oct/12 ]

Thanks Eric - have done: SERVER-7243

Comment by Eric Milkie [ 03/Oct/12 ]

Hi Pierre.
Please open a new JIRA ticket; I'm not sure if these fixes will help your issue.

Comment by Pierre Dane [ 03/Oct/12 ]

update : this is the windows2008+ build using latest c# driver. Let me know if I need to open a separate ticket please. Txs

Comment by Pierre Dane [ 03/Oct/12 ]

We are seeing this error with no unique key (except _id) present:
Wed Oct 03 09:37:27 [repl writer worker 1] ERROR: writer worker caught exception: E11000 duplicate key error index: ad.ad.$id dup key: (can give full detail in pvt ticket if necessary)

This happens when upgrading from 2.0.6 to 2.2 - simply stopping the server (primary or secondary) and trying to restart with the 2.2 binaries.

Will the above fix solve our issue as well?

Comment by auto [ 02/Oct/12 ]

Author:

{u'date': u'2012-10-02T10:13:15-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 do not ignore special _id unique index
Branch: v2.2
https://github.com/mongodb/mongo/commit/d168d1a3ee648c4dd39de70babed7a9945f75259

Comment by auto [ 02/Oct/12 ]

Author:

{u'date': u'2012-10-01T10:29:58-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 ignore dups for multikey index insertions during certain replication states
Branch: v2.2
https://github.com/mongodb/mongo/commit/d2d9f179a17f8b76b014b621bfc7a5bf67733633

Comment by auto [ 02/Oct/12 ]

Author:

{u'date': u'2012-09-28T13:20:59-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 add ROLLBACK to the list of states where we suppress duplicate key enforcement

During rollback, there is a stage where we apply all the docs we fetched to undo all the
rolled-back operations. This stage may encounter duplicate key errors, since we are
fetching the docs from the future and not from the time when they were recorded in the oplog.
Branch: v2.2
https://github.com/mongodb/mongo/commit/275f68924ab8cec65fafe35193be5cbd722b3bef

Comment by auto [ 02/Oct/12 ]

Author:

{u'date': u'2012-09-28T11:54:44-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 suppress unique index enforcement during STARTUP2 or RECOVERING secondary states

Operations involving unique indexes may be repeated during a recovery or initial sync. We need to ignore unique key violations in this situation. This is okay because by the time we reach the end of the oplog stream (and are finally caught up), all the violations should be resolved (as we should end up with an exact copy of the primary).
Branch: v2.2
https://github.com/mongodb/mongo/commit/1e852c70e5ad7907ec97142d27278a21324ae544

Comment by auto [ 02/Oct/12 ]

Author:

{u'date': u'2012-10-02T10:13:15-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 do not ignore special _id unique index
Branch: master
https://github.com/mongodb/mongo/commit/670f32edd8451c00a3cf6237231a434c2f7976c4

Comment by auto [ 01/Oct/12 ]

Author:

{u'date': u'2012-10-01T10:29:58-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 ignore dups for multikey index insertions during certain replication states
Branch: master
https://github.com/mongodb/mongo/commit/20701eeb63a48c5a997b33f1b1f0bb7ce00515bc

Comment by auto [ 28/Sep/12 ]

Author:

{u'date': u'2012-09-28T13:20:59-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 add ROLLBACK to the list of states where we suppress duplicate key enforcement

During rollback, there is a stage where we apply all the docs we fetched to undo all the
rolled-back operations. This stage may encounter duplicate key errors, since we are
fetching the docs from the future and not from the time when they were recorded in the oplog.
Branch: master
https://github.com/mongodb/mongo/commit/c51c807b7581a3f82c4d57b2b85be1193b2d81f3

Comment by auto [ 28/Sep/12 ]

Author:

{u'date': u'2012-09-28T11:54:44-07:00', u'email': u'milkie@10gen.com', u'name': u'Eric Milkie'}

Message: SERVER-6671 suppress unique index enforcement during STARTUP2 or RECOVERING secondary states

Operations involving unique indexes may be repeated during a recovery or initial sync. We need to ignore unique key violations in this situation. This is okay because by the time we reach the end of the oplog stream (and are finally caught up), all the violations should be resolved (as we should end up with an exact copy of the primary).
Branch: master
https://github.com/mongodb/mongo/commit/559d8c713ec9f81bded92da3af3b7d849756aafb

Comment by Ben Becker [ 31/Jul/12 ]

Just to note – the attached test is a bit nondeterministic due to killOp()/syncTail timing. Open to any advice/input on how to make it more deterministic.

Generated at Thu Feb 08 03:12:22 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.