Data race in generated code

[SergeyRadist]

Hello guys, I probably have race in generated _mock file. This is my test https://pastebin.com/Bt5XAxhb go test ./ledger/light/proc/set_result_test.go -race -count 10000 full output here https://pastebin.com/EVUPkiVs short output:

==================
WARNING: DATA RACE
Write at 0x00c0004581a0 by goroutine 7:
  sync/atomic.AddInt64()
      /usr/local/Cellar/go/1.13/libexec/src/runtime/race_amd64.s:276 +0xb
  github.com/insolar/insolar/insolar/bus.(*SenderMock).Reply()
      /Users/radist/go/src/github.com/insolar/insolar/insolar/bus/sender_mock.go:179 +0xbed
  github.com/insolar/insolar/ledger/light/proc.(*SetResult).Proceed()
      /Users/radist/go/src/github.com/insolar/insolar/ledger/light/proc/set_result.go:152 +0xef9
  command-line-arguments_test.TestSetResult_Proceed_ResultDuplicated()
      /Users/radist/go/src/github.com/insolar/insolar/ledger/light/proc/set_result_test.go:263 +0xe68
  testing.tRunner()
      /usr/local/Cellar/go/1.13/libexec/src/testing/testing.go:909 +0x199

Previous write at 0x00c0004581a0 by goroutine 18:
  command-line-arguments_test.TestSetResult_Proceed_HasOpenedOutgoing_Error.func3()
      /Users/radist/go/src/github.com/insolar/insolar/ledger/light/proc/set_result_test.go:696 +0x263
  github.com/insolar/insolar/ledger/light/executor.(*FilamentCalculatorMock).OpenedRequests()
      /Users/radist/go/src/github.com/insolar/insolar/ledger/light/executor/filament_calculator_mock.go:224 +0xe9b
  github.com/insolar/insolar/ledger/light/proc.(*SetResult).Proceed()
      /Users/radist/go/src/github.com/insolar/insolar/ledger/light/proc/set_result.go:157 +0x11be
  command-line-arguments_test.TestSetResult_Proceed_HasOpenedOutgoing_Error()
      /Users/radist/go/src/github.com/insolar/insolar/ledger/light/proc/set_result_test.go:715 +0x18ff
  testing.tRunner()
      /usr/local/Cellar/go/1.13/libexec/src/testing/testing.go:909 +0x199

What I did? I've noticed that if I'm using Inspect instead of Set there is no race. So I added lock/unlock in mocked method before "Setted" func is calling and it helps

// Reply implements Sender
func (mmReply *SenderMock) Reply(ctx context.Context, origin payload.Meta, reply *message.Message) {
    mm_atomic.AddUint64(&mmReply.beforeReplyCounter, 1)
    defer mm_atomic.AddUint64(&mmReply.afterReplyCounter, 1)

    if mmReply.inspectFuncReply != nil {
        mmReply.inspectFuncReply(ctx, origin, reply)
    }

    params := &SenderMockReplyParams{ctx, origin, reply}

    // Record call args
    mmReply.ReplyMock.mutex.Lock()
    mmReply.ReplyMock.callArgs = append(mmReply.ReplyMock.callArgs, params)
    mmReply.ReplyMock.mutex.Unlock()

    for _, e := range mmReply.ReplyMock.expectations {
        if minimock.Equal(e.params, params) {
            mm_atomic.AddUint64(&e.Counter, 1)
            return
        }
    }

    if mmReply.ReplyMock.defaultExpectation != nil {
        mm_atomic.AddUint64(&mmReply.ReplyMock.defaultExpectation.Counter, 1)
        want := mmReply.ReplyMock.defaultExpectation.params
        got := SenderMockReplyParams{ctx, origin, reply}
        if want != nil && !minimock.Equal(*want, got) {
            mmReply.t.Errorf("SenderMock.Reply got unexpected parameters, want: %#v, got: %#v%s\n", *want, got, minimock.Diff(*want, got))
        }

        return

    }
    // here
    mmReply.ReplyMock.mutex.Lock()
    defer mmReply.ReplyMock.mutex.Unlock()
    if mmReply.funcReply != nil {
        mmReply.funcReply(ctx, origin, reply)
        return
    }
    mmReply.t.Fatalf("Unexpected call to SenderMock.Reply. %v %v %v", ctx, origin, reply)

}

I'm not sure that it is the right solution. If so, I can make a pr

Added: I've replaced code inside function to sleep to exclude races inside it

sender.ReplyMock.Set(func(_ context.Context, receivedMeta payload.Meta, resMsg *message.Message) {
        time.Sleep(2 * time.Millisecond)
    })

minimock version 2.1.9 Thanks!

[hexdigest]

Hi @SergeyRadist Thanks for posting the issue!

I briefly looked at your test and it seems like these tests are completely isolated one from each other so as mocks.

The difference between Set and Inspect is that all the code inside the Set(ted) func is executed when the test is running while inspect is called when the test is done and mc.Finish() is called. So my guess is that you either have race somewhere in your code or somewhere in the test. For example if you have following in every test:

        opened = []record.CompositeFilamentRecord{
            // req that we closing
            {
                RecordID: requestID,
                Record: record.Material{
                    Virtual: record.Wrap(&record.OutgoingRequest{}),
                },
            },
        }

Where opened is some local variable so if mocked OpenedRequests method is being called concurrently somewhere you have a data race. Of course wrapping the call to mocked func with mutex helps in this case but what should be actually protected with mutex is a critical section where you reassign a new value to opened var. I'm sure that we don't want to protect calls to mocked methods with mutexes bc it might hide some existing race conditions in the tested code.

Please check if my above guess about opened var is right and if not please provide the generated mock file so I have more information for analysis.

[hexdigest]

@SergeyRadist did you have a chance to look at the test and wrap assignment to opened var with mutex?

[SergeyRadist]

@SergeyRadist did you have a chance to look at the test and wrap assignment to opened var with mutex?

Thank you very much for your advice, but unfortunately I haven't check everything yet. Planning to do it till the end of the week

[SergeyRadist]

Hello again and thanks! I found a problem, in one of tests there were an invisible bug sender := bus.NewSenderMock(t) Only sad thing is that stack trace was unusable in this situation and I had to bother you

Btw as I can see from mock, there is no such difference between Set and Inspect. Inspected func is calling during the test and even earlier that Setted

[hexdigest]

@SergeyRadist

Ok no problem, indeed Inspect is being called before. Sorry for the misinformation I was looking at

        func (m *{{$mock}}) MinimockFinish() {
            if !m.minimockDone() {
                {{- range $method := $.Interface.Methods }}
                    m.Minimock{{$method.Name}}Inspect()
                {{ end -}}
                m.t.FailNow()
            }
        }

But I forgot that we call inspectFunc from the mocked method.