Fix race in Diff printer #654

gz-c · 2018-08-28T07:09:32Z

Fixes #625

Race conditions were triggered when Sprintf-ing certain objects when preparing a diff for mock failures.

This restores the order of sprintf(obj) calls to the order it was prior to the race condition appearing.

Incorporates a new test case from @bhcleek

gz-c · 2018-08-29T03:40:30Z

The problem is when the object to print has a mutex, and another goroutine is locking or unlocking the mutex, the sprintf will race. There is not a clear solution to fix this in all cases. At least for the common case of tests passing, this could skip the sprintf of the actual value and print expected instead. Another option is capturing values and deferring the sprintf until later, but this would need a larger redesign.

dcu · 2018-09-12T23:15:44Z

this one doesn't completely fix the issue but it helps, I think it should be merged for now. this issue is very frustrating

dcu · 2019-01-09T16:54:37Z

@georgelesica-wf can you take a look at this one?

georgelesica-wf · 2019-01-10T21:35:26Z

When I revert the changes to mock/mock.go and run the test suite I don't see a failure. Are you sure the new test actually does what it attempts to do?

dcu · 2019-01-11T18:27:52Z

@georgelesica-wf are you running the tests with -race ?

georgelesica-wf · 2019-01-11T20:04:50Z

$ go test -race ./...
ok  	github.com/stretchr/testify	1.035s
ok  	github.com/stretchr/testify/assert	1.095s
?   	github.com/stretchr/testify/http	[no test files]
ok  	github.com/stretchr/testify/mock	1.141s
ok  	github.com/stretchr/testify/require	1.047s
ok  	github.com/stretchr/testify/suite	1.078s

This is after I removed the changes made to mock/mock.go in this PR. I would expect the new test to fail without those changes, but it does not, unless I'm doing something wrong here. I don't think the race condition detector should matter here, but here it is without...

$ GOCACHE=false go test ./...
ok  	github.com/stretchr/testify	0.019s
ok  	github.com/stretchr/testify/assert	0.041s
?   	github.com/stretchr/testify/http	[no test files]
ok  	github.com/stretchr/testify/mock	0.055s
ok  	github.com/stretchr/testify/require	0.025s
ok  	github.com/stretchr/testify/suite	0.025s

bhcleek · 2019-01-11T20:46:42Z

@georgelesica-wf 👋 I'm the original author of that test. I haven't checked the test on latest master, but I can relatively reliably get it to fail on the commit that added the test.

As you may know, the race detector can have false negatives, but is guaranteed to not have false positives. When I checkout the commit that added the test and then run go test -count=1 -race ./..., the race condition happens much more often than not:

╭─bhcleek@dishrag:~/go/src/github.com/stretchr/testify (master=)
╰─❯❯❯ git checkout 43ab038
... snip output of checkout of detached HEAD ...
╭─bhcleek@dishrag:~/go/src/github.com/stretchr/testify ((43ab038...))
╰─❯❯❯ go test -count=1 -race ./...
ok      github.com/stretchr/testify     1.031s
ok      github.com/stretchr/testify/assert      1.115s
?       github.com/stretchr/testify/http        [no test files]
==================
WARNING: DATA RACE
Write at 0x00c000148570 by goroutine 58:
...

glesica

lgtm thank you for your contribution, sorry it took so long!

mock/mock.go

Print "FAIL" upon failure, not "PASS"

gz-c · 2020-09-04T09:22:13Z

Note: the same race condition is still there, and always has been. It became more likely to occur with PR #596. This PR restores the order of sprintf calls to how it was before #596, which triggers the race condition less often, at least when using the latest go runtime at the time this was written. Some people will continue to have race failures.

reductionista · 2022-04-10T21:39:40Z

The Test_Mock_AssertExpectationsServer test added in this PR passes on master (v1.7.1) (at least with go 1.18 and 1.17?), and does not hit any race condition for me (even if run with race detection many times in parallel).

