Aggregation on large collection throws a "not a master" error most of the time

[Raul]

Hello,

This is more of a mongodb question than a mgo question but perhaps I'm hoping to gather responses based on everyone's experience using the MongoDB aggregation feature (via mgo's Pipeline)

I have a four node replicaSet and i'm running an aggregation over a large collection of about 120million+ records and uses the $out parameter.

I get a hit and miss with regards to proper execution of the Pipeline. Sometimes, the aggregation process completes but most of the time, I get  the following error


        failed to create temporary $out collection 'datahub.tmp.agg_out.18': { note: "from execCommand", ok: 0.0, errmsg: "not master" }

I am aware that the PRIMARY/SECONDARY roles doesn't change while the aggregation is running so I'm quite confused as to what is happening.

Could this be a driver (mgo) issue?

Following is the Pipeline code.

pipeline := []bson.M{

bson.M{"$match": bson.M{"vehicle.part_id": bson.M{"$gt": 0}}},

bson.M{"$group": bson.M{

"_id": bson.M{

"$concat": []interface{}{

bson.M{"$substr": []interface{}{"$vehicle.part_id", 0, -1}},

"_",

bson.M{"$substr": []interface{}{"$vehicle.aid", 0, -1}},

"_",

"$vehicle.veh_value",

},

},

"make_id":          bson.M{"$first": "$vehicle.make_id"},

"model_id":         bson.M{"$first": "$vehicle.model_id"},

"lba_id":         bson.M{"$first": "$vehicle.aid"},

                        <other statements.....>

},

},

bson.M{"$out": "tmp_partvehicle_map_stage2"},

}

pipe := mgoSession.DB(dbName).C("prodapps").Pipe(pipeline)

pipe.AllowDiskUse()

pipe.Batch(4)

Regards,

Raul

[Raul]

Hello,

Some additional context based on the Debug output:

The current replica status is

  MONGOSVR10.companygroup.com  is PRIMARY

    MONGOSVR11.companygroup.com  is SECONDARY

    MONGOSVR12.companygroup.com  is SECONDARY

And executing the code with debugger turned-on reveals that the aggregation with $out parameter is being sent to MONGOSVR11 which of course will fail because $out requires a primary. 

I have been using mgo.Strong or mgo.Monotonic to control the consistency but I can't seem to force aggregation queries with $out to execute against the PRIMARY server. 

Any idea how to do this via mgo?

2015/09/02 03:18:16 New session 0xc208040680 on cluster 0xc20804a000

2015/09/02 03:18:16 Session 0xc208040680: setting mode 1 with refresh=true (master=0x0, slave=0x0)

2015/09/02 03:18:16 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}

2015/09/02 03:18:16 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: sending 1 op(s) (58 bytes)

2015/09/02 03:18:16 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: updated write deadline to 5s ahead (2015-09-02 03:18:21.844881011 -0700 PDT)

2015/09/02 03:18:16 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: updated read deadline to 5s ahead (2015-09-02 03:18:21.844952802 -0700 PDT)

2015/09/02 03:18:16 SYNC Address MONGOSVR11.companygroup.com:27017 resolved as 10.10.30.179:27017

2015/09/02 03:18:16 SYNC Processing MONGOSVR11.companygroup.com:27017...

2015/09/02 03:18:16 Cluster 0xc20804a000 acquired (refs=4)

2015/09/02 03:18:16 New session 0xc2080409c0 on cluster 0xc20804a000

2015/09/02 03:18:16 Session 0xc2080409c0: setting mode 1 with refresh=true (master=0x0, slave=0x0)

2015/09/02 03:18:16 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}

2015/09/02 03:18:16 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: sending 1 op(s) (58 bytes)

2015/09/02 03:18:16 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: updated write deadline to 5s ahead (2015-09-02 03:18:21.845346875 -0700 PDT)

2015/09/02 03:18:16 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: updated read deadline to 5s ahead (2015-09-02 03:18:21.845390252 -0700 PDT)

