search

globalsign / mgo

The MongoDB driver for Go
Other
1.97k stars 230 forks source link

More sockets created than PoolLimit #322

Open jameshartig opened 5 years ago

jameshartig commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

Hi @fastest963

Is this actually creating the connections, or could it be related to https://github.com/globalsign/mgo/pull/329? It might be worth trying with @KJTsanaktsidis's branch.

Dom

vinllen commented 5 years ago

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