[SERVER-9870] Rollback should not enforce unique indexes while applying ops Created: 06/Jun/13  Updated: 06/Dec/22  Resolved: 21/Dec/15

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: 2.2.3, 2.4.4, 2.5.0
Fix Version/s: 3.0.0

Type: Bug Priority: Major - P3
Reporter: Michael Henson Assignee: Backlog - Replication Team
Resolution: Done Votes: 3
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Ubuntu Precise 12.04 LTS


Attachments: File mongodb-2013-06-03.db-event4.abridged.log     File oplog.rs.bson    
Issue Links:
Depends
depends on SERVER-18215 DataReplicator Applier: Always disabl... Closed
Duplicate
is duplicated by SERVER-7016 Rollback should use initial sync logi... Closed
Assigned Teams:
Replication
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

We recently had an event where our primary server had to step down and after the new election occurred was put into a rollback state. During the rollback mongo encountered a unique index violation while attempting to write to the view_stats collection and promptly crashed.

Mon Jun  3 18:50:32 [repl writer worker 2] ERROR: writer worker caught exception: E11000 duplicate key error index: songza.view_stats.$view_1_host_1_pid_1  dup key: { : null, : null, : null } on: { ts: Timestamp 1370285310000|4, h: 1593562783886765644, v: 2, op: "u", ns: "songza.view_stats", o2: { _id: ObjectId('51ace4772a5a3f13accdbe17') }, o: { $set: { count: 2 }, $set: { sum_ms: 29 }, $set: { sum_square_ms: 565 } } }
Mon Jun  3 18:50:32 [repl writer worker 2]   Fatal Assertion 16360
0xb07561 0xacc8b3 0x9abaf6 0xadab5d 0xb4d3d9 0x7f845177be9a 0x7f8450a8ecbd 
/usr/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0xb07561]
/usr/bin/mongod(_ZN5mongo13fassertFailedEi+0xa3) [0xacc8b3]
/usr/bin/mongod(_ZN5mongo7replset14multiSyncApplyERKSt6vectorINS_7BSONObjESaIS2_EEPNS0_8SyncTailE+0x156) [0x9abaf6]
/usr/bin/mongod(_ZN5mongo10threadpool6Worker4loopEv+0x26d) [0xadab5d]
/usr/bin/mongod() [0xb4d3d9]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a) [0x7f845177be9a]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f8450a8ecbd]
Mon Jun  3 18:50:32 [repl writer worker 2] 
***aborting after fassert() failure
Mon Jun  3 18:50:32 Got signal: 6 (Aborted).
Mon Jun  3 18:50:32 Backtrace:
0xb07561 0x5598c9 0x7f84509d14a0 0x7f84509d1425 0x7f84509d4b8b 0xacc8ee 0x9abaf6 0xadab5d 0xb4d3d9 0x7f845177be9a 0x7f8450a8ecbd 
/usr/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0xb07561]
/usr/bin/mongod(_ZN5mongo10abruptQuitEi+0x399) [0x5598c9]
/lib/x86_64-linux-gnu/libc.so.6(+0x364a0) [0x7f84509d14a0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35) [0x7f84509d1425]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x17b) [0x7f84509d4b8b]
/usr/bin/mongod(_ZN5mongo13fassertFailedEi+0xde) [0xacc8ee]
/usr/bin/mongod(_ZN5mongo7replset14multiSyncApplyERKSt6vectorINS_7BSONObjESaIS2_EEPNS0_8SyncTailE+0x156) [0x9abaf6]
/usr/bin/mongod(_ZN5mongo10threadpool6Worker4loopEv+0x26d) [0xadab5d]
/usr/bin/mongod() [0xb4d3d9]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a) [0x7f845177be9a]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f8450a8ecbd]

I brought the machine back up out of the replicaset and was able to verify that there were 4 bad documents that lacked the host, view and pid fields. No other active hosts had these bad documents and it's technically highly unlikely that any of our code inserted them in the first place. I removed the bad documents and brought the member back into the replicaset, but it crashed again shortly thereafter with the same error. We were only able to resolve the issue by restoring the database from an EBS snapshot and letting it catch up again.

I've attached a log from the primary to this ticket.



 Comments   
Comment by Anthony MOI [ 02/Aug/13 ]

We had a similar behavior just after adding an index with

{ unique: true, dropDups: true }

. The index got created, and just after that, all our secondaries started to crash with errors "E11000 duplicate key error index" and similar stacks. The only way to stop this from happening again was to remove the index and re-sync secondaries from scratch.

All our instances are running MongoDB 2.4.3

Comment by Scott Hernandez (Inactive) [ 11/Jun/13 ]

Yes, this sounds like the exact situation which would cause this kind of issue. We will look through the oplog for some proof, but I think we can reproduce this in the future either way.

Thanks for the oplog data.

Comment by Michael Henson [ 08/Jun/13 ]

Here are the indexes that are currently on that collection:

[
{
"v" : 1,
"key" :

{ "_id" : 1 }

,
"ns" : "songza.view_stats",
"name" : "id"
},
{
"v" : 1,
"key" :

{ "view" : 1, "host" : 1, "pid" : 1 }

,
"unique" : true,
"ns" : "songza.view_stats",
"name" : "view_1_host_1_pid_1",
"background" : true
}
]

This collection acts as a staging ground to store performance information on various routes in our REST api. There are basically two sorts of operations that we perform on the documents in this collection. The first is to perform an upsert on a particular (view, host, pid) which will increment the count, sum_ms, and sum_square_ms fields. This action is triggered by a request being issued against our API for the given route (called view in this case). We don't actually perform an upsert for every request. Instead, we sample, let's say 10% of our requests. The second sort of operation occurs once per minute. We aggregate all of the documents for a given view and then delete them all one view at a time.

Comment by Scott Hernandez (Inactive) [ 07/Jun/13 ]

Thanks Michael,

Can you also provide your index definitions for that collection:

> use songza
> db.view_stats.getIndexes()

We believe the problem was a transitive index violation during the rollback because documents were being replaced by the current ones (as existed on the new/current primary) in an order different than happened in the original timeline. We are trying to track down where this might be possible by looking at the oplog as a hint since we can't really go back in time Once we get the indexes it should be a little more clear.

Do you think the application/data might have changed documents in an order where looking at two different points in time, in that small windows of time, there were two documents which had the same [view, host, pid] values (it seems like you have a unique index on the combination of those three fields)?

Comment by Michael Henson [ 07/Jun/13 ]

Here are the contents of the oplog on that machine from after 2013-06-03T18:48:00 (the log indicated this was the date to sync back to).

Comment by Scott Hernandez (Inactive) [ 06/Jun/13 ]

Would it be possible for you to upload the oplog from that "rollback" host? Really we just need the portion being used to do the rollback.

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