Mgo queries are run twice with goconvey. "go test" runs them once.

[shashanktomar]

I am facing a very strange issue. I have written the sample code to explain it. Here is my simple mgo interaction code which can insert, find and remove a struct from database.

package main

import (
    "log"

    "gopkg.in/mgo.v2"
    "gopkg.in/mgo.v2/bson"
)

var Db string

func InitDb(info *mgo.DialInfo) *mgo.Session {
    Db = info.Database
    session, err := mgo.DialWithInfo(info)
    if err != nil {
        log.Fatalf("CreateSession: %s\n", err)
    }
    session.SetMode(mgo.Monotonic, true)
    session.SetSafe(&mgo.Safe{})
    return session
}

type DataStore struct {
    Session        *mgo.Session
    CollectionName string
}

type Data struct {
    ID       bson.ObjectId `bson:"_id,omitempty"`
    fieldOne string        `bson:"filedOne,omitempty"`
    fieldTwo string        `bson:"filedTwo,omitempty"`
}

func NewDataStore(session *mgo.Session) *DataStore {
    return &DataStore{Session: session, CollectionName: "testCollection"}
}

func (d *DataStore) Insert(data *Data) error {
    session := d.Session.Copy()
    defer session.Close()
    collection := session.DB(Db).C(d.CollectionName)

    return collection.Insert(data)
}

func (d *DataStore) FindAll() ([]Data, error) {
    session := d.Session.Copy()
    defer session.Close()
    collection := session.DB(Db).C(d.CollectionName)

    var values []Data
    err := collection.Find(nil).All(&values)
    if err != nil {
        return nil, err
    }
    return values, nil
}

func (d *DataStore) Remove(id bson.ObjectId) error {
    session := d.Session.Copy()
    defer session.Close()
    collection := session.DB(Db).C(d.CollectionName)

    return collection.RemoveId(id)
}

And here are tests written using goconvey.

package main

import (
    "testing"
    "time"

    "gopkg.in/mgo.v2"

    . "github.com/smartystreets/goconvey/convey"
)

var s *mgo.Session

func initDbForTest() {
    if s == nil {
        mongoDBDialInfo := &mgo.DialInfo{
            Addrs:    []string{"localhost:27017"},
            Timeout:  60 * time.Second,
            FailFast: true,
            Database: "goconveyTestDb",
        }
        s = InitDb(mongoDBDialInfo)
    }
}

func TestFunction(t *testing.T) {
    initDbForTest()
    dataStore := NewDataStore(s)
    clear(s, dataStore.CollectionName)

    Convey("Given data", t, func() {
        data := &Data{fieldOne: "field1", fieldTwo: "field2"}
        Convey("Should insert it", func() {
            err := dataStore.Insert(data)
            So(err, ShouldBeNil)

            d, errf := dataStore.FindAll()
            So(errf, ShouldBeNil)
            So(len(d), ShouldEqual, 1)

            errd := dataStore.Remove(d[0].ID)
            So(errd, ShouldBeNil)
        })
    })
}

func clear(s *mgo.Session, col string) error {
    session := s.Copy()
    defer session.Close()
    collection := session.DB(Db).C(col)

    _, err := collection.RemoveAll(nil)
    return err
}

Everything pass and life is joyful and happy. But here comes the tricky part. I run these tests by calling goconvey in my test directory. When the tests are run, either explicitly from UI or by saving the file, my mongodb interactions happen twice i.e. there are two connections running in parallel which call insert, find and remove twice. Here is the log dumped by mongo.

2016-02-11T05:03:28.658+0000 I WRITE    [conn142] remove goconveyTestDb.testCollection ndeleted:0 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 0ms
2016-02-11T05:03:28.659+0000 I COMMAND  [conn142] command goconveyTestDb.$cmd command: delete { delete: "testCollection", deletes: [ { q: {}, limit: 0 } ], writeConcern: { getLastError: 1 }, ordered: true } ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 0ms
2016-02-11T05:03:28.659+0000 I COMMAND  [conn142] command goconveyTestDb.testCollection command: insert { insert: "testCollection", documents: [ {} ], writeConcern: { getLastError: 1 }, ordered: true } ntoskip:0 ninserted:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 0ms
2016-02-11T05:03:28.660+0000 I QUERY    [conn142] query goconveyTestDb.testCollection planSummary: COLLSCAN ntoreturn:0 ntoskip:0 keysExamined:0 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms
2016-02-11T05:03:28.661+0000 I WRITE    [conn142] remove goconveyTestDb.testCollection query: { _id: ObjectId('56bc1620b935340297b9f3cf') } ndeleted:1 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 0ms
2016-02-11T05:03:28.661+0000 I COMMAND  [conn142] command goconveyTestDb.$cmd command: delete { delete: "testCollection", deletes: [ { q: { _id: ObjectId('56bc1620b935340297b9f3cf') }, limit: 1 } ], writeConcern: { getLastError: 1 }, ordered: true } ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 0ms

