testify: race condition on master in mock

Upgraded to master and tests that previously ran without issues now fail the race detector:

$ go test ./model/modelhelpers/ -race -run TestUpdateRefreshScheduleTimerSuccess
==================
WARNING: DATA RACE
Read at 0x00c4203a34e8 by goroutine 21:
  reflect.typedmemmove()
      /usr/local/Cellar/go/1.10.2/libexec/src/runtime/mbarrier.go:265 +0x0
  reflect.packEface()
      /usr/local/Cellar/go/1.10.2/libexec/src/reflect/value.go:119 +0x101
  reflect.valueInterface()
      /usr/local/Cellar/go/1.10.2/libexec/src/reflect/value.go:978 +0x16a
  reflect.Value.Interface()
      /usr/local/Cellar/go/1.10.2/libexec/src/reflect/value.go:948 +0x51
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.10.2/libexec/src/fmt/print.go:699 +0x3700
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.10.2/libexec/src/fmt/print.go:853 +0x2550
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.10.2/libexec/src/fmt/print.go:689 +0x192
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.10.2/libexec/src/fmt/print.go:1099 +0x912
  fmt.Sprintf()
      /usr/local/Cellar/go/1.10.2/libexec/src/fmt/print.go:203 +0x73
  some.company.com/some/go-repo/vendor/github.com/stretchr/testify/mock.Arguments.Diff()
      /Users/andrewdeandrade/go/src/some.company.com/some/go-repo/vendor/github.com/stretchr/testify/mock/mock.go:678 +0x1416
  some.company.com/some/go-repo/vendor/github.com/stretchr/testify/mock.(*Mock).findExpectedCall()
      /Users/andrewdeandrade/go/src/some.company.com/some/go-repo/vendor/github.com/stretchr/testify/mock/mock.go:267 +0x175
  some.company.com/some/go-repo/vendor/github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/andrewdeandrade/go/src/some.company.com/some/go-repo/vendor/github.com/stretchr/testify/mock/mock.go:343 +0xb3
  some.company.com/some/go-repo/vendor/github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/andrewdeandrade/go/src/some.company.com/some/go-repo/vendor/github.com/stretchr/testify/mock/mock.go:333 +0x18a
  some.company.com/some/go-repo/mocks.(*ProvidesTimers).Remove()
      /Users/andrewdeandrade/go/src/some.company.com/some/go-repo/mocks/provides_timers.go:40 +0x2a1

Previous write at 0x00c4203a34e8 by goroutine 20:
  sync/atomic.CompareAndSwapInt32()
      /usr/local/Cellar/go/1.10.2/libexec/src/runtime/race_amd64.s:293 +0xb
  sync.(*Mutex).Lock()
      /usr/local/Cellar/go/1.10.2/libexec/src/sync/mutex.go:74 +0x4d
  some.company.com/some/go-repo/vendor/github.com/stretchr/testify/mock.(*Mock).AssertCalled()
      /Users/andrewdeandrade/go/src/some.company.com/some/go-repo/vendor/github.com/stretchr/testify/mock/mock.go:489 +0xc8
  some.company.com/some/go-repo/model/modelhelpers.TestUpdateRefreshScheduleTimerSuccess()
      /Users/andrewdeandrade/go/src/some.company.com/some/go-repo/model/modelhelpers/helpers_test.go:267 +0xafe
  testing.tRunner()
      /usr/local/Cellar/go/1.10.2/libexec/src/testing/testing.go:777 +0x16d

Goroutine 21 (running) created at:
  some.company.com/some/go-repo/model/modelhelpers.removeTimerAsync()
      /Users/andrewdeandrade/go/src/some.company.com/some/go-repo/model/modelhelpers/helpers.go:94 +0x10f
  some.company.com/some/go-repo/model/modelhelpers.UpdateRefreshScheduleTimer()
      /Users/andrewdeandrade/go/src/some.company.com/some/go-repo/model/modelhelpers/helpers.go:152 +0x2c2
  some.company.com/some/go-repo/model/modelhelpers.TestUpdateRefreshScheduleTimerSuccess()
      /Users/andrewdeandrade/go/src/some.company.com/some/go-repo/model/modelhelpers/helpers_test.go:241 +0x5e0
  testing.tRunner()
      /usr/local/Cellar/go/1.10.2/libexec/src/testing/testing.go:777 +0x16d

Goroutine 20 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.10.2/libexec/src/testing/testing.go:824 +0x564
  testing.runTests.func1()
      /usr/local/Cellar/go/1.10.2/libexec/src/testing/testing.go:1063 +0xa4
  testing.tRunner()
      /usr/local/Cellar/go/1.10.2/libexec/src/testing/testing.go:777 +0x16d
  testing.runTests()
      /usr/local/Cellar/go/1.10.2/libexec/src/testing/testing.go:1061 +0x4e1
  testing.(*M).Run()
      /usr/local/Cellar/go/1.10.2/libexec/src/testing/testing.go:978 +0x2cd
  main.main()
      _testmain.go:52 +0x22a

