[SERVER-16339] Updating by _id field with a regex breaks replication in 2.4 Created: 26/Nov/14  Updated: 18/Feb/15  Resolved: 18/Feb/15

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: 2.4.12
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Andre de Frere Assignee: Unassigned
Resolution: Won't Fix Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
is duplicated by SERVER-16359 Upserting a document where the _id fi... Closed
Related
is related to SERVER-9502 Using regex in _id breaks replication Closed
Operating System: ALL
Steps To Reproduce:

var date = new ISODate()
db.test.insert( { _id : "A", date : new ISODate() } )
db.test.update( { _id : /[A-Z]/, date : { $lte : date } }, { $set : { date : date } }, { multi : true, upsert : true } )

Participants:

 Description   

Appears to be an unresolved issue that was previously expected fixed in SERVER-9502.

The following steps will cause Secondaries to fail:

var date = new ISODate()
db.test.insert( { _id : "A", date : new ISODate() } )
db.test.update( { _id : /[A-Z]/, date : { $lte : date } }, { $set : { date : date } }, { multi : true, upsert : true } )

Error from Secondaries:

Thu Nov 27 10:29:38.488 [repl writer worker 1] ERROR: writer worker caught exception: cannot change _id of a document old:{ _id: "A", date: new Date(1417044555726) } new:{ _id: /[A-Z]/, date: new Date(1417044555721) } on: { ts: Timestamp 1417044578000|1, h: 8883000633175610356, v: 2, op: "i", ns: "test.test", o: { _id: /[A-Z]/, date: new Date(1417044555721) } }
Thu Nov 27 10:29:38.489 [repl writer worker 1]   Fatal Assertion 16360
0x1004520cb 0x10042b2e7 0x10034134f 0x1004326f8 0x100484c65 0x7fff8c0b62fc 0x7fff8c0b6279 0x7fff8c0b44b1
 0   mongod                              0x00000001004520cb _ZN5mongo15printStackTraceERSo + 43
 1   mongod                              0x000000010042b2e7 _ZN5mongo13fassertFailedEi + 151
 2   mongod                              0x000000010034134f _ZN5mongo7replset14multiSyncApplyERKSt6vectorINS_7BSONObjESaIS2_EEPNS0_8SyncTailE + 271
 3   mongod                              0x00000001004326f8 _ZN5mongo10threadpool6Worker4loopEv + 138
 4   mongod                              0x0000000100484c65 thread_proxy + 229
 5   libsystem_pthread.dylib             0x00007fff8c0b62fc _pthread_body + 131
 6   libsystem_pthread.dylib             0x00007fff8c0b6279 _pthread_body + 0
 7   libsystem_pthread.dylib             0x00007fff8c0b44b1 thread_start + 13
Thu Nov 27 10:29:38.491 [repl writer worker 1]
 
***aborting after fassert() failure
 
 
Thu Nov 27 10:29:38.492 Got signal: 6 (Abort trap: 6).
 
Thu Nov 27 10:29:38.494 Backtrace:
0x1004520cb 0x1000016b1 0x7fff85f06f1a 0x5 0x7fff844bfb73 0x10042b325 0x10034134f 0x1004326f8 0x100484c65 0x7fff8c0b62fc 0x7fff8c0b6279 0x7fff8c0b44b1
 0   mongod                              0x00000001004520cb _ZN5mongo15printStackTraceERSo + 43
 1   mongod                              0x00000001000016b1 _ZN5mongo10abruptQuitEi + 225
 2   libsystem_platform.dylib            0x00007fff85f06f1a _sigtramp + 26
 3   ???                                 0x0000000000000005 0x0 + 5
 4   libsystem_c.dylib                   0x00007fff844bfb73 abort + 129
 5   mongod                              0x000000010042b325 _ZN5mongo13fassertFailedEi + 213
 6   mongod                              0x000000010034134f _ZN5mongo7replset14multiSyncApplyERKSt6vectorINS_7BSONObjESaIS2_EEPNS0_8SyncTailE + 271
 7   mongod                              0x00000001004326f8 _ZN5mongo10threadpool6Worker4loopEv + 138
 8   mongod                              0x0000000100484c65 thread_proxy + 229
 9   libsystem_pthread.dylib             0x00007fff8c0b62fc _pthread_body + 131
 10  libsystem_pthread.dylib             0x00007fff8c0b6279 _pthread_body + 0
 11  libsystem_pthread.dylib             0x00007fff8c0b44b1 thread_start + 13



 Comments   