However, there is a race condition on master when a mocked function with a Context arg is called more than the expected number of times (or if it's not expected at all). For example:

func TestContextRace(t *testing.T) {
    m := &mock.Mock{}
    m.On("TestContextRace", mock.Anything).Once().Return()

    ctx, _ := context.WithCancel(context.Background())

    go func() {
        <-ctx.Done()
    }() 

    m.Called(ctx)
    m.Called(ctx)
}

go test -run TestContextRace -count 1 -race

==================
WARNING: DATA RACE
Read at 0x00c00016eb50 by goroutine 7:
  reflect.typedmemmove()
      /opt/homebrew/Cellar/go/1.18/libexec/src/runtime/mbarrier.go:178 +0x0
  reflect.packEface()
      /opt/homebrew/Cellar/go/1.18/libexec/src/reflect/value.go:123 +0x94
  reflect.valueInterface()
      /opt/homebrew/Cellar/go/1.18/libexec/src/reflect/value.go:1460 +0x14c
  reflect.Value.Interface()
      /opt/homebrew/Cellar/go/1.18/libexec/src/reflect/value.go:1430 +0x78
  fmt.(*pp).printValue()
      /opt/homebrew/Cellar/go/1.18/libexec/src/fmt/print.go:722 +0x7c
  fmt.(*pp).printValue()
      /opt/homebrew/Cellar/go/1.18/libexec/src/fmt/print.go:876 +0xee0
  fmt.(*pp).printArg()
      /opt/homebrew/Cellar/go/1.18/libexec/src/fmt/print.go:712 +0xbec
  fmt.(*pp).doPrintf()
      /opt/homebrew/Cellar/go/1.18/libexec/src/fmt/print.go:1026 +0x348
  fmt.Sprintf()
      /opt/homebrew/Cellar/go/1.18/libexec/src/fmt/print.go:219 +0x54
  github.com/stretchr/testify/mock.callString()
      /Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/testify@v1.7.1/mock/mock.go:362 +0x240
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/testify@v1.7.1/mock/mock.go:407 +0xa0
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/testify@v1.7.1/mock/mock.go:391 +0x140
  mygo/mockrace/m/v2.TestContextRace()
      /Users/dominovaldano/go-arm64/pkg/mod/mygo/mockrace/mockrace_test.go:234 +0x2a8
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1439 +0x18c
  testing.(*T).Run.func1()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1486 +0x44

Previous write at 0x00c00016eb50 by goroutine 8:
  ??()
      -:0 +0x104708b48
  sync/atomic.AddInt32()
      <autogenerated>:1 +0x14
  context.(*cancelCtx).Done.func1()
      /opt/homebrew/Cellar/go/1.18/libexec/src/context/context.go:364 +0x38
  runtime.deferreturn()
      /opt/homebrew/Cellar/go/1.18/libexec/src/runtime/panic.go:436 +0x34
  mygo/mockrace/m/v2.TestContextRace.func1()
      /Users/dominovaldano/go-arm64/pkg/mod/mygo/mockrace/mockrace_test.go:230 +0x40

Goroutine 7 (running) created at:
  testing.(*T).Run()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1486 +0x560
  testing.runTests.func1()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1839 +0x94
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1439 +0x18c
  testing.runTests()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1837 +0x6c8
  testing.(*M).Run()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1719 +0x878
  main.main()
      _testmain.go:59 +0x2fc

Goroutine 8 (running) created at:
  mygo/mockrace/m/v2.TestContextRace()
      /Users/dominovaldano/go-arm64/pkg/mod/mygo/mockrace/mockrace_test.go:229 +0x190
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1439 +0x18c
  testing.(*T).Run.func1()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1486 +0x44
==================
==================
WARNING: DATA RACE
Read at 0x00c00016eb58 by goroutine 7:
  reflect.typedmemmove()
      /opt/homebrew/Cellar/go/1.18/libexec/src/runtime/mbarrier.go:178 +0x0
  reflect.packEface()
      /opt/homebrew/Cellar/go/1.18/libexec/src/reflect/value.go:123 +0x94
  reflect.valueInterface()
      /opt/homebrew/Cellar/go/1.18/libexec/src/reflect/value.go:1460 +0x14c
  reflect.Value.Interface()
      /opt/homebrew/Cellar/go/1.18/libexec/src/reflect/value.go:1430 +0x78
  fmt.(*pp).printValue()
      /opt/homebrew/Cellar/go/1.18/libexec/src/fmt/print.go:722 +0x7c
  fmt.(*pp).printValue()
      /opt/homebrew/Cellar/go/1.18/libexec/src/fmt/print.go:876 +0xee0
  fmt.(*pp).printArg()
      /opt/homebrew/Cellar/go/1.18/libexec/src/fmt/print.go:712 +0xbec
  fmt.(*pp).doPrintf()
      /opt/homebrew/Cellar/go/1.18/libexec/src/fmt/print.go:1026 +0x348
  fmt.Sprintf()
      /opt/homebrew/Cellar/go/1.18/libexec/src/fmt/print.go:219 +0x54
  github.com/stretchr/testify/mock.callString()
      /Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/testify@v1.7.1/mock/mock.go:362 +0x240
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/testify@v1.7.1/mock/mock.go:407 +0xa0
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/testify@v1.7.1/mock/mock.go:391 +0x140
  mygo/mockrace/m/v2.TestContextRace()
      /Users/dominovaldano/go-arm64/pkg/mod/mygo/mockrace/mockrace_test.go:234 +0x2a8
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1439 +0x18c
  testing.(*T).Run.func1()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1486 +0x44

Previous write at 0x00c00016eb58 by goroutine 8:
  ??()
      -:0 +0x104707fb8
  sync/atomic.StorePointer()
      /opt/homebrew/Cellar/go/1.18/libexec/src/runtime/atomic_pointer.go:51 +0x3c
  context.(*cancelCtx).Done()
      /opt/homebrew/Cellar/go/1.18/libexec/src/context/context.go:368 +0xe8
  mygo/mockrace/m/v2.TestContextRace.func1()
      /Users/dominovaldano/go-arm64/pkg/mod/mygo/mockrace/mockrace_test.go:230 +0x40

Goroutine 7 (running) created at:
  testing.(*T).Run()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1486 +0x560
  testing.runTests.func1()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1839 +0x94
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1439 +0x18c
  testing.runTests()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1837 +0x6c8
  testing.(*M).Run()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1719 +0x878
  main.main()
      _testmain.go:59 +0x2fc

Goroutine 8 (running) created at:
  mygo/mockrace/m/v2.TestContextRace()
      /Users/dominovaldano/go-arm64/pkg/mod/mygo/mockrace/mockrace_test.go:229 +0x190
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1439 +0x18c
  testing.(*T).Run.func1()
      /opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1486 +0x44
==================
--- FAIL: TestContextRace (0.00s)
    testing.go:1312: race detected during execution of test
panic: 
assert: mock: The method has been called over 1 times.
	Either do one more Mock.On("TestContextRace").Return(...), or remove extra call.
	This call was unexpected:
		TestContextRace(*context.cancelCtx)
		0: &context.cancelCtx{Context:(*context.emptyCtx)(0xc00011e018), mu:sync.Mutex{state:0, sema:0x0}, done:atomic.Value{v:(chan struct {})(0xc000096000)}, children:map[context.canceler]struct {}(nil), err:error(nil)}
	at: [mockrace_test.go:234] [recovered]
	panic: 
assert: mock: The method has been called over 1 times.
	Either do one more Mock.On("TestContextRace").Return(...), or remove extra call.
	This call was unexpected:
		TestContextRace(*context.cancelCtx)
		0: &context.cancelCtx{Context:(*context.emptyCtx)(0xc00011e018), mu:sync.Mutex{state:0, sema:0x0}, done:atomic.Value{v:(chan struct {})(0xc000096000)}, children:map[context.canceler]struct {}(nil), err:error(nil)}
	at: [mockrace_test.go:234]

goroutine 19 [running]:
testing.tRunner.func1.2({0x104b3dd20, 0xc0001132b0})
	/opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1389 +0x278
testing.tRunner.func1()
	/opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1392 +0x420
panic({0x104b3dd20, 0xc0001132b0})
	/opt/homebrew/Cellar/go/1.18/libexec/src/runtime/panic.go:844 +0x258
github.com/stretchr/testify/mock.(*Mock).fail(0xc000100500, {0x104a849cb, 0xa5}, {0xc00016ecc0, 0x4, 0x4})
	/Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/testify@v1.7.1/mock/mock.go:262 +0x140
github.com/stretchr/testify/mock.(*Mock).MethodCalled(0xc000100500, {0x104bebed1, 0xf}, {0xc000113190, 0x1, 0x1})
	/Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/testify@v1.7.1/mock/mock.go:407 +0x264
github.com/stretchr/testify/mock.(*Mock).Called(0x104ba6d78?, {0xc000113190, 0x1, 0x1})
	/Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/testify@v1.7.1/mock/mock.go:391 +0x144
mygo/mockrace/m/v2.TestContextRace(0x0?)
	/Users/dominovaldano/go-arm64/pkg/mod/mygo/mockrace/mockrace_test.go:234 +0x2ac
testing.tRunner(0xc000107860, 0x104ba2b18)
	/opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1439 +0x190
created by testing.(*T).Run
	/opt/homebrew/Cellar/go/1.18/libexec/src/testing/testing.go:1486 +0x564
exit status 2
FAIL	mygo/mockrace/m/v2	0.301s

There is no race on the first call in Diff() because it uses Sprintf("%v", arg) to print the differences, which calls Context.String(). It does detect a race on the second call in callString() which uses Sprintf("%#v"), because it's looking for Context.GoString() which does not exist... causing it to fall back on using recursive reflection to print everything.

bhcleek and others added 2 commits August 21, 2018 12:07

add a test to demonstrate an interesting race condition

43ab038

Fix stretchr#625 Diff race condition

365386c

bhcleek mentioned this pull request Aug 29, 2018

race condition on master in mock #625

Closed

georgelesica-wf added bug input needed labels Jan 10, 2019

georgelesica-wf added this to the Next Release milestone Jan 10, 2019

georgelesica-wf modified the milestones: v1.4.0 Release, Next Release Aug 12, 2019

sjames-iberis mentioned this pull request Sep 3, 2019

Refactor Diff to reduce risk of triggering race conditions. #812

Open

Merge branch 'master' into fix-diff-race

1799b11

glesica previously approved these changes Feb 7, 2020

View reviewed changes

boyan-soubachov modified the milestones: v1.6.0, v1.7.0 May 29, 2020

jmdacruz reviewed Aug 18, 2020

View reviewed changes

mock/mock.go Outdated Show resolved Hide resolved

Update mock.go

735d9e5

Print "FAIL" upon failure, not "PASS"

gz-c dismissed glesica’s stale review via 735d9e5 September 4, 2020 09:15

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix race in Diff printer #654

Fix race in Diff printer #654

Uh oh!

gz-c commented Aug 28, 2018

Uh oh!

gz-c commented Aug 29, 2018

Uh oh!

dcu commented Sep 12, 2018

Uh oh!

dcu commented Jan 9, 2019

Uh oh!

georgelesica-wf commented Jan 10, 2019

Uh oh!

dcu commented Jan 11, 2019

Uh oh!

georgelesica-wf commented Jan 11, 2019 •

edited

Loading

Uh oh!

bhcleek commented Jan 11, 2019 •

edited

Loading

Uh oh!

glesica left a comment

Uh oh!

Uh oh!

gz-c commented Sep 4, 2020

Uh oh!

reductionista commented Apr 10, 2022 •

edited

Loading

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

8 participants

Fix race in Diff printer #654

Are you sure you want to change the base?

Fix race in Diff printer #654

Uh oh!

Conversation

gz-c commented Aug 28, 2018

Uh oh!

gz-c commented Aug 29, 2018

Uh oh!

dcu commented Sep 12, 2018

Uh oh!

dcu commented Jan 9, 2019

Uh oh!

georgelesica-wf commented Jan 10, 2019

Uh oh!

dcu commented Jan 11, 2019

Uh oh!

georgelesica-wf commented Jan 11, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

bhcleek commented Jan 11, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

glesica left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

gz-c commented Sep 4, 2020

Uh oh!

reductionista commented Apr 10, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

8 participants

georgelesica-wf commented Jan 11, 2019 •

edited

Loading

bhcleek commented Jan 11, 2019 •

edited

Loading

reductionista commented Apr 10, 2022 •

edited

Loading