Connection to the mongo server is periodically reconnected

[changwoo-nam]

description

The isMaster request fails in syncServersIteration(), which is repeatedly executed, and disconnects from the existing mongodb server and repeats the connection again.

This causes user requests to mongodb to be periodically delayed.

It seems to occur when an isMaster request is made through a pooled mongodb connection.

• mgo debug log

2018/02/07 19:12:33 Cluster 0xc4202cc900 acquired (refs=3)
2018/02/07 19:12:33 New session 0xc4203ed380 on cluster 0xc4202cc900
2018/02/07 19:12:33 Session 0xc4203ed380: setting mode 1 with refresh=true (master=0x0, slave=0x0)
2018/02/07 19:12:33 Socket 0xc420660000 to 10.101.216.180:27017: serializing op: &mgo.queryOp{query:bson.D{bson.DocElem{Name:"isMaster", Value:1}, bson.DocElem{Name:"client", Value:bson.M{"driver":bson.M{"name":"mgo", "version":"globalsign"}, "os":bson.M{"type":"linux", "architecture":"amd64"}}}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x869280), mode:1, skip:0, limit:-1, options:mgo.queryWrapper{Query:interface {}(nil), OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D(nil), MaxScan:0, MaxTimeMS:0, Comment:"", Collation:(*mgo.Collation)(nil)}, hasOptions:false, flags:0x4, readConcern:""}
2018/02/07 19:12:33 final query is &mgo.queryWrapper{Query:bson.D{bson.DocElem{Name:"isMaster", Value:1}, bson.DocElem{Name:"client", Value:bson.M{"driver":bson.M{"name":"mgo", "version":"globalsign"}, "os":bson.M{"architecture":"amd64", "type":"linux"}}}}, OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D{bson.DocElem{Name:"mode", Value:"secondaryPreferred"}}, MaxScan:0, MaxTimeMS:0, Comment:"", Collation:(*mgo.Collation)(nil)}
2018/02/07 19:12:33 Socket 0xc420660000 to 10.101.216.180:27017: sending 1 op(s) (235 bytes)
2018/02/07 19:12:33 Socket 0xc420660000 to 10.101.216.180:27017: updated write deadline to 5s ahead (2018-02-07 19:12:38.348446658 +0900 KST)
2018/02/07 19:12:33 Socket 0xc420660000 to 10.101.216.180:27017: updated read deadline to 5s ahead (2018-02-07 19:12:38.348473501 +0900 KST)
2018/02/07 19:12:33 Socket 0xc420660000 to 10.101.216.180:27017: got reply (187 bytes)
2018/02/07 19:12:33 Socket 0xc420660000 to 10.101.216.180:27017: received document: bson.M{"ok":0, "errmsg":"The client metadata document may only be sent in the first isMaster", "code":186, "codeName":"ClientMetadataCannotBeMutated"}
2018/02/07 19:12:33 Run command unmarshaled: mgo.queryOp{query:bson.D{bson.DocElem{Name:"isMaster", Value:1}, bson.DocElem{Name:"client", Value:bson.M{"driver":bson.M{"name":"mgo", "version":"globalsign"}, "os":bson.M{"type":"linux", "architecture":"amd64"}}}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x869280), mode:1, skip:0, limit:-1, options:mgo.queryWrapper{Query:bson.D{bson.DocElem{Name:"isMaster", Value:1}, bson.DocElem{Name:"client", Value:bson.M{"driver":bson.M{"name":"mgo", "version":"globalsign"}, "os":bson.M{"type":"linux", "architecture":"amd64"}}}}, OrderBy:interface {}(nil), Hint:interface {}(nil), Explain:false, Snapshot:false, ReadPreference:bson.D{bson.DocElem{Name:"mode", Value:"secondaryPreferred"}}, MaxScan:0, MaxTimeMS:0, Comment:"", Collation:(*mgo.Collation)(nil)}, hasOptions:true, flags:0x4, readConcern:""}, result: bson.M{"ok":0, "errmsg":"The client metadata document may only be sent in the first isMaster", "code":186, "codeName":"ClientMetadataCannotBeMutated"}
2018/02/07 19:12:33 Closing session 0xc4203ed380
2018/02/07 19:12:33 unset master socket from session 0xc4203ed380
2018/02/07 19:12:33 Cluster 0xc4202cc900 released (refs=2)
2018/02/07 19:12:33 SYNC Command 'ismaster' to 10.101.216.180:27017 failed: The client metadata document may only be sent in the first isMaster
2018/02/07 19:12:33 Connections to 10.101.216.180:27017 closing (1 live sockets).
2018/02/07 19:12:33 Socket 0xc420660000 to 10.101.216.180:27017: closing: Closed explicitly (abend=false)
2018/02/07 19:12:33 Socket 0xc420660000 to 10.101.216.180:27017: idle and close.
2018/02/07 19:12:33 Removed server 10.101.216.180:27017 from cluster.

• related mongodb changes

  • Only the first isMaster can contain client meta. Otherwise, a ClientMetadataCannotBeMutated error is returned.
  • mongodb/mongo@ad27c92?diff=split#diff-21452f235de2f3567768f3bddc2c2a54

• Affected mongo versions

  • mongodb: 3.4 or later
  • wireVersion : 5 or later

[domodwyer]

Hi @changwoo-nam

This is a great bug report - thanks for including all the info needed to diagnose and fix this. I'll have a look at this as soon as I can free up a bit of time.

Dom

[canthefason]

I've addressed this problem.

mgo/cluster.go

Line 160 in 896bbb8

err := session.Run(bson.D{{Name: "isMaster", Value: 1}, {Name: "client", Value: metaInfo}}, result)

for mongodb versions 3.4 or later, this returns The client metadata document may only be sent in the first isMaster error for the synchronization requests. So we need a control mechanism that sends the metadata only for the very first isMaster request.

To test this out, I removed that metadata completely and confirmed that the library works fine.

[domodwyer]

Hi all,

@jyoon17 is right, the periodic cluster sync causes the isMaster command to be sent again and the spec specifies:

isMaster commands issued after the initial connection handshake MUST NOT
contain handshake arguments

I've confirmed the issue locally and will push a fix in the next hour - sorry for the issue in the first place, our testing setup didn't catch this as it doesn't support the client metadata property.

Thanks everyone for the help identifying and debugging the issue, it's really appreciated!

Dom