invocation from timer triggered go routine will report data race

[zdevwu]

There is a strange behaviour for the Call when triggered in go routines, a data race will be detected from timer triggered go routine but not in channel triggered go routine, see the bellow test cases:

func TestChannelTriggeredGoRoutineInvocation(t *testing.T) {
	ctrl := gomock.NewController(t)
	m := mock.NewMockMath(ctrl)

	called := make(chan struct{})
	releaseChannel := make(chan struct{})
	go func() {
		<-releaseChannel
		go func() {
			m.Sum(1, 1)
			called <- struct{}{}
		}()
	}()

	m.EXPECT().
		Sum(gomock.Any(), gomock.Any()).
		Return(2)
	close(releaseChannel)
	<-called
}

func TestTimerTriggeredGoRoutineInvocation(t *testing.T) {
	t.Skip("this test should not fail but it does")
	ctrl := gomock.NewController(t)
	m := mock.NewMockMath(ctrl)

	called := make(chan struct{})
	go func() {
		<-time.After(time.Millisecond * 300)
		go func() {
			m.Sum(1, 1)
			called <- struct{}{}
		}()
	}()

	m.EXPECT().
		Sum(gomock.Any(), gomock.Any()).
		Return(2)
	<-called
}

==================
WARNING: DATA RACE
Read at 0x00c000138160 by goroutine 18:
  go.uber.org/mock/gomock.(*Call).call()
      /home/zdevwu/projects/mock/gomock/call.go:432 +0x7ba
  go.uber.org/mock/gomock.(*Controller).Call.func1()
      /home/zdevwu/projects/mock/gomock/controller.go:224 +0x767
  go.uber.org/mock/gomock.(*Controller).Call()
      /home/zdevwu/projects/mock/gomock/controller.go:229 +0xc6
  go.uber.org/mock/sample/concurrent/mock.(*MockMath).Sum()
      /home/zdevwu/projects/mock/sample/concurrent/mock/concurrent_mock.go:44 +0x176
  go.uber.org/mock/sample/concurrent.TestTimerTriggeredGoRoutineInvocation.func1.1()
      /home/zdevwu/projects/mock/sample/concurrent/concurrent_test.go:119 +0x3b

Previous write at 0x00c000138160 by goroutine 16:
  go.uber.org/mock/gomock.(*Call).addAction()
      /home/zdevwu/projects/mock/gomock/call.go:497 +0xe8c
  go.uber.org/mock/gomock.(*Call).Return()
      /home/zdevwu/projects/mock/gomock/call.go:220 +0x3e9
  go.uber.org/mock/sample/concurrent.TestTimerTriggeredGoRoutineInvocation()
      /home/zdevwu/projects/mock/sample/concurrent/concurrent_test.go:126 +0x2d8
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 18 (running) created at:
  go.uber.org/mock/sample/concurrent.TestTimerTriggeredGoRoutineInvocation.func1()
      /home/zdevwu/projects/mock/sample/concurrent/concurrent_test.go:118 +0x104

Goroutine 16 (running) created at:
  testing.(*T).Run()
      /snap/go/10585/src/testing/testing.go:1742 +0x825
  testing.runTests.func1()
      /snap/go/10585/src/testing/testing.go:2161 +0x85
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.runTests()
      /snap/go/10585/src/testing/testing.go:2159 +0x8be
  testing.(*M).Run()
      /snap/go/10585/src/testing/testing.go:2027 +0xf17
  main.main()
      _testmain.go:55 +0x2bd
==================
==================
WARNING: DATA RACE
Read at 0x00c0001161c8 by goroutine 18:
  go.uber.org/mock/gomock.(*Controller).Call()
      /home/zdevwu/projects/mock/gomock/controller.go:232 +0xeb
  go.uber.org/mock/sample/concurrent/mock.(*MockMath).Sum()
      /home/zdevwu/projects/mock/sample/concurrent/mock/concurrent_mock.go:44 +0x176
  go.uber.org/mock/sample/concurrent.TestTimerTriggeredGoRoutineInvocation.func1.1()
      /home/zdevwu/projects/mock/sample/concurrent/concurrent_test.go:119 +0x3b

Previous write at 0x00c0001161c8 by goroutine 16:
  go.uber.org/mock/gomock.(*Call).addAction()
      /home/zdevwu/projects/mock/gomock/call.go:497 +0xe30
  go.uber.org/mock/gomock.(*Call).Return()
      /home/zdevwu/projects/mock/gomock/call.go:220 +0x3e9
  go.uber.org/mock/sample/concurrent.TestTimerTriggeredGoRoutineInvocation()
      /home/zdevwu/projects/mock/sample/concurrent/concurrent_test.go:126 +0x2d8
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.(*T).Run.gowrap1()
      /snap/go/10585/src/testing/testing.go:1742 +0x44

Goroutine 18 (running) created at:
  go.uber.org/mock/sample/concurrent.TestTimerTriggeredGoRoutineInvocation.func1()
      /home/zdevwu/projects/mock/sample/concurrent/concurrent_test.go:118 +0x104

Goroutine 16 (running) created at:
  testing.(*T).Run()
      /snap/go/10585/src/testing/testing.go:1742 +0x825
  testing.runTests.func1()
      /snap/go/10585/src/testing/testing.go:2161 +0x85
  testing.tRunner()
      /snap/go/10585/src/testing/testing.go:1689 +0x21e
  testing.runTests()
      /snap/go/10585/src/testing/testing.go:2159 +0x8be
  testing.(*M).Run()
      /snap/go/10585/src/testing/testing.go:2027 +0xf17
  main.main()
      _testmain.go:55 +0x2bd
==================
    concurrent_test.go:128: race should be detected
    testing.go:1398: race detected during execution of test
--- FAIL: TestTimerTriggeredInvocation (0.31s)

The fork to demo the issue here:

https://github.com/zdevwu/mock/commit/0a962b4727acd05a4a8b0568c1f083f98473a378

• gomock mode (reflect or source): source
• gomock version or git ref: c9ae04c6e772f065390ee33052c1ed0ce753b897
• golang version: go1.22.2

Triage Notes for the Maintainers

[r-hang]

Hey @zdevwu, are you expecting the mock generated methods to be concurrency safe? If so, they're not expected to be.

With respect to the two cases you gave above, the first case does not race as he first goroutine only gets unblocked after the mock expectation is declared which serializes the the Sum expectation setting and the mock call to Sum.

[zdevwu]

Thanks for getting back @r-hang, can you elaborate a bit on the second case please? Although not explicitly sending the signal by closing the releaseChannel to continue to launch the go routine, the timer in second case makes sure the mock happens before the nested go routine that is calling Sum start running, both cases the mock happens before the call, but race is only detected in the second case with timer released go routine.