‘E11000 duplicate key error’ is an error that you might have encountered during the restore process. In this blog, we will talk about in what scenario you might face this error when restoring Oplog for PITR (point-in-time recovery).
You might wonder why this error will come during PITR as the operations in the Oplog are idempotent, meaning they always result in the same change to the database no matter how many times they’re performed. Now let’s see in which scenario you might face this error while applying Oplog.
I created a collection book with four documents with a unique compound index. So as per the application logic, the document is first inserted, updated, and deleted, but when a new document is re-inserted, it is created with the same keys and values on which a unique index is created.
Index:
{
"v" : 2,
"unique" : true,
"key" : {
"number" : 1,
"author" : 1
},
"name" : "number_1_author_1"
}
Now your application logic is written in such a way that it is doing insert, update, delete, and again inserting the document with the same values in the number and author keys on which the unique index is created. Below we have already inserted four docs, and now, we will update one of the below documents.
- First insert:
rs1:PRIMARY> db.book.find()
{ "_id" : ObjectId("641c11bfd0495f80ac5e610c"), "number" : 1, "title" : "harry potter", "author" : "shakespear" }
{ "_id" : ObjectId("641c11bfd0495f80ac5e610d"), "number" : 2, "title" : "game of thrones", "author" : "chetan" }
{ "_id" : ObjectId("641c11bfd0495f80ac5e610e"), "number" : 3, "title" : "2 states", "author" : "Peter" }
{ "_id" : ObjectId("641c11c1d0495f80ac5e610f"), "number" : 4, "title" : "a time to kill", "author" : "Graham" }
rs1:PRIMARY> Date()
Thu Mar 23 2023 08:45:55 GMT+0000 (UTC)
rs1:PRIMARY>
Corresponding ops in Oplog:
rs1:PRIMARY> db.oplog.rs.find({ns:"london.book"})
{ "op" : "i", "ns" : "london.book", "ui" : UUID("9cb7ae0a-6974-4363-ae24-0de30f0cd915"), "o" : { "_id" : ObjectId("641c11bfd0495f80ac5e610c"), "number" : 1, "title" : "harry potter", "author" : "shakespear" }, "ts" : Timestamp(1679561151, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T08:45:51.775Z") }
{ "op" : "i", "ns" : "london.book", "ui" : UUID("9cb7ae0a-6974-4363-ae24-0de30f0cd915"), "o" : { "_id" : ObjectId("641c11bfd0495f80ac5e610d"), "number" : 2, "title" : "game of thrones", "author" : "chetan" }, "ts" : Timestamp(1679561151, 2), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T08:45:51.778Z") }
{ "op" : "i", "ns" : "london.book", "ui" : UUID("9cb7ae0a-6974-4363-ae24-0de30f0cd915"), "o" : { "_id" : ObjectId("641c11bfd0495f80ac5e610e"), "number" : 3, "title" : "2 states", "author" : "Peter" }, "ts" : Timestamp(1679561151, 3), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T08:45:51.781Z") }
{ "op" : "i", "ns" : "london.book", "ui" : UUID("9cb7ae0a-6974-4363-ae24-0de30f0cd915"), "o" : { "_id" : ObjectId("641c11c1d0495f80ac5e610f"), "number" : 4, "title" : "a time to kill", "author" : "Graham" }, "ts" : Timestamp(1679561153, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T08:45:53.302Z") }
rs1:PRIMARY>
- After update:
rs1:PRIMARY> db.book.update({"number":4},{$set: {title: "Minion"}})
WriteResult({ "nMatched" : 1, "nUpserted" : 0, "nModified" : 1 })
rs1:PRIMARY> Date()
Thu Mar 23 2023 08:47:29 GMT+0000 (UTC)
rs1:PRIMARY> db.book.find()
{ "_id" : ObjectId("641c11bfd0495f80ac5e610c"), "number" : 1, "title" : "harry potter", "author" : "shakespear" }
{ "_id" : ObjectId("641c11bfd0495f80ac5e610d"), "number" : 2, "title" : "game of thrones", "author" : "chetan" }
{ "_id" : ObjectId("641c11bfd0495f80ac5e610e"), "number" : 3, "title" : "2 states", "author" : "Peter" }
{ "_id" : ObjectId("641c11c1d0495f80ac5e610f"), "number" : 4, "title" : "Minion", "author" : "Graham" }
rs1:PRIMARY>
Corresponding op in Oplog:
rs1:PRIMARY> db.oplog.rs.find({ns:"london.book"}).sort({$natural:-1}).limit(1)
{ "op" : "u", "ns" : "london.book", "ui" : UUID("9cb7ae0a-6974-4363-ae24-0de30f0cd915"), "o" : { "$v" : 1, "$set" : { "title" : "Minion" } }, "o2" : { "_id" : ObjectId("641c11c1d0495f80ac5e610f") }, "ts" : Timestamp(1679561243, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T08:47:23.448Z") }
rs1:PRIMARY>
- After remove:
rs1:PRIMARY> db.book.remove({number: 4})
WriteResult({ "nRemoved" : 1 })
rs1:PRIMARY> Date()
Thu Mar 23 2023 08:48:37 GMT+0000 (UTC)
rs1:PRIMARY> db.book.find()
{ "_id" : ObjectId("641c11bfd0495f80ac5e610c"), "number" : 1, "title" : "harry potter", "author" : "shakespear" }
{ "_id" : ObjectId("641c11bfd0495f80ac5e610d"), "number" : 2, "title" : "game of thrones", "author" : "chetan" }
{ "_id" : ObjectId("641c11bfd0495f80ac5e610e"), "number" : 3, "title" : "2 states", "author" : "Peter" }
rs1:PRIMARY>
Corresponding op in Oplog:
rs1:PRIMARY> db.oplog.rs.find({ns:"london.book"}).sort({$natural:-1}).limit(1)
{ "op" : "d", "ns" : "london.book", "ui" : UUID("9cb7ae0a-6974-4363-ae24-0de30f0cd915"), "o" : { "_id" : ObjectId("641c11c1d0495f80ac5e610f") }, "ts" : Timestamp(1679561315, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T08:48:35.203Z") }
rs1:PRIMARY>
- Below we will insert a new document:
rs1:PRIMARY> db.book.insert({"number" : 4, "title" : "Stranger things", "author" : "Graham" })
WriteResult({ "nInserted" : 1 })
rs1:PRIMARY> Date()
Thu Mar 23 2023 08:50:46 GMT+0000 (UTC)
rs1:PRIMARY> db.book.find()
{ "_id" : ObjectId("641c11bfd0495f80ac5e610c"), "number" : 1, "title" : "harry potter", "author" : "shakespear" }
{ "_id" : ObjectId("641c11bfd0495f80ac5e610d"), "number" : 2, "title" : "game of thrones", "author" : "chetan" }
{ "_id" : ObjectId("641c11bfd0495f80ac5e610e"), "number" : 3, "title" : "2 states", "author" : "Peter" }
{ "_id" : ObjectId("641c12e4d0495f80ac5e6111"), "number" : 4, "title" : "Stranger things", "author" : "Graham" }
rs1:PRIMARY>
Corresponding op in Oplog:
rs1:PRIMARY> db.oplog.rs.find({ns:"london.book"}).sort({$natural:-1}).limit(1)
{ "op" : "i", "ns" : "london.book", "ui" : UUID("9cb7ae0a-6974-4363-ae24-0de30f0cd915"), "o" : { "_id" : ObjectId("641c12e4d0495f80ac5e6111"), "number" : 4, "title" : "Stranger things", "author" : "Graham" }, "ts" : Timestamp(1679561444, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T08:50:44.861Z") }
rs1:PRIMARY>
- Take mongodump of database london:
# mongodump
2023-03-23T08:52:01.032+0000 writing admin.system.version to dump/admin/system.version.bson
2023-03-23T08:52:01.033+0000 done dumping admin.system.version (1 document)
2023-03-23T08:52:01.033+0000 writing london.book to dump/london/book.bson
2023-03-23T08:52:01.034+0000 done dumping london.book (4 documents)
#
- We will again insert a new doc:
rs1:PRIMARY> db.book.insert({"number" : 5, "title" : "Stranger things", "author" : "Graham" })
WriteResult({ "nInserted" : 1 })
rs1:PRIMARY> Date()
Thu Mar 23 2023 08:52:37 GMT+0000 (UTC)
rs1:PRIMARY> db.book.find()
{ "_id" : ObjectId("641c11bfd0495f80ac5e610c"), "number" : 1, "title" : "harry potter", "author" : "shakespear" }
{ "_id" : ObjectId("641c11bfd0495f80ac5e610d"), "number" : 2, "title" : "game of thrones", "author" : "chetan" }
{ "_id" : ObjectId("641c11bfd0495f80ac5e610e"), "number" : 3, "title" : "2 states", "author" : "Peter" }
{ "_id" : ObjectId("641c12e4d0495f80ac5e6111"), "number" : 4, "title" : "Stranger things", "author" : "Graham" }
{ "_id" : ObjectId("641c1352673573868f17cacf"), "number" : 5, "title" : "Stranger things", "author" : "Graham" }
rs1:PRIMARY>
Corresponding op in Oplog:
rs1:PRIMARY> db.oplog.rs.find({ns:"london.book"}).sort({$natural:-1}).limit(1)
{ "op" : "i", "ns" : "london.book", "ui" : UUID("9cb7ae0a-6974-4363-ae24-0de30f0cd915"), "o" : { "_id" : ObjectId("641c1352673573868f17cacf"), "number" : 5, "title" : "Stranger things", "author" : "Graham" }, "ts" : Timestamp(1679561554, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T08:52:34.739Z") }
rs1:PRIMARY>
- Take incremental Oplog backup.
After first Oplog dump:
# mongodump --db=local --collection=oplog.rs --query '{"ts":{"$gte":{"$timestamp": {"i":1, "t": 1679561120}}, "$lte":{"$timestamp": {"i":2, "t": 1679561151}}}}'
2023-03-23T08:59:29.667+0000 writing local.oplog.rs to dump/local/oplog.rs.bson
2023-03-23T08:59:29.668+0000 done dumping local.oplog.rs (7 documents)
#
# cd dump/local/
# ls -ltrh
total 8.0K
-rw-r--r-- 1 root root 193 Mar 23 08:59 oplog.rs.metadata.json
-rw-r--r-- 1 root root 1.1K Mar 23 08:59 oplog.rs.bson
# mv oplog.rs.metadata.json oplog_1.rs.metadata.json
# mv oplog.rs.bson oplog_1.rs.bson
# ls -ltr
total 8
-rw-r--r-- 1 root root 193 Mar 23 08:59 oplog_1.rs.metadata.json
-rw-r--r-- 1 root root 1.1K Mar 23 08:59 oplog_1.rs.bson
#
# bsondump oplog_1.rs.bson | tail -n 1
2023-03-23T09:01:50.590+0000 7 objects found
{"op":"i","ns":"london.book","ui":{"$binary":{"base64":"nLeuCml0Q2OuJA3jDwzZFQ==","subType":"04"}},"o":{"_id":{"$oid":"641c11bfd0495f80ac5e610d"},"number":{"$numberDouble":"2.0"},"title":"game of thrones","author":"chetan"},"ts":{"$timestamp":{"t":1679561151,"i":2}},"t":{"$numberLong":"1"},"v":{"$numberLong":"2"},"wall":{"$date":{"$numberLong":"1679561151778"}}}
#
Above is the last document of the first Oplog backup, i.e., till {“$timestamp”:{“t”:1679561151,”i”:2}}.
After second Oplog dump (incremental):
# mongodump --db=local --collection=oplog.rs --query '{"ts":{"$gt":{"$timestamp": {"i":2, "t": 1679561151}}, "$lte":{"$timestamp": {"i":1, "t": 1679562180}}}}'
2023-03-23T09:03:27.070+0000 writing local.oplog.rs to dump/local/oplog.rs.bson
2023-03-23T09:03:27.071+0000 done dumping local.oplog.rs (107 documents)
#
# ls -ltrh
total 24K
-rw-r--r-- 1 root root 193 Mar 23 08:59 oplog_1.rs.metadata.json
-rw-r--r-- 1 root root 1.1K Mar 23 08:59 oplog_1.rs.bson
-rw-r--r-- 1 root root 193 Mar 23 09:03 oplog.rs.metadata.json
-rw-r--r-- 1 root root 12K Mar 23 09:03 oplog.rs.bson
#
# bsondump oplog.rs.bson | head -n 1
2023-03-23T09:04:28.976+0000 107 objects found
{"op":"i","ns":"london.book","ui":{"$binary":{"base64":"nLeuCml0Q2OuJA3jDwzZFQ==","subType":"04"}},"o":{"_id":{"$oid":"641c11bfd0495f80ac5e610e"},"number":{"$numberDouble":"3.0"},"title":"2 states","author":"Peter"},"ts":{"$timestamp":{"t":1679561151,"i":3}},"t":{"$numberLong":"1"},"v":{"$numberLong":"2"},"wall":{"$date":{"$numberLong":"1679561151781"}}}
#
Above is the starting document of the second/incremental Oplog backup i.e., $timestamp”:{“t”:1679561151,”i”:3}}
- Drop database:
rs1:PRIMARY> db.dropDatabase()
{
"dropped" : "london",
"ok" : 1,
"$clusterTime" : {
"clusterTime" : Timestamp(1679562380, 2),
"signature" : {
"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
"keyId" : NumberLong(0)
}
},
"operationTime" : Timestamp(1679562380, 2)
}
rs1:PRIMARY> Date()
Thu Mar 23 2023 09:06:37 GMT+0000 (UTC)
rs1:PRIMARY>
Corresponding op in Oplog:
rs1:PRIMARY> db.oplog.rs.find({ns:"london.$cmd"}).sort({$natural:-1}).limit(1)
{ "op" : "c", "ns" : "london.$cmd", "o" : { "dropDatabase" : 1 }, "ts" : Timestamp(1679562380, 2), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T09:06:20.121Z") }
rs1:PRIMARY>
- First, we will restore the database from the dump, which we took in step five:
# mongorestore dump/london/book.bson
2023-03-23T09:09:05.433+0000 checking for collection data in dump/london/book.bson
2023-03-23T09:09:05.433+0000 reading metadata for london.book from dump/london/book.metadata.json
2023-03-23T09:09:05.448+0000 restoring london.book from dump/london/book.bson
2023-03-23T09:09:05.490+0000 finished restoring london.book (4 documents, 0 failures)
2023-03-23T09:09:05.490+0000 restoring indexes for collection london.book from metadata
2023-03-23T09:09:05.490+0000 index: &idx.IndexDocument{Options:primitive.M{"name":"number_1_author_1", "unique":true, "v":2}, Key:primitive.D{primitive.E{Key:"number", Value:1}, primitive.E{Key:"author", Value:1}}, PartialFilterExpression:primitive.D(nil)}
2023-03-23T09:09:05.526+0000 4 document(s) restored successfully. 0 document(s) failed to restore.
#
The above-restored documents match until step five before taking the dump of london database:
rs1:PRIMARY> db.book.find()
{ "_id" : ObjectId("641c11bfd0495f80ac5e610c"), "number" : 1, "title" : "harry potter", "author" : "shakespear" }
{ "_id" : ObjectId("641c11bfd0495f80ac5e610d"), "number" : 2, "title" : "game of thrones", "author" : "chetan" }
{ "_id" : ObjectId("641c11bfd0495f80ac5e610e"), "number" : 3, "title" : "2 states", "author" : "Peter" }
{ "_id" : ObjectId("641c12e4d0495f80ac5e6111"), "number" : 4, "title" : "Stranger things", "author" : "Graham" }
rs1:PRIMARY>
Corresponding ops in Oplog after restore from dump:
{ "lsid" : { "id" : UUID("ce17fa90-9f06-4710-9b3b-3f4e9484e213"), "uid" : BinData(0,"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=") }, "txnNumber" : NumberLong(1), "op" : "i", "ns" : "london.book", "ui" : UUID("9e30c316-b21a-4f43-bbcc-d80593001391"), "o" : { "_id" : ObjectId("641c12e4d0495f80ac5e6111"), "number" : 4, "title" : "Stranger things", "author" : "Graham" }, "ts" : Timestamp(1679562545, 5), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T09:09:05.451Z"), "stmtId" : 3, "prevOpTime" : { "ts" : Timestamp(1679562545, 4), "t" : NumberLong(1) } }
{ "lsid" : { "id" : UUID("ce17fa90-9f06-4710-9b3b-3f4e9484e213"), "uid" : BinData(0,"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=") }, "txnNumber" : NumberLong(1), "op" : "i", "ns" : "london.book", "ui" : UUID("9e30c316-b21a-4f43-bbcc-d80593001391"), "o" : { "_id" : ObjectId("641c11bfd0495f80ac5e610e"), "number" : 3, "title" : "2 states", "author" : "Peter" }, "ts" : Timestamp(1679562545, 4), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T09:09:05.451Z"), "stmtId" : 2, "prevOpTime" : { "ts" : Timestamp(1679562545, 3), "t" : NumberLong(1) } }
{ "lsid" : { "id" : UUID("ce17fa90-9f06-4710-9b3b-3f4e9484e213"), "uid" : BinData(0,"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=") }, "txnNumber" : NumberLong(1), "op" : "i", "ns" : "london.book", "ui" : UUID("9e30c316-b21a-4f43-bbcc-d80593001391"), "o" : { "_id" : ObjectId("641c11bfd0495f80ac5e610d"), "number" : 2, "title" : "game of thrones", "author" : "chetan" }, "ts" : Timestamp(1679562545, 3), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T09:09:05.451Z"), "stmtId" : 1, "prevOpTime" : { "ts" : Timestamp(1679562545, 2), "t" : NumberLong(1) } }
{ "lsid" : { "id" : UUID("ce17fa90-9f06-4710-9b3b-3f4e9484e213"), "uid" : BinData(0,"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=") }, "txnNumber" : NumberLong(1), "op" : "i", "ns" : "london.book", "ui" : UUID("9e30c316-b21a-4f43-bbcc-d80593001391"), "o" : { "_id" : ObjectId("641c11bfd0495f80ac5e610c"), "number" : 1, "title" : "harry potter", "author" : "shakespear" }, "ts" : Timestamp(1679562545, 2), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T09:09:05.451Z"), "stmtId" : 0, "prevOpTime" : { "ts" : Timestamp(0, 0), "t" : NumberLong(-1) } }
- Now we will check in Oplog backup to which document the data has been recovered and from which Oplog file we need to apply ops. We can see that documents in the first Oplog backup have been restored in step nine. To verify, below is the last ops entry in the first Oplog backup:
# bsondump oplog_1.rs.bson | tail -n 1
2023-03-23T09:11:40.539+0000 7 objects found
{"op":"i","ns":"london.book","ui":{"$binary":{"base64":"nLeuCml0Q2OuJA3jDwzZFQ==","subType":"04"}},"o":{"_id":{"$oid":"641c11bfd0495f80ac5e610d"},"number":{"$numberDouble":"2.0"},"title":"game of thrones","author":"chetan"},"ts":{"$timestamp":{"t":1679561151,"i":2}},"t":{"$numberLong":"1"},"v":{"$numberLong":"2"},"wall":{"$date":{"$numberLong":"1679561151778"}}}
#
Now we need to replay the second Oplog backup just before the drop command ops (we already have the time of drop database command in step eight) for PITR (we can see below ops is already available, but we cannot split the BSON file based on the time or ops, so we need to apply full Oplog slice):
# bsondump oplog.rs.bson | head -n 1
2023-03-23T09:12:31.646+0000 107 objects found
{"op":"i","ns":"london.book","ui":{"$binary":{"base64":"nLeuCml0Q2OuJA3jDwzZFQ==","subType":"04"}},"o":{"_id":{"$oid":"641c11bfd0495f80ac5e610e"},"number":{"$numberDouble":"3.0"},"title":"2 states","author":"Peter"},"ts":{"$timestamp":{"t":1679561151,"i":3}},"t":{"$numberLong":"1"},"v":{"$numberLong":"2"},"wall":{"$date":{"$numberLong":"1679561151781"}}}
#
#mongorestore --oplogFile=oplog.rs.bson --oplogReplay --oplogLimit 1679562370:1 /root/dump/local/
2023-03-23T09:13:18.969+0000 preparing collections to restore from
2023-03-23T09:13:18.969+0000 don't know what to do with file "/root/dump/local/oplog.rs.bson", skipping…
2023-03-23T09:13:18.969+0000 don't know what to do with file "/root/dump/local/oplog.rs.metadata.json", skipping…
2023-03-23T09:13:18.969+0000 don't know what to do with file "/root/dump/local/oplog_1.rs.bson", skipping…
2023-03-23T09:13:18.969+0000 don't know what to do with file "/root/dump/local/oplog_1.rs.metadata.json", skipping…
2023-03-23T09:13:18.969+0000 replaying oplog
2023-03-23T09:13:18.978+0000 Failed: restore error: error applying oplog: applyOps: (DuplicateKey) E11000 duplicate key error collection: london.book index: number_1_author_1 dup key: { number: 4.0, author: "Graham" }
2023-03-23T09:13:18.978+0000 0 document(s) restored successfully. 0 document(s) failed to restore.
#
We can see Oplog replay got failed due to a unique index constraint, as we can see the ops associated with { number: 4.0, author: “Graham” } is already present in the database:
{ "_id" : ObjectId("641c12e4d0495f80ac5e6111"), "number" : 4, "title" : "Stranger things", "author" : "Graham" }
Below are the ops from the incremental Oplog backup slice associated with { number: 4.0, author: “Graham” }. So if you see the first ops below is an insert op with a different _id (“o”:{“_id”:{“$oid”:”641c11c1d0495f80ac5e610f“}) which was inserted in the beginning. When Oplog tries to replay the below op, it sees that there is already a document with a different _id associated with { number: 4.0, author: “Graham” }, and it cannot apply this op due to a unique index violation. Thus failing to apply the Oplog and PITR.
# bsondump oplog.rs.bson | grep Graham
{"op":"i","ns":"london.book","ui":{"$binary":{"base64":"nLeuCml0Q2OuJA3jDwzZFQ==","subType":"04"}},"o":{"_id":{"$oid":"641c11c1d0495f80ac5e610f"},"number":{"$numberDouble":"4.0"},"title":"a time to kill","author":"Graham"},"ts":{"$timestamp":{"t":1679561153,"i":1}},"t":{"$numberLong":"1"},"v":{"$numberLong":"2"},"wall":{"$date":{"$numberLong":"1679561153302"}}}
{"op":"i","ns":"london.book","ui":{"$binary":{"base64":"nLeuCml0Q2OuJA3jDwzZFQ==","subType":"04"}},"o":{"_id":{"$oid":"641c12e4d0495f80ac5e6111"},"number":{"$numberDouble":"4.0"},"title":"Stranger things","author":"Graham"},"ts":{"$timestamp":{"t":1679561444,"i":1}},"t":{"$numberLong":"1"},"v":{"$numberLong":"2"},"wall":{"$date":{"$numberLong":"1679561444861"}}}
{"op":"i","ns":"london.book","ui":{"$binary":{"base64":"nLeuCml0Q2OuJA3jDwzZFQ==","subType":"04"}},"o":{"_id":{"$oid":"641c1352673573868f17cacf"},"number":{"$numberDouble":"5.0"},"title":"Stranger things","author":"Graham"},"ts":{"$timestamp":{"t":1679561554,"i":1}},"t":{"$numberLong":"1"},"v":{"$numberLong":"2"},"wall":{"$date":{"$numberLong":"1679561554739"}}}
2023-03-23T09:14:34.118+0000 107 objects found
#
There are two solutions for the above issue:
-
- If the incremental Oplog backup is having only ops starting since the last op that is in the database backup.
- Have Percona Backup for MongoDB (PBM) configured and let PBM handle all the above manual processes (restoring dump + applying Oplog for PITR) automatically.
To overcome the above issue, I configured the PBM on the same replica set and took a backup (both full and incremental Oplog). Here’s how to install, set up, and configure PBM.
Below is the process I followed again from step one to step six for PBM, and below are the corresponding ops in Oplog:
rs1:PRIMARY> db.oplog.rs.find({ns:"london.book"})
{ "op" : "i", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "_id" : ObjectId("641c3b0a6eddc54ce4f75df8"), "number" : 1, "title" : "harry potter", "author" : "shakespear" }, "ts" : Timestamp(1679571722, 2), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T11:42:02.988Z") }
{ "op" : "i", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "_id" : ObjectId("641c3b0a6eddc54ce4f75df9"), "number" : 2, "title" : "game of thrones", "author" : "chetan" }, "ts" : Timestamp(1679571722, 3), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T11:42:02.990Z") }
{ "op" : "i", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "_id" : ObjectId("641c3b0a6eddc54ce4f75dfa"), "number" : 3, "title" : "2 states", "author" : "Peter" }, "ts" : Timestamp(1679571722, 4), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T11:42:02.992Z") }
{ "op" : "i", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "_id" : ObjectId("641c3b0b6eddc54ce4f75dfb"), "number" : 4, "title" : "a time to kill", "author" : "Graham" }, "ts" : Timestamp(1679571723, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T11:42:03.840Z") }
{ "op" : "u", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "$v" : 1, "$set" : { "title" : "Minion" } }, "o2" : { "_id" : ObjectId("641c3b0b6eddc54ce4f75dfb") }, "ts" : Timestamp(1679571914, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T11:45:14.026Z") }
{ "op" : "d", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "_id" : ObjectId("641c3b0b6eddc54ce4f75dfb") }, "ts" : Timestamp(1679573573, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T12:12:53.817Z") }
{ "op" : "i", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "_id" : ObjectId("641c42519662ff210d35343e"), "number" : 4, "title" : "Stranger things", "author" : "Graham" }, "ts" : Timestamp(1679573585, 3), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T12:13:05.567Z") }
{ "op" : "i", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "_id" : ObjectId("641c433b474b755a080f10bb"), "number" : 5, "title" : "Stranger things", "author" : "Graham" }, "ts" : Timestamp(1679573819, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T12:16:59.806Z") }
Below are the two full backups taken + incremental Oplog backup:
# pbm list
Backup snapshots:
2023-03-23T11:52:05Z <logical> [restore_to_time: 2023-03-23T11:52:10Z]
2023-03-23T12:14:04Z <logical> [restore_to_time: 2023-03-23T12:14:08Z]
PITR <off>:
2023-03-23T11:52:11Z - 2023-03-23T13:06:45Z
#
Above, you can see the latest backup was taken till 2023-03-23T12:14:08, and incremental Oplog backup was taken till 2023-03-23T13:06:45.
Now we will drop the database:
rs1:PRIMARY> db.dropDatabase()
{
"dropped" : "london",
"ok" : 1,
"$clusterTime" : {
"clusterTime" : Timestamp(1679576445, 4),
"signature" : {
"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
"keyId" : NumberLong(0)
}
},
"operationTime" : Timestamp(1679576445, 4)
}
rs1:PRIMARY> Date()
Thu Mar 23 2023 13:00:51 GMT+0000 (UTC)
Now we will restore the database and perform PITR using PBM:
# pbm restore --time="2023-03-23T13:00:44"
Below are the logs for restore + PITR:
# pbm logs --tail=100 | grep -i restore
2023-03-23T13:07:37Z I [rs1/127.0.0.1:27017] got command pitrestore [name: 2023-03-23T13:07:37.410117048Z, point-in-time ts: 1679576444] <ts: 1679576857>
2023-03-23T13:07:37Z I [rs1/127.0.0.1:27017] [pitrestore/2023-03-23T13:07:37.410117048Z] to time: 2023-03-23T13:00:44Z
2023-03-23T13:07:37Z I [rs1/127.0.0.1:27017] [pitrestore/2023-03-23T13:07:37.410117048Z] recovery started
2023-03-23T13:07:38Z I [rs1/127.0.0.1:27017] [pitrestore/2023-03-23T13:07:37.410117048Z] moving to state running
2023-03-23T13:07:41Z I [rs1/127.0.0.1:27017] [pitrestore/2023-03-23T13:07:37.410117048Z] restoring users and roles
2023-03-23T13:07:41Z I [rs1/127.0.0.1:27017] [pitrestore/2023-03-23T13:07:37.410117048Z] moving to state dumpDone
2023-03-23T13:07:43Z I [rs1/127.0.0.1:27017] [pitrestore/2023-03-23T13:07:37.410117048Z] starting oplog replay
2023-03-23T13:07:43Z I [rs1/127.0.0.1:27017] [pitrestore/2023-03-23T13:07:37.410117048Z] oplog replay finished on {1679576440 2}
2023-03-23T13:07:44Z I [rs1/127.0.0.1:27017] [pitrestore/2023-03-23T13:07:37.410117048Z] recovery successfully finished
Below are the documents after restore + PITR via PBM:
rs1:PRIMARY> db.book.find()
{ "_id" : ObjectId("641c3b0a6eddc54ce4f75df8"), "number" : 1, "title" : "harry potter", "author" : "shakespear" }
{ "_id" : ObjectId("641c3b0a6eddc54ce4f75df9"), "number" : 2, "title" : "game of thrones", "author" : "chetan" }
{ "_id" : ObjectId("641c3b0a6eddc54ce4f75dfa"), "number" : 3, "title" : "2 states", "author" : "Peter" }
{ "_id" : ObjectId("641c42519662ff210d35343e"), "number" : 4, "title" : "Stranger things", "author" : "Graham" }
{ "_id" : ObjectId("641c433b474b755a080f10bb"), "number" : 5, "title" : "Stranger things", "author" : "Graham"
rs1:PRIMARY>
Below are the Oplog entries after PBM restore, and we can see that PBM restored the relevant base backup first and started applying Oplog after the last op in the base backup.
rs1:PRIMARY> db.oplog.rs.find({ns:/^london/}).sort({$natural:-1})
{ "op" : "i", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "_id" : ObjectId("641c433b474b755a080f10bb"), "number" : 5, "title" : "Stranger things", "author" : "Graham" }, "ts" : Timestamp(1679576863, 9), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T13:07:43.222Z") }
{ "op" : "c", "ns" : "london.$cmd", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "commitIndexBuild" : "book", "indexBuildUUID" : UUID("c95a669a-9e62-4a59-974a-a702c52127da"), "indexes" : [ { "v" : 2, "unique" : true, "key" : { "number" : 1, "author" : 1 }, "name" : "number_1_author_1" } ] }, "ts" : Timestamp(1679576861, 8), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T13:07:41.159Z") }
{ "op" : "c", "ns" : "london.$cmd", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "startIndexBuild" : "book", "indexBuildUUID" : UUID("c95a669a-9e62-4a59-974a-a702c52127da"), "indexes" : [ { "v" : 2, "unique" : true, "key" : { "number" : 1, "author" : 1 }, "name" : "number_1_author_1" } ] }, "ts" : Timestamp(1679576861, 6), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T13:07:41.152Z") }
{ "lsid" : { "id" : UUID("6ec94b0c-098b-4986-a971-078c36761cf5"), "uid" : BinData(0,"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=") }, "txnNumber" : NumberLong(3), "op" : "i", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "_id" : ObjectId("641c42519662ff210d35343e"), "number" : 4, "title" : "Stranger things", "author" : "Graham" }, "ts" : Timestamp(1679576861, 4), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T13:07:41.006Z"), "stmtId" : 3, "prevOpTime" : { "ts" : Timestamp(1679576861, 3), "t" : NumberLong(1) } }
{ "lsid" : { "id" : UUID("6ec94b0c-098b-4986-a971-078c36761cf5"), "uid" : BinData(0,"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=") }, "txnNumber" : NumberLong(3), "op" : "i", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "_id" : ObjectId("641c3b0a6eddc54ce4f75dfa"), "number" : 3, "title" : "2 states", "author" : "Peter" }, "ts" : Timestamp(1679576861, 3), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T13:07:41.006Z"), "stmtId" : 2, "prevOpTime" : { "ts" : Timestamp(1679576861, 2), "t" : NumberLong(1) } }
{ "lsid" : { "id" : UUID("6ec94b0c-098b-4986-a971-078c36761cf5"), "uid" : BinData(0,"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=") }, "txnNumber" : NumberLong(3), "op" : "i", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "_id" : ObjectId("641c3b0a6eddc54ce4f75df9"), "number" : 2, "title" : "game of thrones", "author" : "chetan" }, "ts" : Timestamp(1679576861, 2), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T13:07:41.006Z"), "stmtId" : 1, "prevOpTime" : { "ts" : Timestamp(1679576861, 1), "t" : NumberLong(1) } }
{ "lsid" : { "id" : UUID("6ec94b0c-098b-4986-a971-078c36761cf5"), "uid" : BinData(0,"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=") }, "txnNumber" : NumberLong(3), "op" : "i", "ns" : "london.book", "ui" : UUID("5959bd53-6986-4d0d-a72a-9fac81113934"), "o" : { "_id" : ObjectId("641c3b0a6eddc54ce4f75df8"), "number" : 1, "title" : "harry potter", "author" : "shakespear" }, "ts" : Timestamp(1679576861, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2023-03-23T13:07:41.006Z"), "stmtId" : 0, "prevOpTime" : { "ts" : Timestamp(0, 0), "t" : NumberLong(-1) } }
Above, you can see that PBM has applied the latest backup and performed the PITR automatically. The reason that we didn’t face the ‘E11000 duplicate key error’ during PITR using PBM is that PBM handles it automatically, from which Oplog entry it needs to apply the ops after the restore from a full backup. PBM will ensure consistency while restoring a full backup + incremental Oplog backup.
Here’s how Percona Backup for MongoDB works.
Conclusion
So above, we can see how to avoid the ‘E11000 duplicate key error’ using PBM automatically. Another way is also possible, as explained above, but that will require a manual process. Why go with a manual process when PBM is open source, does not require any license, and can handle it automatically?
Please check out our products for Percona Server for MongoDB, Percona Backup for MongoDB, and Percona Operator for MongoDB. We also recommend checking out our blog MongoDB: Why Pay for Enterprise When Open Source Has You Covered?
Percona Distribution for MongoDB is a freely available MongoDB database alternative, giving you a single solution that combines the best and most important enterprise components from the open source community, designed and tested to work together.
Download Percona Distribution for MongoDB Today!
This post was originally published in April 2023 and was updated in April 2025. When asked “Is MongoDB open source?”, at Percona, our definitive answer is “no.” Let’s start with this: MongoDB is accurately referred to as source-available software. Whereas many open source software offerings — like the community version of MySQL — use the […]
One of the main features that I like about the 