2016-02-11T05:03:28.826+0000 I WRITE    [conn143] remove goconveyTestDb.testCollection ndeleted:0 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 0ms
2016-02-11T05:03:28.826+0000 I COMMAND  [conn143] command goconveyTestDb.$cmd command: delete { delete: "testCollection", deletes: [ { q: {}, limit: 0 } ], writeConcern: { getLastError: 1 }, ordered: true } ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 0ms
2016-02-11T05:03:28.827+0000 I COMMAND  [conn143] command goconveyTestDb.testCollection command: insert { insert: "testCollection", documents: [ {} ], writeConcern: { getLastError: 1 }, ordered: true } ntoskip:0 ninserted:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 0ms
2016-02-11T05:03:28.827+0000 I QUERY    [conn143] query goconveyTestDb.testCollection planSummary: COLLSCAN ntoreturn:0 ntoskip:0 keysExamined:0 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms
2016-02-11T05:03:28.828+0000 I WRITE    [conn143] remove goconveyTestDb.testCollection query: { _id: ObjectId('56bc1620b935340297b9f3d0') } ndeleted:1 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 0ms
2016-02-11T05:03:28.828+0000 I COMMAND  [conn143] command goconveyTestDb.$cmd command: delete { delete: "testCollection", deletes: [ { q: { _id: ObjectId('56bc1620b935340297b9f3d0') }, limit: 1 } ], writeConcern: { getLastError: 1 }, ordered: true } ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 0ms

In this logs the queries by two connections are sequential, but they are concurrent in most of the cases overlapping with each other. Now if i run the same tests by calling go test in test folder, the interactions happen only once. Here is the attached log.

2016-02-11T05:04:41.197+0000 I WRITE    [conn144] remove goconveyTestDb.testCollection ndeleted:0 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 0ms
2016-02-11T05:04:41.197+0000 I COMMAND  [conn144] command goconveyTestDb.$cmd command: delete { delete: "testCollection", deletes: [ { q: {}, limit: 0 } ], writeConcern: { getLastError: 1 }, ordered: true } ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 0ms
2016-02-11T05:04:41.198+0000 I COMMAND  [conn144] command goconveyTestDb.testCollection command: insert { insert: "testCollection", documents: [ {} ], writeConcern: { getLastError: 1 }, ordered: true } ntoskip:0 ninserted:1 keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 0ms
2016-02-11T05:04:41.199+0000 I QUERY    [conn144] query goconveyTestDb.testCollection planSummary: COLLSCAN ntoreturn:0 ntoskip:0 keysExamined:0 docsExamined:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:1 reslen:42 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } 0ms
2016-02-11T05:04:41.200+0000 I WRITE    [conn144] remove goconveyTestDb.testCollection query: { _id: ObjectId('56bc1669b935340297b9f3d1') } ndeleted:1 keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 0ms
2016-02-11T05:04:41.200+0000 I COMMAND  [conn144] command goconveyTestDb.$cmd command: delete { delete: "testCollection", deletes: [ { q: { _id: ObjectId('56bc1669b935340297b9f3d1') }, limit: 1 } ], writeConcern: { getLastError: 1 }, ordered: true } ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:0 reslen:40 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 0ms

This triggers a huge problem if the number of tests are large. Tests start failing randomly because of common concurrency issues. Like insertion happen twice and then test for find fails because length is 2.

Just invoke the local mongo server and try to run this code, its a very strange behaviour. Am i missing something about goconvey command?

[mdwhatcott]

goconvey logs debug output to the terminal. Could you post that output?

[shashanktomar]

Thanks for reply @mdwhatcott

Here are the logs from goconvey command run.

2016/02/12 06:58:30 integration.go:120: File system state modified, publishing current folders... 2910410872 2910410892
2016/02/12 06:58:30 goconvey.go:111: Received request from watcher to execute tests...
2016/02/12 06:58:30 executor.go:69: Executor status: 'executing'
2016/02/12 06:58:30 coordinator.go:46: Executing concurrent tests: .
2016/02/12 06:58:31 parser.go:24: [passed]: .
2016/02/12 06:58:31 executor.go:69: Executor status: 'idle'

This looks normal to me. One more observation is, if i quit goconvey process and run it again, everything runs fine for the first time, but on subsequent invocation by saving files, db calls are made twice.

Are you facing the same issue if you run the code above?

[shashanktomar]

Hi Folks,

Any update on this?

[mdwhatcott]

Nothing yet. You might try starting a fresh test suite that is as simple as possible, then slowly add stuff until you see the double execution.

[riannucci]

What if you move the 'clear' inside the first Convey function?

[farnasirim]

+1 Have observed the exact same behavior trying to test db related stuff.