Details
Description
Retryable writes was added in v3.6, and the way the server remembers a write is written is by tagging the oplog entry for the write. During migration, the server will also need to transfer the oplog entries related to retryable write to the destination shard. It also has to make sure that the oplog entries it sends doesn't get rolled back. The current code is extra paranoid and can trigger the assert even though the oplog entries are majority committed.
Â
Original Description: One collection will not migrate chunks due to change of term, but reports stale term
I have a 3.6.5 cluster with four (three-member) shards, three config servers, and 13 routers.
Aside from the config database, my cluster contains two other databases. Each of those databases has identical collection counts and names. In each database, we've sharded the same two collections in the same way across databases. In one database, the balancer has successfully balanced both collections. In the other database, the balancer has only balanced one collection.
The other collection fails to balance with the error message "commit clone failed :: caused by :: Location40650: detected change of term from 228 to 229". Oddly enough, the shard from which the chunk is being moved is on election term 231. This error message is new to Mongo 3.6.x:Â
I stopped every single component of the cluster (mongos/shardserver/configserver) and then started them back up hoping that the problem would resolve itself. I didn't see any improvement. I also checked for replica set lag and didn't see any.
Please let me know what information I can provide to make diagnosis easier.
Â
mongos> sh.status()--- Sharding Status ---sharding version: {"_id" : 1,"minCompatibleVersion" : 5,"currentVersion" : 6,"clusterId" : ObjectId("5b11d3f969791a2b6a246ef9")}shards:{ "_id" : "rs0", "host" : "rs0/mongos0r1:27017,mongos0r2:27017,mongos0r3:27017", "state" : 1 }{ "_id" : "rs1", "host" : "rs1/mongos1r1:27018,mongos1r2:27018,mongos1r3:27018", "state" : 1 }{ "_id" : "rs2", "host" : "rs2/mongos2r1:27018,mongos2r2:27018,mongos2r3:27018", "state" : 1 }{ "_id" : "rs3", "host" : "rs3/mongos3r1:27018,mongos3r2:27018,mongos3r3:27018", "state" : 1 }active mongoses:"3.6.5" : 13autosplit:Currently enabled: yesbalancer:Currently enabled: yesCurrently running: noBalancer active window is set between 03:30 and 01:00 server local timeFailed balancer rounds in last 5 attempts: 0Migration Results for the last 24 hours:2747 : Success926 : Failed with error 'aborted', from rs0 to rs1932 : Failed with error 'aborted', from rs0 to rs3917 : Failed with error 'aborted', from rs0 to rs2databases:{ "_id" : "mydb", "primary" : "rs0", "partitioned" : true }mydb.mycollshard key: {"field1" : 1,"field2" : 1}unique: truebalancing: truechunks:rs0 96708too many chunks to print, use verbose if you want to force printmydb.fs.chunksshard key: { "files_id" : 1, "n" : 1 }unique: truebalancing: truechunks:rs0 21116rs1 1711rs2 1711rs3 1712too many chunks to print, use verbose if you want to force print{ "_id" : "otherdb", "primary" : "rs0", "partitioned" : true }otherdb.mycollshard key: {"field1" : 1,"field2" : 1}unique: truebalancing: truechunks:rs0 8697rs1 8697rs2 8697rs3 8697too many chunks to print, use verbose if you want to force printotherdb.fs.chunksshard key: { "files_id" : 1, "n" : 1 }unique: truebalancing: truechunks:rs0 2376rs1 2375rs2 2376rs3 2376too many chunks to print, use verbose if you want to force print{ "_id" : "config", "primary" : "config", "partitioned" : true }config.system.sessionsshard key: { "_id" : 1 }unique: falsebalancing: truechunks:rs0 1{ "_id" : { "$minKey" : 1 } } -->> { "_id" : { "$maxKey" : 1 } } on : rs0 Timestamp(1, 0){ "_id" : "nagios", "primary" : "rs0", "partitioned" : false }{ "_id" : "test", "primary" : "rs1", "partitioned" : false }
mongos>sh.moveChunk("mydb.mycoll", {"field1":1, "field2":1}, "rs1"){"ok" : 0,"errmsg" : "commit clone failed :: caused by :: Location40650: detected change of term from 228 to 229","code" : 125,"codeName" : "CommandFailed","$clusterTime" : {"clusterTime" : Timestamp(1529346339, 7898),"signature" : {"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),"keyId" : NumberLong(0)}},"operationTime" : Timestamp(1529346339, 7898)}mongos>
rs0:PRIMARY> rs.status(){"set" : "rs0","date" : ISODate("2018-06-18T18:29:55.149Z"),"myState" : 1,"term" : NumberLong(231),"heartbeatIntervalMillis" : NumberLong(2000),"optimes" : {"lastCommittedOpTime" : {"ts" : Timestamp(1529346594, 10),"t" : NumberLong(231)},"readConcernMajorityOpTime" : {"ts" : Timestamp(1529346594, 10),"t" : NumberLong(231)},"appliedOpTime" : {"ts" : Timestamp(1529346594, 10),"t" : NumberLong(231)},"durableOpTime" : {"ts" : Timestamp(1529346594, 10),"t" : NumberLong(231)}},"members" : [{"_id" : 3,"name" : "mongos0r1:27017","health" : 1,"state" : 1,"stateStr" : "PRIMARY","uptime" : 1999,"optime" : {"ts" : Timestamp(1529346594, 10),"t" : NumberLong(231)},"optimeDate" : ISODate("2018-06-18T18:29:54Z"),"electionTime" : Timestamp(1529346325, 2),"electionDate" : ISODate("2018-06-18T18:25:25Z"),"configVersion" : 205694,"self" : true},{"_id" : 4,"name" : "mongos0r2:27017","health" : 1,"state" : 2,"stateStr" : "SECONDARY","uptime" : 1964,"optime" : {"ts" : Timestamp(1529346593, 5),"t" : NumberLong(231)},"optimeDurable" : {"ts" : Timestamp(1529346593, 5),"t" : NumberLong(231)},"optimeDate" : ISODate("2018-06-18T18:29:53Z"),"optimeDurableDate" : ISODate("2018-06-18T18:29:53Z"),"lastHeartbeat" : ISODate("2018-06-18T18:29:53.503Z"),"lastHeartbeatRecv" : ISODate("2018-06-18T18:29:54.441Z"),"pingMs" : NumberLong(0),"syncingTo" : "mongos0r3:27017","configVersion" : 205694},{"_id" : 5,"name" : "mongos0r3:27017","health" : 1,"state" : 2,"stateStr" : "SECONDARY","uptime" : 1980,"optime" : {"ts" : Timestamp(1529346593, 5),"t" : NumberLong(231)},"optimeDurable" : {"ts" : Timestamp(1529346593, 5),"t" : NumberLong(231)},"optimeDate" : ISODate("2018-06-18T18:29:53Z"),"optimeDurableDate" : ISODate("2018-06-18T18:29:53Z"),"lastHeartbeat" : ISODate("2018-06-18T18:29:53.508Z"),"lastHeartbeatRecv" : ISODate("2018-06-18T18:29:53.971Z"),"pingMs" : NumberLong(0),"syncingTo" : "mongos0r1:27017","configVersion" : 205694}],"ok" : 1,"operationTime" : Timestamp(1529346594, 10),"$gleStats" : {"lastOpTime" : Timestamp(0, 0),"electionId" : ObjectId("7fffffff00000000000000e7")},"$clusterTime" : {"clusterTime" : Timestamp(1529346594, 19),"signature" : {"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),"keyId" : NumberLong(0)}},"$configServerState" : {"opTime" : {"ts" : Timestamp(1529346594, 16),"t" : NumberLong(5)}}}rs0:PRIMARY>