Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

More sockets created than PoolLimit #322

Open
jameshartig opened this issue Jan 15, 2019 · 4 comments
Open

More sockets created than PoolLimit #322

jameshartig opened this issue Jan 15, 2019 · 4 comments
Labels
enhancement help wanted

Comments

@jameshartig
Copy link

jameshartig commented Jan 15, 2019 •
edited
Loading

Despite setting PoolLimit: 1, the mgo driver proceeds to make 2 connections to the primary.

What version of MongoDB are you using (mongod --version)?

4.0.5

What version of Go are you using (go version)?

1.11.1

What operating system and processor architecture are you using (go env)?

CentOS 7
linux/amd64

What did you do?

Setup a 3 member replica set with 1 primary, 1 secondary, 1 arbiter.

Run

package main

import (
	"fmt"
	"log"
	"os"
	"time"

	"github.com/globalsign/mgo"
)

func init() {
	mgo.SetStats(true)
}

func main() {
	info := mgo.DialInfo{}
	mgo.SetLogger(log.New(os.Stdout, "", 0))
	mgo.SetDebug(true)
	info.Timeout = 3 * time.Second
	info.ReadTimeout = time.Minute
	info.WriteTimeout = 15 * time.Second
	info.MaxIdleTimeMS = 5 * 60 * 1000
	info.PoolLimit = 1
	info.PoolTimeout = 3 * time.Second
	info.AppName = "mgotest"
	info.ReadPreference = &mgo.ReadPreference{Mode: mgo.PrimaryPreferred}
	info.Addrs = []string{"127.0.0.1:27017"}
	info.Safe = mgo.Safe{}
	s, err := mgo.DialWithInfo(&info)
	if err != nil {
		panic(err)
	}
	s.SetSyncTimeout(3 * time.Second)
	if err := s.Ping(); err != nil {
		panic(err)
	}
	for range time.NewTicker(time.Second).C {
		stats := mgo.GetStats()
		fmt.Printf("%+v\n", stats)
	}
}

Where 127.0.0.1:27017 is an address to a mongo node in the replica set.

It'll starting printing out:

{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
...

Until after 30 seconds it'll start printing out:

{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}

Now there's 3 sockets alive, 2 to the primary and 1 to the secondary.

Here are the debug logs from running that with the initial address being unity.node.gce-us-central1.admiral:27017:

Cluster 0xc0000b4000 acquired (refs=2)
New session 0xc000094680 on cluster 0xc0000b4000
Session 0xc000094680: setting mode 0 with refresh=true (master=0x0, slave=0x0)
Cluster 0xc0000b4000 released (refs=1)
Cluster has 0 known masters and 0 known slaves.
Waiting for servers to synchronize...
SYNC Cluster 0xc0000b4000 is starting a sync loop iteration.
SYNC Starting full topology synchronization...
SYNC Address unity.node.gce-us-central1.admiral:27017 resolved as 10.128.0.14:27017
SYNC Processing unity.node.gce-us-central1.admiral:27017...
Establishing new connection to unity.node.gce-us-central1.admiral:27017 (timeout=3s)...
Connection to unity.node.gce-us-central1.admiral:27017 established.
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: initialized
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: requesting a new nonce
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: serializing op: &mgo.queryOp{query:(*mgo.getNonceCmd)(0xc00016a020), collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x570f20), mode:0, 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:0x0, readConcern:""}
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: sending 1 op(s) (58 bytes)
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: updated write deadline to 2019-01-15 21:22:33.560374573 +0000 UTC m=+15.081951864
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: updated read deadline to 2019-01-15 21:23:18.560492105 +0000 UTC m=+60.082069398
Cluster 0xc0000b4000 acquired (refs=3)
New session 0xc0001ae000 on cluster 0xc0000b4000
Session 0xc0001ae000: setting mode 1 with refresh=true (master=0x0, slave=0x0)
Socket 0xc000198000 to unity.node.gce-us-central1.admiral: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{"architecture":"amd64", "type":"linux"}, "application":bson.M{"name":"mgotest"}}}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x5730f0), 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:""}
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: sending 1 op(s) (207 bytes)
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: updated write deadline to 2019-01-15 21:22:33.56068197 +0000 UTC m=+15.082259247
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: got reply (206 bytes)
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: received document: bson.M{"nonce":"3b74daa2105b78f3", "ok":1, "operationTime":6646837000118730896, "$clusterTime":bson.M{"clusterTime":6646837000118730896, "signature":bson.M{"keyId":0, "hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}}}}
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: nonce unmarshalled: &mgo.getNonceResult{Nonce:"3b74daa2105b78f3", Err:"", Code:0}
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: updated read deadline to 2019-01-15 21:23:18.597675722 +0000 UTC m=+60.119253011
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: got reply (855 bytes)
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: received document: bson.M{"me":"unity.node.gce-us-central1.admiral:27017", "maxMessageSizeBytes":48000000, "localTime":time.Time{wall:0x22739480, ext:63683184138, loc:(*time.Location)(nil)}, "arbiters":[]interface {}{"effie.node.gce-us-central1.admiral:27017"}, "setName":"preagg", "secondary":false, "lastWrite":bson.M{"majorityOpTime":bson.M{"ts":6646837000118730896, "t":26}, "majorityWriteDate":time.Time{wall:0x0, ext:63683184137, loc:(*time.Location)(nil)}, "opTime":bson.M{"ts":6646837000118730896, "t":26}, "lastWriteDate":time.Time{wall:0x0, ext:63683184137, loc:(*time.Location)(nil)}}, "operationTime":6646837000118730896, "hosts":[]interface {}{"vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}, "setVersion":15478, "maxBsonObjectSize":16777216, "maxWriteBatchSize":100000, "readOnly":false, "ok":1, "$clusterTime":bson.M{"clusterTime":6646837000118730896, "signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}}, "ismaster":true, "primary":"unity.node.gce-us-central1.admiral:27017", "electionId":"\u007f\xff\xff\xff\x00\x00\x00\x00\x00\x00\x00\x1a", "logicalSessionTimeoutMinutes":30, "minWireVersion":0, "maxWireVersion":7}
Run command unmarshaled: mgo.queryOp{query:bson.D{bson.DocElem{Name:"isMaster", Value:1}, bson.DocElem{Name:"client", Value:bson.M{"os":bson.M{"type":"linux", "architecture":"amd64"}, "application":bson.M{"name":"mgotest"}, "driver":bson.M{"name":"mgo", "version":"globalsign"}}}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x5730f0), 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:""}, result: bson.M{"maxBsonObjectSize":16777216, "localTime":time.Time{wall:0x22739480, ext:63683184138, loc:(*time.Location)(nil)}, "maxWireVersion":7, "primary":"unity.node.gce-us-central1.admiral:27017", "me":"unity.node.gce-us-central1.admiral:27017", "lastWrite":bson.M{"majorityOpTime":bson.M{"ts":6646837000118730896, "t":26}, "majorityWriteDate":time.Time{wall:0x0, ext:63683184137, loc:(*time.Location)(nil)}, "opTime":bson.M{"ts":6646837000118730896, "t":26}, "lastWriteDate":time.Time{wall:0x0, ext:63683184137, loc:(*time.Location)(nil)}}, "ok":1, "secondary":false, "electionId":"\u007f\xff\xff\xff\x00\x00\x00\x00\x00\x00\x00\x1a", "maxWriteBatchSize":100000, "maxMessageSizeBytes":48000000, "logicalSessionTimeoutMinutes":30, "minWireVersion":0, "hosts":[]interface {}{"vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}, "setName":"preagg", "setVersion":15478, "operationTime":6646837000118730896, "$clusterTime":bson.M{"clusterTime":6646837000118730896, "signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}}, "arbiters":[]interface {}{"effie.node.gce-us-central1.admiral:27017"}, "ismaster":true, "readOnly":false}
Closing session 0xc0001ae000
unset slave socket from session 0xc0001ae000
Cluster 0xc0000b4000 released (refs=2)
SYNC Result of 'ismaster' from unity.node.gce-us-central1.admiral:27017: mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"unity.node.gce-us-central1.admiral:27017", Hosts:[]string{"vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}, Passives:[]string(nil), Tags:bson.D(nil), Msg:"", SetName:"preagg", MaxWireVersion:7}
SYNC unity.node.gce-us-central1.admiral:27017 is a master.
SYNC unity.node.gce-us-central1.admiral:27017 knows about the following peers: []string{"unity.node.gce-us-central1.admiral:27017", "vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}
SYNC Adding unity.node.gce-us-central1.admiral:27017 to cluster as a master.
SYNC Broadcasting availability of server unity.node.gce-us-central1.admiral:27017
Cluster has 1 known masters and 0 known slaves.
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: serializing op: &mgo.queryOp{query:bson.D{bson.DocElem{Name:"ping", Value:1}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x5730f0), mode:0, 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:""}
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: sending 1 op(s) (54 bytes)
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: updated write deadline to 2019-01-15 21:22:33.598401598 +0000 UTC m=+15.119978866
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: updated read deadline to 2019-01-15 21:23:18.598454509 +0000 UTC m=+60.120031869
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: got reply (178 bytes)
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: received document: bson.M{"ok":1, "operationTime":6646837000118730896, "$clusterTime":bson.M{"clusterTime":6646837000118730896, "signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}}}
Session 0xc000094680: setting mode 3 with refresh=true (master=0x0, slave=0x0)
Cluster has 1 known masters and 0 known slaves.
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: serializing op: &mgo.queryOp{query:bson.D{bson.DocElem{Name:"ping", Value:1}}, collection:"admin.$cmd", serverTags:[]bson.D{}, selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x5730f0), mode:3, 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:""}
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: sending 1 op(s) (54 bytes)
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: updated write deadline to 2019-01-15 21:22:33.634877836 +0000 UTC m=+15.156455106
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: updated read deadline to 2019-01-15 21:23:18.63492216 +0000 UTC m=+60.156499430
SYNC Address vega.node.gce-us-central1.admiral:27017 resolved as 10.128.0.9:27017
SYNC Processing vega.node.gce-us-central1.admiral:27017...
Establishing new connection to vega.node.gce-us-central1.admiral:27017 (timeout=3s)...
SYNC Address unity.node.gce-us-central1.admiral:27017 resolved as 10.128.0.14:27017
SYNC Address unity.node.gce-us-central1.admiral:27017 resolved as 10.128.0.14:27017
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: got reply (178 bytes)
Socket 0xc000198000 to unity.node.gce-us-central1.admiral:27017: received document: bson.M{"ok":1, "operationTime":6646837000118730896, "$clusterTime":bson.M{"clusterTime":6646837000118730896, "signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}}}
Connection to vega.node.gce-us-central1.admiral:27017 established.
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: initialized
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: requesting a new nonce
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: serializing op: &mgo.queryOp{query:(*mgo.getNonceCmd)(0xc000174008), collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x570f20), mode:0, 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:0x0, readConcern:""}
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: sending 1 op(s) (58 bytes)
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: updated write deadline to 2019-01-15 21:22:33.675456165 +0000 UTC m=+15.197033434
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: updated read deadline to 2019-01-15 21:23:18.675505322 +0000 UTC m=+60.197082591
Cluster 0xc0000b4000 acquired (refs=3)
New session 0xc000240000 on cluster 0xc0000b4000
Session 0xc000240000: setting mode 1 with refresh=true (master=0x0, slave=0x0)
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral: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"}, "application":bson.M{"name":"mgotest"}}}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x5730f0), 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:""}
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: sending 1 op(s) (207 bytes)
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: updated write deadline to 2019-01-15 21:22:33.675632286 +0000 UTC m=+15.197209556
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: got reply (206 bytes)
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: received document: bson.M{"nonce":"d92920bdfaf07ff6", "ok":1, "operationTime":6646837000118730896, "$clusterTime":bson.M{"clusterTime":6646837000118730896, "signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}}}
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: nonce unmarshalled: &mgo.getNonceResult{Nonce:"d92920bdfaf07ff6", Err:"", Code:0}
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: updated read deadline to 2019-01-15 21:23:18.71275684 +0000 UTC m=+60.234334110
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: got reply (830 bytes)
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: received document: bson.M{"maxWriteBatchSize":100000, "localTime":time.Time{wall:0x295d9980, ext:63683184138, loc:(*time.Location)(nil)}, "maxWireVersion":7, "operationTime":6646837000118730896, "setVersion":15478, "lastWrite":bson.M{"opTime":bson.M{"ts":6646837000118730896, "t":26}, "lastWriteDate":time.Time{wall:0x0, ext:63683184137, loc:(*time.Location)(nil)}, "majorityOpTime":bson.M{"ts":6646837000118730896, "t":26}, "majorityWriteDate":time.Time{wall:0x0, ext:63683184137, loc:(*time.Location)(nil)}}, "maxBsonObjectSize":16777216, "ok":1, "setName":"preagg", "secondary":true, "logicalSessionTimeoutMinutes":30, "arbiters":[]interface {}{"effie.node.gce-us-central1.admiral:27017"}, "me":"vega.node.gce-us-central1.admiral:27017", "maxMessageSizeBytes":48000000, "minWireVersion":0, "readOnly":false, "$clusterTime":bson.M{"clusterTime":6646837000118730896, "signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}}, "hosts":[]interface {}{"vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}, "ismaster":false, "primary":"unity.node.gce-us-central1.admiral:27017"}
Run command unmarshaled: mgo.queryOp{query:bson.D{bson.DocElem{Name:"isMaster", Value:1}, bson.DocElem{Name:"client", Value:bson.M{"os":bson.M{"type":"linux", "architecture":"amd64"}, "application":bson.M{"name":"mgotest"}, "driver":bson.M{"name":"mgo", "version":"globalsign"}}}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x5730f0), 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:""}, result: bson.M{"ismaster":false, "readOnly":false, "hosts":[]interface {}{"vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}, "primary":"unity.node.gce-us-central1.admiral:27017", "me":"vega.node.gce-us-central1.admiral:27017", "maxBsonObjectSize":16777216, "maxMessageSizeBytes":48000000, "maxWriteBatchSize":100000, "maxWireVersion":7, "$clusterTime":bson.M{"clusterTime":6646837000118730896, "signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}}, "arbiters":[]interface {}{"effie.node.gce-us-central1.admiral:27017"}, "secondary":true, "localTime":time.Time{wall:0x295d9980, ext:63683184138, loc:(*time.Location)(nil)}, "minWireVersion":0, "ok":1, "setName":"preagg", "setVersion":15478, "lastWrite":bson.M{"majorityOpTime":bson.M{"ts":6646837000118730896, "t":26}, "majorityWriteDate":time.Time{wall:0x0, ext:63683184137, loc:(*time.Location)(nil)}, "opTime":bson.M{"ts":6646837000118730896, "t":26}, "lastWriteDate":time.Time{wall:0x0, ext:63683184137, loc:(*time.Location)(nil)}}, "logicalSessionTimeoutMinutes":30, "operationTime":6646837000118730896}
Closing session 0xc000240000
unset slave socket from session 0xc000240000
Cluster 0xc0000b4000 released (refs=2)
SYNC Result of 'ismaster' from vega.node.gce-us-central1.admiral:27017: mgo.isMasterResult{IsMaster:false, Secondary:true, Primary:"unity.node.gce-us-central1.admiral:27017", Hosts:[]string{"vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}, Passives:[]string(nil), Tags:bson.D(nil), Msg:"", SetName:"preagg", MaxWireVersion:7}
SYNC vega.node.gce-us-central1.admiral:27017 is a slave.
SYNC vega.node.gce-us-central1.admiral:27017 knows about the following peers: []string{"unity.node.gce-us-central1.admiral:27017", "vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}
SYNC Adding vega.node.gce-us-central1.admiral:27017 to cluster as a slave.
SYNC Broadcasting availability of server vega.node.gce-us-central1.admiral:27017
SYNC Address unity.node.gce-us-central1.admiral:27017 resolved as 10.128.0.14:27017
SYNC Address unity.node.gce-us-central1.admiral:27017 resolved as 10.128.0.14:27017
SYNC Address vega.node.gce-us-central1.admiral:27017 resolved as 10.128.0.9:27017
SYNC Synchronization was complete (got data from primary).
SYNC Synchronization completed: 1 master(s) and 1 slave(s) alive.
SYNC New dynamic seeds: []string{"unity.node.gce-us-central1.admiral:27017", "vega.node.gce-us-central1.admiral:27017"}
Cluster 0xc0000b4000 released (refs=1)
SYNC Cluster 0xc0000b4000 waiting for next requested or scheduled sync.
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:6 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: serializing op: &mgo.queryOp{query:bson.D{bson.DocElem{Name:"ping", Value:1}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x5730f0), mode:0, 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:""}
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: sending 1 op(s) (54 bytes)
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: updated write deadline to 2019-01-15 21:22:48.637659999 +0000 UTC m=+30.159237270
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: updated read deadline to 2019-01-15 21:23:33.637751389 +0000 UTC m=+75.159328664
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:6 ReceivedDocs:6 SocketsAlive:2 SocketsInUse:2 SocketRefs:2 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: got reply (178 bytes)
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: received document: bson.M{"ok":1, "operationTime":6646837017298600081, "$clusterTime":bson.M{"clusterTime":6646837017298600081, "signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}}}
Ping for vega.node.gce-us-central1.admiral:27017 is 38 ms
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:1 SlaveConns:1 SentOps:7 ReceivedOps:7 ReceivedDocs:7 SocketsAlive:2 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: serializing op: &mgo.queryOp{query:bson.D{bson.DocElem{Name:"ping", Value:1}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x5730f0), mode:0, 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:""}
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: sending 1 op(s) (54 bytes)
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: updated write deadline to 2019-01-15 21:23:03.676271132 +0000 UTC m=+45.197848401
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: updated read deadline to 2019-01-15 21:23:48.676362186 +0000 UTC m=+90.197939473
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: got reply (178 bytes)
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: received document: bson.M{"ok":1, "operationTime":6646837124672782481, "$clusterTime":bson.M{"clusterTime":6646837124672782481, "signature":bson.M{"keyId":0, "hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}}}}
Ping for vega.node.gce-us-central1.admiral:27017 is 38 ms
SYNC Cluster 0xc0000b4000 is starting a sync loop iteration.
SYNC Starting full topology synchronization...
SYNC Address vega.node.gce-us-central1.admiral:27017 resolved as 10.128.0.9:27017
SYNC Processing vega.node.gce-us-central1.admiral:27017...
Cluster 0xc0000b4000 acquired (refs=3)
New session 0xc000094820 on cluster 0xc0000b4000
Session 0xc000094820: setting mode 1 with refresh=true (master=0x0, slave=0x0)
SYNC Address unity.node.gce-us-central1.admiral:27017 resolved as 10.128.0.14:27017
SYNC Processing unity.node.gce-us-central1.admiral:27017...
Establishing new connection to unity.node.gce-us-central1.admiral:27017 (timeout=3s)...
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: serializing op: &mgo.queryOp{query:bson.D{bson.DocElem{Name:"isMaster", Value:1}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x5730f0), 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:""}
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: sending 1 op(s) (58 bytes)
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: updated write deadline to 2019-01-15 21:23:04.440843007 +0000 UTC m=+45.962420296
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: updated read deadline to 2019-01-15 21:23:49.440898184 +0000 UTC m=+90.962475454
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: got reply (830 bytes)
Socket 0xc00022c000 to vega.node.gce-us-central1.admiral:27017: received document: bson.M{"hosts":[]interface {}{"vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}, "setName":"preagg", "maxWriteBatchSize":100000, "logicalSessionTimeoutMinutes":30, "$clusterTime":bson.M{"clusterTime":6646837124672782481, "signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}}, "setVersion":15478, "ismaster":false, "maxBsonObjectSize":16777216, "secondary":true, "primary":"unity.node.gce-us-central1.admiral:27017", "lastWrite":bson.M{"majorityWriteDate":time.Time{wall:0x0, ext:63683184166, loc:(*time.Location)(nil)}, "opTime":bson.M{"ts":6646837124672782481, "t":26}, "lastWriteDate":time.Time{wall:0x0, ext:63683184166, loc:(*time.Location)(nil)}, "majorityOpTime":bson.M{"ts":6646837124672782481, "t":26}}, "maxMessageSizeBytes":48000000, "minWireVersion":0, "ok":1, "operationTime":6646837124672782481, "arbiters":[]interface {}{"effie.node.gce-us-central1.admiral:27017"}, "me":"vega.node.gce-us-central1.admiral:27017", "localTime":time.Time{wall:0x1b4c8680, ext:63683184169, loc:(*time.Location)(nil)}, "maxWireVersion":7, "readOnly":false}
Run command unmarshaled: mgo.queryOp{query:bson.D{bson.DocElem{Name:"isMaster", Value:1}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x5730f0), 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:""}, result: bson.M{"readOnly":false, "ok":1, "hosts":[]interface {}{"vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}, "setVersion":15478, "maxWriteBatchSize":100000, "lastWrite":bson.M{"opTime":bson.M{"ts":6646837124672782481, "t":26}, "lastWriteDate":time.Time{wall:0x0, ext:63683184166, loc:(*time.Location)(nil)}, "majorityOpTime":bson.M{"ts":6646837124672782481, "t":26}, "majorityWriteDate":time.Time{wall:0x0, ext:63683184166, loc:(*time.Location)(nil)}}, "logicalSessionTimeoutMinutes":30, "$clusterTime":bson.M{"clusterTime":6646837124672782481, "signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}}, "minWireVersion":0, "secondary":true, "me":"vega.node.gce-us-central1.admiral:27017", "maxBsonObjectSize":16777216, "primary":"unity.node.gce-us-central1.admiral:27017", "maxMessageSizeBytes":48000000, "localTime":time.Time{wall:0x1b4c8680, ext:63683184169, loc:(*time.Location)(nil)}, "maxWireVersion":7, "operationTime":6646837124672782481, "arbiters":[]interface {}{"effie.node.gce-us-central1.admiral:27017"}, "setName":"preagg", "ismaster":false}
Closing session 0xc000094820
unset slave socket from session 0xc000094820
Cluster 0xc0000b4000 released (refs=2)
SYNC Result of 'ismaster' from vega.node.gce-us-central1.admiral:27017: mgo.isMasterResult{IsMaster:false, Secondary:true, Primary:"unity.node.gce-us-central1.admiral:27017", Hosts:[]string{"vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}, Passives:[]string(nil), Tags:bson.D(nil), Msg:"", SetName:"preagg", MaxWireVersion:7}
SYNC vega.node.gce-us-central1.admiral:27017 is a slave.
SYNC vega.node.gce-us-central1.admiral:27017 knows about the following peers: []string{"unity.node.gce-us-central1.admiral:27017", "vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}
Connection to unity.node.gce-us-central1.admiral:27017 established.
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: initialized
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: requesting a new nonce
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: serializing op: &mgo.queryOp{query:(*mgo.getNonceCmd)(0xc000012b48), collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x570f20), mode:0, 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:0x0, readConcern:""}
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: sending 1 op(s) (58 bytes)
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: updated write deadline to 2019-01-15 21:23:04.478734685 +0000 UTC m=+46.000311954
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: updated read deadline to 2019-01-15 21:23:49.478789058 +0000 UTC m=+91.000366327
Cluster 0xc0000b4000 acquired (refs=3)
New session 0xc0000949c0 on cluster 0xc0000b4000
Session 0xc0000949c0: setting mode 1 with refresh=true (master=0x0, slave=0x0)
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: serializing op: &mgo.queryOp{query:bson.D{bson.DocElem{Name:"isMaster", Value:1}, bson.DocElem{Name:"client", Value:bson.M{"os":bson.M{"type":"linux", "architecture":"amd64"}, "application":bson.M{"name":"mgotest"}, "driver":bson.M{"name":"mgo", "version":"globalsign"}}}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x5730f0), 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:""}
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: sending 1 op(s) (207 bytes)
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: updated write deadline to 2019-01-15 21:23:04.47891446 +0000 UTC m=+46.000491728
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: got reply (206 bytes)
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: received document: bson.M{"nonce":"c8eda1b0ca1f379d", "ok":1, "operationTime":6646837124672782481, "$clusterTime":bson.M{"clusterTime":6646837124672782481, "signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}}}
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: nonce unmarshalled: &mgo.getNonceResult{Nonce:"c8eda1b0ca1f379d", Err:"", Code:0}
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: updated read deadline to 2019-01-15 21:23:49.516143244 +0000 UTC m=+91.037720532
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: got reply (855 bytes)
Socket 0xc000010900 to unity.node.gce-us-central1.admiral:27017: received document: bson.M{"arbiters":[]interface {}{"effie.node.gce-us-central1.admiral:27017"}, "ismaster":true, "me":"unity.node.gce-us-central1.admiral:27017", "electionId":"\u007f\xff\xff\xff\x00\x00\x00\x00\x00\x00\x00\x1a", "maxMessageSizeBytes":48000000, "hosts":[]interface {}{"vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}, "setVersion":15478, "primary":"unity.node.gce-us-central1.admiral:27017", "maxWriteBatchSize":100000, "readOnly":false, "ok":1, "operationTime":6646837124672782481, "lastWrite":bson.M{"majorityWriteDate":time.Time{wall:0x0, ext:63683184166, loc:(*time.Location)(nil)}, "opTime":bson.M{"ts":6646837124672782481, "t":26}, "lastWriteDate":time.Time{wall:0x0, ext:63683184166, loc:(*time.Location)(nil)}, "majorityOpTime":bson.M{"ts":6646837124672782481, "t":26}}, "maxBsonObjectSize":16777216, "localTime":time.Time{wall:0x1d9f9e40, ext:63683184169, loc:(*time.Location)(nil)}, "setName":"preagg", "secondary":false, "logicalSessionTimeoutMinutes":30, "minWireVersion":0, "maxWireVersion":7, "$clusterTime":bson.M{"clusterTime":6646837124672782481, "signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}}}
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"}, "application":bson.M{"name":"mgotest"}}}}, collection:"admin.$cmd", serverTags:[]bson.D(nil), selector:interface {}(nil), replyFunc:(mgo.replyFunc)(0x5730f0), 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:""}, result: bson.M{"logicalSessionTimeoutMinutes":30, "ok":1, "arbiters":[]interface {}{"effie.node.gce-us-central1.admiral:27017"}, "secondary":false, "maxBsonObjectSize":16777216, "readOnly":false, "ismaster":true, "maxMessageSizeBytes":48000000, "maxWireVersion":7, "maxWriteBatchSize":100000, "operationTime":6646837124672782481, "$clusterTime":bson.M{"signature":bson.M{"hash":[]uint8{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, "keyId":0}, "clusterTime":6646837124672782481}, "hosts":[]interface {}{"vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}, "setName":"preagg", "lastWrite":bson.M{"lastWriteDate":time.Time{wall:0x0, ext:63683184166, loc:(*time.Location)(nil)}, "majorityOpTime":bson.M{"ts":6646837124672782481, "t":26}, "majorityWriteDate":time.Time{wall:0x0, ext:63683184166, loc:(*time.Location)(nil)}, "opTime":bson.M{"ts":6646837124672782481, "t":26}}, "electionId":"\u007f\xff\xff\xff\x00\x00\x00\x00\x00\x00\x00\x1a", "localTime":time.Time{wall:0x1d9f9e40, ext:63683184169, loc:(*time.Location)(nil)}, "minWireVersion":0, "setVersion":15478, "primary":"unity.node.gce-us-central1.admiral:27017", "me":"unity.node.gce-us-central1.admiral:27017"}
Closing session 0xc0000949c0
unset master socket from session 0xc0000949c0
Cluster 0xc0000b4000 released (refs=2)
SYNC Result of 'ismaster' from unity.node.gce-us-central1.admiral:27017: mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"unity.node.gce-us-central1.admiral:27017", Hosts:[]string{"vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}, Passives:[]string(nil), Tags:bson.D(nil), Msg:"", SetName:"preagg", MaxWireVersion:7}
SYNC unity.node.gce-us-central1.admiral:27017 is a master.
SYNC unity.node.gce-us-central1.admiral:27017 knows about the following peers: []string{"unity.node.gce-us-central1.admiral:27017", "vega.node.gce-us-central1.admiral:27017", "unity.node.gce-us-central1.admiral:27017"}
SYNC Broadcasting availability of server unity.node.gce-us-central1.admiral:27017
SYNC Address vega.node.gce-us-central1.admiral:27017 resolved as 10.128.0.9:27017
SYNC Broadcasting availability of server vega.node.gce-us-central1.admiral:27017
SYNC Address vega.node.gce-us-central1.admiral:27017 resolved as 10.128.0.9:27017
SYNC Address unity.node.gce-us-central1.admiral:27017 resolved as 10.128.0.14:27017
SYNC Address unity.node.gce-us-central1.admiral:27017 resolved as 10.128.0.14:27017
SYNC Address unity.node.gce-us-central1.admiral:27017 resolved as 10.128.0.14:27017
SYNC Address unity.node.gce-us-central1.admiral:27017 resolved as 10.128.0.14:27017
SYNC Synchronization was complete (got data from primary).
SYNC Synchronization completed: 1 master(s) and 1 slave(s) alive.
SYNC New dynamic seeds: []string{"unity.node.gce-us-central1.admiral:27017", "vega.node.gce-us-central1.admiral:27017"}
Cluster 0xc0000b4000 released (refs=1)
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
SYNC Cluster 0xc0000b4000 waiting for next requested or scheduled sync.
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}
{Clusters:1 MasterConns:2 SlaveConns:1 SentOps:11 ReceivedOps:11 ReceivedDocs:11 SocketsAlive:3 SocketsInUse:1 SocketRefs:1 TimesSocketAcquired:2 TimesWaitedForPool:0 TotalPoolWaitTime:0s PoolTimeouts:0}

Can you reproduce the issue on the latest development branch?

Yes, the same thing happens.
@jameshartig
Copy link
Author

After digging some more it looks like this might be intentional:

// Don't ever hit the pool limit for syncing
config := cluster.dialInfo.Copy()
config.PoolLimit = 0

This is unfortunate because it doubles the number of connections that we think we're making to the primary. Can an option be added to make the pool limit be a hard limit and if the pool is full/used then fail the sync?

@maitesin
Copy link

Hi @fastest963 ,

Thanks for taking the time to report this issue. We are happy to review pull requests, so feel free to send one with the changes to address the problem with the pool limit.

Best regards,
Oscar

@domodwyer
Copy link

Hi @fastest963

Is this actually creating the connections, or could it be related to #329? It might be worth trying with @KJTsanaktsidis's branch.

Dom

@vinllen vinllen mentioned this issue Aug 5, 2019
Open
@vinllen
Copy link

vinllen commented Aug 5, 2019

I've already submitted a bugfix branch to solve this problem, please review #373

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
enhancement help wanted
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@jameshartig @maitesin @vinllen @domodwyer @eminano