2015/09/02 03:18:16 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: got reply (541 bytes)

2015/09/02 03:18:16 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: received document: bson.M{"setVersion":8, "maxWriteBatchSize":1000, "minWireVersion":0, "ismaster":false, "arbiters":[]interface {}{"MONGOSVR09.companygroup.com:27018"}, "primary":"MONGOSVR10.companygroup.com:27017", "me":"MONGOSVR12.companygroup.com:27017", "maxBsonObjectSize":16777216, "ok":1, "setName":"hydra-ng-prod", "secondary":true, "hosts":[]interface {}{"MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}, "maxMessageSizeBytes":48000000, "localTime":time.Time{sec:63576785896, nsec:849000000, loc:(*time.Location)(0x7ab020)}, "maxWireVersion":3}

2015/09/02 03:18:16 Run command unmarshaled: mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}, result: bson.M{"ismaster":false, "secondary":true, "maxBsonObjectSize":16777216, "localTime":time.Time{sec:63576785896, nsec:849000000, loc:(*time.Location)(0x7ab020)}, "me":"MONGOSVR12.companygroup.com:27017", "maxWriteBatchSize":1000, "setName":"hydra-ng-prod", "hosts":[]interface {}{"MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}, "arbiters":[]interface {}{"MONGOSVR09.companygroup.com:27018"}, "minWireVersion":0, "ok":1, "setVersion":8, "primary":"MONGOSVR10.companygroup.com:27017", "maxMessageSizeBytes":48000000, "maxWireVersion":3}

2015/09/02 03:18:16 Closing session 0xc208040680

2015/09/02 03:18:16 Cluster 0xc20804a000 released (refs=3)

2015/09/02 03:18:16 SYNC Result of 'ismaster' from MONGOSVR12.companygroup.com:27017: mgo.isMasterResult{IsMaster:false, Secondary:true, Primary:"MONGOSVR10.companygroup.com:27017", Hosts:[]string{"MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}, Passives:[]string(nil), Tags:bson.D(nil), Msg:"", SetName:"hydra-ng-prod", MaxWireVersion:3}

2015/09/02 03:18:16 SYNC MONGOSVR12.companygroup.com:27017 is a slave.

2015/09/02 03:18:16 SYNC MONGOSVR12.companygroup.com:27017 knows about the following peers: []string{"MONGOSVR10.companygroup.com:27017", "MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}

2015/09/02 03:18:16 SYNC Address MONGOSVR10.companygroup.com:27017 resolved as 10.10.30.178:27017

2015/09/02 03:18:16 SYNC Processing MONGOSVR10.companygroup.com:27017...

2015/09/02 03:18:16 Cluster 0xc20804a000 acquired (refs=4)

2015/09/02 03:18:16 New session 0xc208040ea0 on cluster 0xc20804a000

2015/09/02 03:18:16 Session 0xc208040ea0: setting mode 1 with refresh=true (master=0x0, slave=0x0)

2015/09/02 03:18:16 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}

2015/09/02 03:18:16 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: sending 1 op(s) (58 bytes)

2015/09/02 03:18:16 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: updated write deadline to 5s ahead (2015-09-02 03:18:21.847037036 -0700 PDT)

2015/09/02 03:18:16 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: updated read deadline to 5s ahead (2015-09-02 03:18:21.847082587 -0700 PDT)

2015/09/02 03:18:16 SYNC Address MONGOSVR10.companygroup.com:27017 resolved as 10.10.30.178:27017

2015/09/02 03:18:16 SYNC Address MONGOSVR10.companygroup.com:27017 resolved as 10.10.30.178:27017

2015/09/02 03:18:16 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: got reply (541 bytes)

2015/09/02 03:18:16 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: received document: bson.M{"primary":"MONGOSVR10.companygroup.com:27017", "setVersion":8, "hosts":[]interface {}{"MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}, "arbiters":[]interface {}{"MONGOSVR09.companygroup.com:27018"}, "maxBsonObjectSize":16777216, "maxMessageSizeBytes":48000000, "setName":"hydra-ng-prod", "me":"MONGOSVR11.companygroup.com:27017", "maxWireVersion":3, "minWireVersion":0, "ok":1, "secondary":true, "maxWriteBatchSize":1000, "localTime":time.Time{sec:63576785896, nsec:843000000, loc:(*time.Location)(0x7ab020)}, "ismaster":false}

2015/09/02 03:18:16 Run command unmarshaled: mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}, result: bson.M{"maxWireVersion":3, "setName":"hydra-ng-prod", "arbiters":[]interface {}{"MONGOSVR09.companygroup.com:27018"}, "primary":"MONGOSVR10.companygroup.com:27017", "localTime":time.Time{sec:63576785896, nsec:843000000, loc:(*time.Location)(0x7ab020)}, "setVersion":8, "hosts":[]interface {}{"MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}, "me":"MONGOSVR11.companygroup.com:27017", "maxMessageSizeBytes":48000000, "maxWriteBatchSize":1000, "ok":1, "ismaster":false, "secondary":true, "maxBsonObjectSize":16777216, "minWireVersion":0}

2015/09/02 03:18:16 Closing session 0xc2080409c0

2015/09/02 03:18:16 Cluster 0xc20804a000 released (refs=3)

2015/09/02 03:18:16 SYNC Result of 'ismaster' from MONGOSVR11.companygroup.com:27017: mgo.isMasterResult{IsMaster:false, Secondary:true, Primary:"MONGOSVR10.companygroup.com:27017", Hosts:[]string{"MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}, Passives:[]string(nil), Tags:bson.D(nil), Msg:"", SetName:"hydra-ng-prod", MaxWireVersion:3}

2015/09/02 03:18:16 SYNC MONGOSVR11.companygroup.com:27017 is a slave.

2015/09/02 03:18:16 SYNC MONGOSVR11.companygroup.com:27017 knows about the following peers: []string{"MONGOSVR10.companygroup.com:27017", "MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}

2015/09/02 03:18:16 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: got reply (565 bytes)

2015/09/02 03:18:16 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: received document: bson.M{"hosts":[]interface {}{"MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}, "localTime":time.Time{sec:63576785896, nsec:838000000, loc:(*time.Location)(0x7ab020)}, "maxWireVersion":3, "setName":"hydra-ng-prod", "setVersion":8, "maxWriteBatchSize":1000, "maxMessageSizeBytes":48000000, "ok":1, "secondary":false, "arbiters":[]interface {}{"MONGOSVR09.companygroup.com:27018"}, "electionId":"U׳\x88\x1dŲ$\x13\x03\xf23", "maxBsonObjectSize":16777216, "minWireVersion":0, "ismaster":true, "primary":"MONGOSVR10.companygroup.com:27017", "me":"MONGOSVR10.companygroup.com:27017"}

2015/09/02 03:18:16 Run command unmarshaled: mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ismaster", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}, result: bson.M{"me":"MONGOSVR10.companygroup.com:27017", "arbiters":[]interface {}{"MONGOSVR09.companygroup.com:27018"}, "primary":"MONGOSVR10.companygroup.com:27017", "maxWireVersion":3, "setVersion":8, "maxBsonObjectSize":16777216, "maxMessageSizeBytes":48000000, "maxWriteBatchSize":1000, "localTime":time.Time{sec:63576785896, nsec:838000000, loc:(*time.Location)(0x7ab020)}, "ok":1, "ismaster":true, "secondary":false, "electionId":"U׳\x88\x1dŲ$\x13\x03\xf23", "minWireVersion":0, "setName":"hydra-ng-prod", "hosts":[]interface {}{"MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}}

2015/09/02 03:18:16 Closing session 0xc208040ea0

2015/09/02 03:18:16 Cluster 0xc20804a000 released (refs=2)

2015/09/02 03:18:16 SYNC Result of 'ismaster' from MONGOSVR10.companygroup.com:27017: mgo.isMasterResult{IsMaster:true, Secondary:false, Primary:"MONGOSVR10.companygroup.com:27017", Hosts:[]string{"MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}, Passives:[]string(nil), Tags:bson.D(nil), Msg:"", SetName:"hydra-ng-prod", MaxWireVersion:3}

2015/09/02 03:18:16 SYNC MONGOSVR10.companygroup.com:27017 is a master.

2015/09/02 03:18:16 SYNC MONGOSVR10.companygroup.com:27017 knows about the following peers: []string{"MONGOSVR10.companygroup.com:27017", "MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}

2015/09/02 03:18:16 SYNC Broadcasting availability of server MONGOSVR10.companygroup.com:27017

2015/09/02 03:18:16 SYNC Address MONGOSVR12.companygroup.com:27017 resolved as 10.10.30.180:27017

2015/09/02 03:18:16 SYNC Address MONGOSVR12.companygroup.com:27017 resolved as 10.10.30.180:27017

2015/09/02 03:18:16 SYNC Address MONGOSVR12.companygroup.com:27017 resolved as 10.10.30.180:27017

2015/09/02 03:18:16 SYNC Broadcasting availability of server MONGOSVR12.companygroup.com:27017

2015/09/02 03:18:16 SYNC Address MONGOSVR11.companygroup.com:27017 resolved as 10.10.30.179:27017

2015/09/02 03:18:16 SYNC Address MONGOSVR11.companygroup.com:27017 resolved as 10.10.30.179:27017

2015/09/02 03:18:16 SYNC Address MONGOSVR11.companygroup.com:27017 resolved as 10.10.30.179:27017

2015/09/02 03:18:16 SYNC Broadcasting availability of server MONGOSVR11.companygroup.com:27017

2015/09/02 03:18:16 SYNC Address MONGOSVR10.companygroup.com:27017 resolved as 10.10.30.178:27017

2015/09/02 03:18:16 SYNC Address MONGOSVR10.companygroup.com:27017 resolved as 10.10.30.178:27017

2015/09/02 03:18:16 SYNC Address MONGOSVR10.companygroup.com:27017 resolved as 10.10.30.178:27017

2015/09/02 03:18:16 SYNC Address MONGOSVR10.companygroup.com:27017 resolved as 10.10.30.178:27017

2015/09/02 03:18:16 SYNC Synchronization was complete (got data from primary).

2015/09/02 03:18:16 SYNC Synchronization completed: 1 master(s) and 2 slave(s) alive.

2015/09/02 03:18:16 SYNC New dynamic seeds: []string{"MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}

2015/09/02 03:18:16 Cluster 0xc20804a000 released (refs=1)

2015/09/02 03:18:17 SYNC Cluster 0xc20804a000 waiting for next requested or scheduled sync.

2015/09/02 03:18:21 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}

2015/09/02 03:18:21 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: sending 1 op(s) (54 bytes)

2015/09/02 03:18:21 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: updated write deadline to 15s ahead (2015-09-02 03:18:36.33356545 -0700 PDT)

2015/09/02 03:18:21 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: updated read deadline to 15s ahead (2015-09-02 03:18:36.333635048 -0700 PDT)

2015/09/02 03:18:21 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}

2015/09/02 03:18:21 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: sending 1 op(s) (54 bytes)

2015/09/02 03:18:21 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: updated write deadline to 15s ahead (2015-09-02 03:18:36.333766449 -0700 PDT)

2015/09/02 03:18:21 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: updated read deadline to 15s ahead (2015-09-02 03:18:36.333801098 -0700 PDT)

2015/09/02 03:18:21 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: got reply (53 bytes)

2015/09/02 03:18:21 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: received document: bson.M{"ok":1}

2015/09/02 03:18:21 Ping for MONGOSVR10.companygroup.com:27017 is 1 ms

2015/09/02 03:18:21 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: got reply (53 bytes)

2015/09/02 03:18:21 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: received document: bson.M{"ok":1}

2015/09/02 03:18:21 Ping for MONGOSVR12.companygroup.com:27017 is 1 ms

2015/09/02 03:18:21 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}

2015/09/02 03:18:21 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: sending 1 op(s) (54 bytes)

2015/09/02 03:18:21 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: updated write deadline to 15s ahead (2015-09-02 03:18:36.3361936 -0700 PDT)

2015/09/02 03:18:21 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: updated read deadline to 15s ahead (2015-09-02 03:18:36.336247027 -0700 PDT)

2015/09/02 03:18:21 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: got reply (53 bytes)

2015/09/02 03:18:21 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: received document: bson.M{"ok":1}

2015/09/02 03:18:21 Ping for MONGOSVR11.companygroup.com:27017 is 0 ms

2015/09/02 03:18:26 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}

2015/09/02 03:18:26 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: sending 1 op(s) (54 bytes)

2015/09/02 03:18:26 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: updated write deadline to 15s ahead (2015-09-02 03:18:41.334252839 -0700 PDT)

2015/09/02 03:18:26 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: updated read deadline to 15s ahead (2015-09-02 03:18:41.334316648 -0700 PDT)

2015/09/02 03:18:26 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}

2015/09/02 03:18:26 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: sending 1 op(s) (54 bytes)

2015/09/02 03:18:26 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: updated write deadline to 15s ahead (2015-09-02 03:18:41.334443313 -0700 PDT)

2015/09/02 03:18:26 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: updated read deadline to 15s ahead (2015-09-02 03:18:41.334471974 -0700 PDT)

2015/09/02 03:18:26 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: got reply (53 bytes)

2015/09/02 03:18:26 Socket 0xc2080747e0 to MONGOSVR10.companygroup.com:27017: received document: bson.M{"ok":1}

2015/09/02 03:18:26 Ping for MONGOSVR10.companygroup.com:27017 is 1 ms

2015/09/02 03:18:26 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: got reply (53 bytes)

2015/09/02 03:18:26 Socket 0xc208074620 to MONGOSVR12.companygroup.com:27017: received document: bson.M{"ok":1}

2015/09/02 03:18:26 Ping for MONGOSVR12.companygroup.com:27017 is 1 ms

2015/09/02 03:18:26 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: serializing op: &mgo.queryOp{collection:"admin.$cmd", query:bson.D{bson.DocElem{Name:"ping", Value:1}}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}

2015/09/02 03:18:26 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: sending 1 op(s) (54 bytes)

2015/09/02 03:18:26 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: updated write deadline to 15s ahead (2015-09-02 03:18:41.336822698 -0700 PDT)

2015/09/02 03:18:26 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: updated read deadline to 15s ahead (2015-09-02 03:18:41.336875502 -0700 PDT)

2015/09/02 03:18:26 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: got reply (53 bytes)

2015/09/02 03:18:26 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: received document: bson.M{"ok":1}

2015/09/02 03:18:26 Ping for MONGOSVR11.companygroup.com:27017 is 0 ms

2015/09/02 03:18:26 Cluster 0xc20804a000 acquired (refs=2)

2015/09/02 03:18:26 New session 0xc2080409c0 on cluster 0xc20804a000 (copy from 0xc208040340)

2015/09/02 03:18:26 Session 0xc2080409c0: setting mode 1 with refresh=false (master=0x0, slave=0x0)

2015/09/02 03:18:26 Cluster has 1 known masters and 2 known slaves.

2015/09/02 03:18:26 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: serializing op: &mgo.queryOp{collection:"bigdb.$cmd", query:mgo.pipeCmd{Aggregate:"prodapps", Pipeline:[]bson.M{bson.M{"$match":bson.M{"vehicle.part_id":bson.M{"$gt":0}}}, bson.M{"$group":bson.M{"model_id":bson.M{"$first":"$vehicle.model_id"}, "submodel_id":bson.M{"$first":"$vehicle.submodel_id"}, "engine_id":bson.M{"$first":"$vehicle.engine_id"}, "appcol_id":bson.M{"$first":"$_id"}, "lba_id":bson.M{"$first":"$vehicle.aid"}, "_id":bson.M{"$concat":[]interface {}{bson.M{"$substr":[]interface {}{"$vehicle.part_id", 0, -1}}, "_", bson.M{"$substr":[]interface {}{"$vehicle.aid", 0, -1}}, "_", "$vehicle.veh_value"}}, "year_ids":bson.M{"$first":"$vehicle.year_id"}, "year_values":bson.M{"$first":"$vehicle.year_value"}, "part_id":bson.M{"$first":"$vehicle.part_id"}, "make_id":bson.M{"$first":"$vehicle.make_id"}, "legacy_engine_id":bson.M{"$first":"$vehicle.legacy_engine_id"}}}, bson.M{"$out":"tmp_partvehicle_map_stage2"}}, Cursor:(*mgo.pipeCmdCursor)(0xc208032b28), Explain:false, AllowDisk:true}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}

2015/09/02 03:18:26 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: sending 1 op(s) (921 bytes)

2015/09/02 03:18:26 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: updated write deadline to 2h0m0s ahead (2015-09-02 05:18:26.353272503 -0700 PDT)

2015/09/02 03:18:26 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: updated read deadline to 2h0m0s ahead (2015-09-02 05:18:26.35332765 -0700 PDT)

2015/09/02 03:18:26 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: got reply (215 bytes)

2015/09/02 03:18:26 Socket 0xc2080741c0 to MONGOSVR11.companygroup.com:27017: received document: bson.M{"errmsg":"exception: failed to create temporary $out collection 'bigdb.tmp.agg_out.82': { note: \"from execCommand\", ok: 0.0, errmsg: \"not master\" }", "code":16994, "ok":0}

2015/09/02 03:18:26 Run command unmarshaled: mgo.queryOp{collection:"bigdb.$cmd", query:mgo.pipeCmd{Aggregate:"prodapps", Pipeline:[]bson.M{bson.M{"$match":bson.M{"vehicle.part_id":bson.M{"$gt":0}}}, bson.M{"$group":bson.M{"part_id":bson.M{"$first":"$vehicle.part_id"}, "make_id":bson.M{"$first":"$vehicle.make_id"}, "legacy_engine_id":bson.M{"$first":"$vehicle.legacy_engine_id"}, "appcol_id":bson.M{"$first":"$_id"}, "lba_id":bson.M{"$first":"$vehicle.aid"}, "_id":bson.M{"$concat":[]interface {}{bson.M{"$substr":[]interface {}{"$vehicle.part_id", 0, -1}}, "_", bson.M{"$substr":[]interface {}{"$vehicle.aid", 0, -1}}, "_", "$vehicle.veh_value"}}, "year_ids":bson.M{"$first":"$vehicle.year_id"}, "year_values":bson.M{"$first":"$vehicle.year_value"}, "model_id":bson.M{"$first":"$vehicle.model_id"}, "submodel_id":bson.M{"$first":"$vehicle.submodel_id"}, "engine_id":bson.M{"$first":"$vehicle.engine_id"}}}, bson.M{"$out":"tmp_partvehicle_map_stage2"}}, Cursor:(*mgo.pipeCmdCursor)(0xc208032b28), Explain:false, AllowDisk:true}, skip:0, limit:-1, selector:interface {}(nil), flags:0x4, replyFunc:(mgo.replyFunc)(0x499a80), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}, result: bson.M{"errmsg":"exception: failed to create temporary $out collection 'bigdb.tmp.agg_out.82': { note: \"from execCommand\", ok: 0.0, errmsg: \"not master\" }", "code":16994, "ok":0}

2015/09/02 03:18:26 Closing session 0xc2080409c0

2015/09/02 03:18:26 Cluster 0xc20804a000 released (refs=1)

2015/09/02 03:18:26 &mgo.Session{m:sync.RWMutex{w:sync.Mutex{state:0, sema:0x0}, writerSem:0x0, readerSem:0x0, readerCount:0, readerWait:0}, cluster_:(*mgo.mongoCluster)(0xc20804a000), slaveSocket:(*mgo.mongoSocket)(nil), masterSocket:(*mgo.mongoSocket)(nil), slaveOk:false, consistency:2, queryConfig:mgo.query{op:mgo.queryOp{collection:"", query:interface {}(nil), skip:0, limit:0, selector:interface {}(nil), flags:0x0, replyFunc:(mgo.replyFunc)(nil), 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:""}, hasOptions:false, serverTags:[]bson.D(nil)}, prefetch:0.25, limit:0}, safeOp:(*mgo.queryOp)(0xc2080748c0), syncTimeout:7200000000000, sockTimeout:7200000000000, defaultdb:"bigdb", sourcedb:"bigdb", dialCred:(*mgo.Credential)(nil), creds:[]mgo.Credential(nil), poolLimit:4096}

2015/09/02 03:18:26 []string{"MONGOSVR10.companygroup.com:27017", "MONGOSVR11.companygroup.com:27017", "MONGOSVR12.companygroup.com:27017"}

2015/09/02 03:18:26 exception: failed to create temporary $out collection 'bigdb.tmp.agg_out.82': { note: "from execCommand", ok: 0.0, errmsg: "not master" }

2015/09/02 03:18:26 Error: "panic: Unable to generate: tmp_partvehicle_map_stage2 "

[Raul]

Hello again,

While waiting for comments from this community, I've made some workaround to ensure that I can move forward with my project.

I had to create an extra code that perform a "write" (or upsert) command before the problematic aggregation logic to ensure that the PRIMARY node becomes the active connection. Seems to work okay with me.

...

[Gustavo Niemeyer]

Hi Raul,

It sounds like you are using a Monotonic session and trying to write out via the aggregation command. This will indeed cause errors because the secondary cannot write, and it makes sense that it works when you do a first write because that forces the monotonic session to move onto the primary.

The better way to fix it is simply to use a Strong session when you want to perform an aggregation pipeline that involves writes. The driver is not parsing your pipeline to tell what sort of options you are using, so it cannot anticipate that this is what you want (at least not yet).

Makes sense?

--
You received this message because you are subscribed to the Google Groups "mgo-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mgo-users+...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

gustavo @ http://niemeyer.net

[Raul]

Hi Gustavo,

The thing that confuses me is, I've been using mgo.Strong mode ever since. Below is a snippet of the actual code.

var mongoHostsArr []string

mongoHostsArr = strings.Split(*mongoHosts, "|")

var mongoDialInfo = &mgo.DialInfo{

  Addrs:    mongoHostsArr,

  Timeout:  120 * time.Minute,

  Database: *mongoDbName,

}

mongoSession, err := mgo.DialWithInfo(mongoDialInfo)

if err != nil {

  log.Fatalf("Create Session: %s \n", err)

}

defer mongoSession.Close()

fmt.Printf("mongoHostsArr: %#v \n", mongoHostsArr)

fmt.Printf("mongodbSession.LiveServers: %#v \n", mongoSession.LiveServers())

if *debugMode == true {

  var mgoLogger *log.Logger

  mgoLogger = log.New(os.Stderr, "", log.LstdFlags)

  mgo.SetDebug(true)

  mgo.SetLogger(mgoLogger)

}

mongoSession.SetMode(mgo.Strong, true)

mongoSession.SetSafe(&mgo.Safe{W: 1})

     <call the method GenerateStage2Collection(mongoSession, "bigdb") to perform the aggregation> 

       ...

       ...

       ...

       ...

   

func GenerateStage2Collection(mgoSession *mgo.Session, dbName string) (bool, error) {

    <aggregation code with $out parameter>

}

          

Regards,

Raul

...