Reconnection Loop when using globalsign

[qhenkart]

I do not think this is a duplicate of #101 ,

we are running mongodb v3.4.10, and connections to the database seem to be completely unstable using the globalsign driver.

I created an ultra simple go app to showcase the issue:

func main() {
	fmt.Println("Starting test")
	session, err := mgo.Dial("mongodb://localhost:27017")
	if err != nil {
		panic(err)
	}

	defer session.Close()

	fmt.Println("running")
	wait()
}

func wait() os.Signal {
	ch := make(chan os.Signal)
	signal.Notify(ch, syscall.SIGINT, syscall.SIGTERM)

	return <-ch
}

when using the labix/mgo driver, there is no issue holding a connection, however when using globalsign/mgo, the connection lasts for about 10 seconds before closing and restarting. The mongod output looks like this

2018-02-12T13:48:03.014-0600 I NETWORK  [thread1] connection accepted from 127.0.0.1:54685 #1 (1 connection now open)
2018-02-12T13:48:03.019-0600 I NETWORK  [conn1] received client metadata from 127.0.0.1:54685 conn1: { driver: { name: "mgo", version: "globalsign" }, os: { architecture: "amd64", type: "darwin" } }
2018-02-12T13:48:34.530-0600 I -        [conn1] end connection 127.0.0.1:54685 (1 connection now open)
2018-02-12T13:48:35.535-0600 I NETWORK  [thread1] connection accepted from 127.0.0.1:54690 #2 (1 connection now open)
2018-02-12T13:48:35.536-0600 I NETWORK  [conn2] received client metadata from 127.0.0.1:54690 conn2: { driver: { name: "mgo", version: "globalsign" }, os: { architecture: "amd64", type: "darwin" } }
2018-02-12T13:49:07.051-0600 I -        [conn2] end connection 127.0.0.1:54690 (1 connection now open)

and will continue that loop ad infinitum. This is occurring on our production environment and creating a number of problems for us. Am I doing something wrong in the way I am initializing the connection?

[jyoon17]

Actually it is a duplicate of #101. According to your mongodb log, connections are reset every 30 seconds.

mgo/cluster.go

Line 344 in 896bbb8

const syncServersDelay = 30 * time.Second

mgo/cluster.go

Line 409 in 896bbb8

case <-time.After(syncServersDelay):

The drive tries to sync server info by calling isMaster every 30 seconds and it will reset all the connections if it fails. Due to a bug in globalsign/mgo, the second attempt to sync will fail and that's why your connection is closed.

[domodwyer]

Hi all,

@jyoon17 is right, the 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