Has anyone else encountered this?

About this issue

  • Original URL
  • State: closed
  • Created 6 years ago
  • Reactions: 1
  • Comments: 24 (5 by maintainers)

Commits related to this issue

Most upvoted comments

I’m still seeing what looks to be a related error on master @ 6241f9ab994219cafb009b160a20acf4a62063aa

WARNING: DATA RACE
Read at 0x00c000039d10 by goroutine 13:
  reflect.typedmemmove()
      /usr/local/go/src/runtime/mbarrier.go:177 +0x0
  reflect.packEface()
      /usr/local/go/src/reflect/value.go:121 +0x12f
  reflect.valueInterface()
      /usr/local/go/src/reflect/value.go:1046 +0x1cd
  reflect.Value.Interface()
      /usr/local/go/src/reflect/value.go:1016 +0x3b64
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:722 +0x3b65
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:876 +0x267b
  fmt.(*pp).printArg()
      /usr/local/go/src/fmt/print.go:712 +0x284
  fmt.(*pp).doPrintf()
      /usr/local/go/src/fmt/print.go:1026 +0x330
  fmt.Sprintf()
      /usr/local/go/src/fmt/print.go:219 +0x73
  github.com/stretchr/testify/mock.callString()
      /home/myuser/Projects/my-project/vendor/github.com/stretchr/testify/mock/mock.go:362 +0x175
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /home/myuser/Projects/my-project/vendor/github.com/stretchr/testify/mock/mock.go:420 +0x1c4
  github.com/stretchr/testify/mock.(*Mock).Called()
      /home/myuser/Projects/my-project/vendor/github.com/stretchr/testify/mock/mock.go:391 +0x1ed

In my case, the particular mock that seems to be problematic is

type MockDoer struct{ mock.Mock }
func (m *MockDoer) Do(ctx context.Context, t string) ([]string, error) {
	args := m.Called(ctx, t)
	return args.Get(0).([]string), args.Error(1)
}
+3
ndisidore on May 13, 2021

I’m also on v.1.6.1, and see the same race condition appear every now and then.

Some of our arguments to a mocked function are structs containing a sync.Mutex. The Called() function deeply inspects those, which causes a race condition with the Mutex.Lock() function.

We already changed our mock.On(...)-calls to use mock.AnythingOfType(...) for those structs, with the reasoning that if the type matches, there should be no need to do that deep inspection (with reflection) of all struct members at all. But unfortunately this makes no difference: mock.Arguments.Diff is still being called by mock.Called, causing the race condition.

==================
WARNING: DATA RACE
Write at 0x00c000177024 by goroutine 22:
  sync/atomic.CompareAndSwapInt32()
      /usr/local/go/src/runtime/race_amd64.s:293 +0xb
  sync.(*Mutex).Lock()
      /usr/local/go/src/sync/mutex.go:74 +0x49

Previous read at 0x00c000177024 by goroutine 77:
  reflect.Value.Int()
      /usr/local/go/src/reflect/value.go:979 +0x3746
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:749 +0x3618
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:810 +0x296e
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:810 +0x296e
  fmt.(*pp).printValue()
      /usr/local/go/src/fmt/print.go:880 +0x2709
  fmt.(*pp).printArg()
      /usr/local/go/src/fmt/print.go:716 +0x25a
  fmt.(*pp).doPrintf()
      /usr/local/go/src/fmt/print.go:1126 +0x910
  fmt.Sprintf()
      /usr/local/go/src/fmt/print.go:219 +0x73
  github.com/stretchr/testify/mock.Arguments.Diff()
      /go/pkg/mod/github.com/stretchr/testify@v1.6.1/mock/mock.go:768 +0x1515
  github.com/stretchr/testify/mock.(*Mock).findExpectedCall()
      /go/pkg/mod/github.com/stretchr/testify@v1.6.1/mock/mock.go:287 +0x16a
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /go/pkg/mod/github.com/stretchr/testify@v1.6.1/mock/mock.go:366 +0xb3
  github.com/stretchr/testify/mock.(*Mock).Called()
      /go/pkg/mod/github.com/stretchr/testify@v1.6.1/mock/mock.go:356 +0x1e4
+3
mtenberge on Sep 14, 2020

I think the problem is more evident when mocking functions that receive a context

+3
dcu on Aug 29, 2018

I’m still seeing the data race:

WARNING: DATA RACE
Write at 0x00c000088230 by goroutine 54:
  sync/atomic.CompareAndSwapInt32()
      /usr/local/Cellar/go/1.11/libexec/src/runtime/race_amd64.s:293 +0xb
  sync.(*Mutex).Lock()
      /usr/local/Cellar/go/1.11/libexec/src/sync/mutex.go:74 +0x4d
  net/http.(*Server).trackConn()
      /usr/local/Cellar/go/1.11/libexec/src/net/http/server.go:2922 +0x4a
  net/http.(*conn).setState()
      /usr/local/Cellar/go/1.11/libexec/src/net/http/server.go:1689 +0x1a2
  net/http.(*Server).Serve()
      /usr/local/Cellar/go/1.11/libexec/src/net/http/server.go:2850 +0x489
  net/http/httptest.(*Server).goServe.func1()
      /usr/local/Cellar/go/1.11/libexec/src/net/http/httptest/server.go:280 +0xac

Previous read at 0x00c000088230 by goroutine 62:
  reflect.typedmemmove()
      /usr/local/Cellar/go/1.11/libexec/src/runtime/mbarrier.go:177 +0x0
  reflect.packEface()
      /usr/local/Cellar/go/1.11/libexec/src/reflect/value.go:119 +0x103
  reflect.valueInterface()
      /usr/local/Cellar/go/1.11/libexec/src/reflect/value.go:978 +0x16f
  reflect.Value.Interface()
      /usr/local/Cellar/go/1.11/libexec/src/reflect/value.go:948 +0x51
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:699 +0x3b32
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:853 +0x27ae
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:689 +0x2fb
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:1003 +0x32d
  fmt.Sprintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:203 +0x73
  context.(*valueCtx).String()
      /usr/local/Cellar/go/1.11/libexec/src/context/context.go:486 +0x109
  fmt.(*pp).handleMethods()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:603 +0x404
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:686 +0x255
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:1003 +0x32d
  fmt.Sprintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:203 +0x73
  context.(*valueCtx).String()
      /usr/local/Cellar/go/1.11/libexec/src/context/context.go:486 +0x109
  fmt.(*pp).handleMethods()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:603 +0x404
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:686 +0x255
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:1003 +0x32d
  fmt.Sprintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:203 +0x73
  context.(*cancelCtx).String()
      /usr/local/Cellar/go/1.11/libexec/src/context/context.go:343 +0x9a
  fmt.(*pp).handleMethods()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:603 +0x404
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:686 +0x255
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:1003 +0x32d
  fmt.Sprintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:203 +0x73
  context.(*cancelCtx).String()
      /usr/local/Cellar/go/1.11/libexec/src/context/context.go:343 +0x9a
  fmt.(*pp).handleMethods()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:603 +0x404
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:686 +0x255
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:1003 +0x32d
  fmt.Sprintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:203 +0x73
  context.(*valueCtx).String()
      /usr/local/Cellar/go/1.11/libexec/src/context/context.go:486 +0x109
  fmt.(*pp).handleMethods()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:603 +0x404
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:686 +0x255
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:1003 +0x32d
  fmt.Sprintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:203 +0x73
  context.(*valueCtx).String()
      /usr/local/Cellar/go/1.11/libexec/src/context/context.go:486 +0x109
  fmt.(*pp).handleMethods()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:603 +0x404
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:686 +0x255
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:1003 +0x32d
  fmt.Sprintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:203 +0x73
  context.(*valueCtx).String()
      /usr/local/Cellar/go/1.11/libexec/src/context/context.go:486 +0x109
  fmt.(*pp).handleMethods()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:603 +0x404
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:686 +0x255
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:1099 +0x93f
  fmt.Sprintf()
      /usr/local/Cellar/go/1.11/libexec/src/fmt/print.go:203 +0x73
  github.com/stretchr/testify/mock.Arguments.Diff.func1()
      /Users/dcuadrado/Projects/GoCode/src/github.com/stretchr/testify/mock/mock.go:690 +0xdd
  github.com/stretchr/testify/mock.Arguments.Diff()
      /Users/dcuadrado/Projects/GoCode/src/github.com/stretchr/testify/mock/mock.go:722 +0x4cf
  github.com/stretchr/testify/mock.(*Mock).findExpectedCall()
      /Users/dcuadrado/Projects/GoCode/src/github.com/stretchr/testify/mock/mock.go:267 +0x177
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/dcuadrado/Projects/GoCode/src/github.com/stretchr/testify/mock/mock.go:343 +0xb3
  github.com/stretchr/testify/mock.(*Mock).Called()

Using:

[~/P/G/s/g/s/testify] [⎇ 365386c] $ git log -1
commit 365386cb02c44b632277e859d737c3456b1630a2 (HEAD, gz-c/fix-diff-race)
Author: gz-c <token@protonmail.com>
Date:   Tue Aug 28 11:01:10 2018 +0800

    Fix #625 Diff race condition
+1
dcu on Aug 28, 2018
Read more comments on GitHub
← testify: assert.Equal randomly fails testing maps
stride: Can't build from editor but build works from visual studio →