session migration is too sensitive to replica set primary elections

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: 

https://github.com/mongodb/mongo/blob/570c2570a728a646a953cee6abedeaa3517f8215/src/mongo/db/s/migration_chunk_cloner_source_legacy.cpp#L772

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>