Major - P3 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" : 13 autosplit: Currently enabled: yes balancer: Currently enabled: yes Currently running: no Balancer active window is set between 03:30 and 01:00 server local time Failed balancer rounds in last 5 attempts: 0 Migration Results for the last 24 hours: 2747 : Success 926 : Failed with error 'aborted', from rs0 to rs1 932 : Failed with error 'aborted', from rs0 to rs3 917 : Failed with error 'aborted', from rs0 to rs2 databases: { "_id" : "mydb", "primary" : "rs0", "partitioned" : true } mydb.mycoll shard key: { "field1" : 1, "field2" : 1 } unique: true balancing: true chunks: rs0 96708 too many chunks to print, use verbose if you want to force print mydb.fs.chunks shard key: { "files_id" : 1, "n" : 1 } unique: true balancing: true chunks: rs0 21116 rs1 1711 rs2 1711 rs3 1712 too many chunks to print, use verbose if you want to force print { "_id" : "otherdb", "primary" : "rs0", "partitioned" : true } otherdb.mycoll shard key: { "field1" : 1, "field2" : 1 } unique: true balancing: true chunks: rs0 8697 rs1 8697 rs2 8697 rs3 8697 too many chunks to print, use verbose if you want to force print otherdb.fs.chunks shard key: { "files_id" : 1, "n" : 1 } unique: true balancing: true chunks: rs0 2376 rs1 2375 rs2 2376 rs3 2376 too many chunks to print, use verbose if you want to force print { "_id" : "config", "primary" : "config", "partitioned" : true } config.system.sessions shard key: { "_id" : 1 } unique: false balancing: true chunks: 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>