testify icon indicating copy to clipboard operation
testify copied to clipboard
verified publisher icon stretchr

Fix race in Diff printer

Open gz-c opened this issue 7 years ago • 9 comments

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 avatar Aug 28 '18 07:08 gz-c

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.

gz-c avatar Aug 29 '18 03:08 gz-c

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 avatar Sep 12 '18 23:09 dcu

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

dcu avatar Jan 09 '19 16:01 dcu

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?

georgelesica-wf avatar Jan 10 '19 21:01 georgelesica-wf

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

dcu avatar Jan 11 '19 18:01 dcu 

$ 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

georgelesica-wf avatar Jan 11 '19 20:01 georgelesica-wf

@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:
...

bhcleek avatar Jan 11 '19 20:01 bhcleek

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.

gz-c avatar Sep 04 '20 09:09 gz-c

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/[email protected]/mock/mock.go:362 +0x240
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:407 +0xa0
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/[email protected]/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/[email protected]/mock/mock.go:362 +0x240
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/[email protected]/mock/mock.go:407 +0xa0
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/dominovaldano/go-arm64/pkg/mod/github.com/stretchr/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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.

reductionista avatar Apr 10 '22 21:04 reductionista