Comment by Ronan Bohan [ 01/Dec/14 ]

Adding some clarification to the description above:

Line 2 inserts a normal document with '_id' set to 'A'. This is replicated as normal to the secondaries.

Line 3 is the real problem in which an upsert command is issued but no matching documents are found. In MongoDB 2.4.x this will create a new, malformed document in which the value of '_id' is the regex '/[A-Z]/'. In the presence of the document from the preceding line it will cause the secondaries to crash.

After running the code above we get the following in MongoDB 2.4.12:

replset:PRIMARY> var date = new ISODate()
replset:PRIMARY> db.test.insert( { _id : "A", date : new ISODate() } )
replset:PRIMARY> db.test.update( { _id : /[A-Z]/, date : { $lte : date } }, { $set : { date : date } }, { multi : true, upsert : true } )
replset:PRIMARY>
Mon Dec  1 12:49:08.797 DBClientCursor::init call() failed
>
Mon Dec  1 12:49:09.765 trying reconnect to 127.0.0.1:27017
Mon Dec  1 12:49:09.765 reconnect 127.0.0.1:27017 ok
replset:SECONDARY> rs.slaveOk()
replset:SECONDARY> db.test.find()
{ "_id" : "A", "date" : ISODate("2014-12-01T12:48:59.680Z") }
{ "_id" : /[A-Z]/, "date" : ISODate("2014-12-01T12:48:55.230Z") }
replset:SECONDARY> use local
switched to db local
replset:SECONDARY> db.oplog.rs.find()
{ "ts" : Timestamp(1417438065, 1), "h" : NumberLong(0), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "initiating set" } }
{ "ts" : Timestamp(1417438139, 1), "h" : NumberLong("-7187006773419573231"), "v" : 2, "op" : "i", "ns" : "test.test", "o" : { "_id" : "A", "date" : ISODate("2014-12-01T12:48:59.680Z") } }
{ "ts" : Timestamp(1417438145, 1), "h" : NumberLong("-877234760831691788"), "v" : 2, "op" : "i", "ns" : "test.test", "o" : { "_id" : /[A-Z]/, "date" : ISODate("2014-12-01T12:48:55.230Z") } }
replset:SECONDARY>

MongoDB 2.6.5 does not appear to be affected:

replset:PRIMARY> var date = new ISODate()
replset:PRIMARY> db.test.insert( { _id : "A", date : new ISODate() } )
WriteResult({ "nInserted" : 1 })
replset:PRIMARY> db.test.update( { _id : /[A-Z]/, date : { $lte : date } }, { $set : { date : date } }, { multi : true, upsert : true } )
WriteResult({
	"nMatched" : 0,
	"nUpserted" : 1,
	"nModified" : 0,
	"_id" : ObjectId("547c643cb6f12be4a6160b28")
})
replset:PRIMARY> db.test.find()
{ "_id" : "A", "date" : ISODate("2014-12-01T12:51:02.599Z") }
{ "_id" : ObjectId("547c643cb6f12be4a6160b28"), "date" : ISODate("2014-12-01T12:50:55.826Z") }
replset:PRIMARY> use local
switched to db local
replset:PRIMARY> db.oplog.rs.find()
{ "ts" : Timestamp(1417438236, 1), "h" : NumberLong(0), "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "initiating set" } }
{ "ts" : Timestamp(1417438262, 1), "h" : NumberLong("-7186997792642957295"), "v" : 2, "op" : "i", "ns" : "test.test", "o" : { "_id" : "A", "date" : ISODate("2014-12-01T12:51:02.599Z") } }
{ "ts" : Timestamp(1417438268, 1), "h" : NumberLong("-857225590531386380"), "v" : 2, "op" : "i", "ns" : "test.test", "o" : { "_id" : ObjectId("547c643cb6f12be4a6160b28"), "date" : ISODate("2014-12-01T12:50:55.826Z") } }
replset:PRIMARY>

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