testify
testify copied to clipboard
stretchr
Workaround race condition in printing of diff values.
Summary
When a pointer argument is used in Run() and this object is modified in an asynchronous fashion, the evaluation of %v in Arguments.Diff causes a race condition.
Example output
==================
WARNING: DATA RACE
Write at 0x00c000161a80 by goroutine 9:
github.com/ipfs-search/ipfs-search/components/crawler.(*CrawlerTestSuite).TestCrawlAddReference.func1()
/Users/drbob/Development/ipfs-search/components/crawler/crawler_test.go:1040 +0x108
github.com/stretchr/testify/mock.(*Mock).MethodCalled()
/Users/drbob/Development/testify/mock/mock.go:538 +0x118e
github.com/stretchr/testify/mock.(*Mock).MethodCalled()
/Users/drbob/Development/testify/mock/mock.go:460 +0xb9
github.com/stretchr/testify/mock.(*Mock).Called()
/Users/drbob/Development/testify/mock/mock.go:450 +0x1a4
github.com/ipfs-search/ipfs-search/components/index.(*Mock).Get()
/Users/drbob/Development/ipfs-search/components/index/mock.go:27 +0x1f3
github.com/ipfs-search/ipfs-search/components/index.MultiGet.func1()
/Users/drbob/Development/ipfs-search/components/index/multiget.go:25 +0x121
golang.org/x/sync/errgroup.(*Group).Go.func1()
/Users/drbob/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57 +0x91
Previous read at 0x00c000161a80 by goroutine 11:
reflect.packEface()
/usr/local/Cellar/go/1.18.2/libexec/src/reflect/value.go:130 +0xfd
reflect.valueInterface()
/usr/local/Cellar/go/1.18.2/libexec/src/reflect/value.go:1460 +0x188
reflect.Value.Interface()
/usr/local/Cellar/go/1.18.2/libexec/src/reflect/value.go:1430 +0xc9
fmt.(*pp).printValue()
/usr/local/Cellar/go/1.18.2/libexec/src/fmt/print.go:722 +0xca
fmt.(*pp).printValue()
/usr/local/Cellar/go/1.18.2/libexec/src/fmt/print.go:806 +0x1c92
fmt.(*pp).printValue()
/usr/local/Cellar/go/1.18.2/libexec/src/fmt/print.go:876 +0x12be
fmt.(*pp).printArg()
/usr/local/Cellar/go/1.18.2/libexec/src/fmt/print.go:712 +0xdf4
fmt.(*pp).doPrintf()
/usr/local/Cellar/go/1.18.2/libexec/src/fmt/print.go:1026 +0x48f
fmt.Sprintf()
/usr/local/Cellar/go/1.18.2/libexec/src/fmt/print.go:219 +0x67
github.com/stretchr/testify/mock.Arguments.Diff()
/Users/drbob/Development/testify/mock/mock.go:883 +0x18e
github.com/stretchr/testify/mock.(*Mock).findExpectedCall()
/Users/drbob/Development/testify/mock/mock.go:355 +0x144
github.com/stretchr/testify/mock.(*Mock).MethodCalled()
/Users/drbob/Development/testify/mock/mock.go:460 +0xb9
github.com/stretchr/testify/mock.(*Mock).Called()
/Users/drbob/Development/testify/mock/mock.go:450 +0x1a4
github.com/ipfs-search/ipfs-search/components/index.(*Mock).Get()
/Users/drbob/Development/ipfs-search/components/index/mock.go:27 +0x1f3
github.com/ipfs-search/ipfs-search/components/index.MultiGet.func1()
/Users/drbob/Development/ipfs-search/components/index/multiget.go:25 +0x121
golang.org/x/sync/errgroup.(*Group).Go.func1()
/Users/drbob/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:57 +0x91
Goroutine 9 (running) created at:
golang.org/x/sync/errgroup.(*Group).Go()
/Users/drbob/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:54 +0xee
github.com/ipfs-search/ipfs-search/components/index.MultiGet()
/Users/drbob/Development/ipfs-search/components/index/multiget.go:22 +0x5a4
github.com/ipfs-search/ipfs-search/components/crawler.(*Crawler).getExistingItem()
/Users/drbob/Development/ipfs-search/components/crawler/existingitem.go:22 +0x2e4
github.com/ipfs-search/ipfs-search/components/crawler.(*Crawler).updateMaybeExisting()
/Users/drbob/Development/ipfs-search/components/crawler/update.go:142 +0x16c
github.com/ipfs-search/ipfs-search/components/crawler.(*Crawler).Crawl()
/Users/drbob/Development/ipfs-search/components/crawler/crawler.go:60 +0x3e5
github.com/ipfs-search/ipfs-search/components/crawler.(*CrawlerTestSuite).TestCrawlAddReference()
/Users/drbob/Development/ipfs-search/components/crawler/crawler_test.go:1083 +0x1187
runtime.call16()
/usr/local/Cellar/go/1.18.2/libexec/src/runtime/asm_amd64.s:701 +0x48
reflect.Value.Call()
/usr/local/Cellar/go/1.18.2/libexec/src/reflect/value.go:339 +0xd7
github.com/stretchr/testify/suite.Run.func1()
/Users/drbob/Development/testify/suite/suite.go:175 +0x6dc
testing.tRunner()
/usr/local/Cellar/go/1.18.2/libexec/src/testing/testing.go:1439 +0x213
testing.(*T).Run.func1()
/usr/local/Cellar/go/1.18.2/libexec/src/testing/testing.go:1486 +0x47
Goroutine 11 (finished) created at:
golang.org/x/sync/errgroup.(*Group).Go()
/Users/drbob/go/pkg/mod/golang.org/x/[email protected]/errgroup/errgroup.go:54 +0xee
github.com/ipfs-search/ipfs-search/components/index.MultiGet()
/Users/drbob/Development/ipfs-search/components/index/multiget.go:22 +0x5a4
github.com/ipfs-search/ipfs-search/components/crawler.(*Crawler).getExistingItem()
/Users/drbob/Development/ipfs-search/components/crawler/existingitem.go:22 +0x2e4
github.com/ipfs-search/ipfs-search/components/crawler.(*Crawler).updateMaybeExisting()
/Users/drbob/Development/ipfs-search/components/crawler/update.go:142 +0x16c
github.com/ipfs-search/ipfs-search/components/crawler.(*Crawler).Crawl()
/Users/drbob/Development/ipfs-search/components/crawler/crawler.go:60 +0x3e5
github.com/ipfs-search/ipfs-search/components/crawler.(*CrawlerTestSuite).TestCrawlAddReference()
/Users/drbob/Development/ipfs-search/components/crawler/crawler_test.go:1083 +0x1187
runtime.call16()
/usr/local/Cellar/go/1.18.2/libexec/src/runtime/asm_amd64.s:701 +0x48
reflect.Value.Call()
/usr/local/Cellar/go/1.18.2/libexec/src/reflect/value.go:339 +0xd7
github.com/stretchr/testify/suite.Run.func1()
/Users/drbob/Development/testify/suite/suite.go:175 +0x6dc
testing.tRunner()
/usr/local/Cellar/go/1.18.2/libexec/src/testing/testing.go:1439 +0x213
testing.(*T).Run.func1()
/usr/local/Cellar/go/1.18.2/libexec/src/testing/testing.go:1486 +0x47
==================
Relevant code
s.fileIdx.
On("Get", mock.Anything, r.Resource.ID, mock.Anything, []string{"references", "last-seen"}).
Run(func(args mock.Arguments) {
u := args.Get(2).(*indexTypes.Update)
lastSeen := time.Now()
u.LastSeen = &lastSeen
u.References = indexTypes.References{
indexTypes.Reference{
ParentHash: "Qmc8mmzycvXnzgwBHokZQd97iWAmtdFMqX4FZUAQ5AQdQi",
Name: "ExistingReference.pdf",
},
}
}).
Return(true, nil).
Once()
https://github.com/ipfs-search/ipfs-search/blob/fix_race_condition/components/crawler/crawler_test.go#L1040
Changes
Replaced %v by %p, inspired by https://github.com/stretchr/testify/commit/6241f9ab994219cafb009b160a20acf4a62063aa.
Motivation
We need to test for race conditions in our code, not the testing library. ;)
This is a workaround and should not be seen as a full fix. It is also lacking regression tests and causes existing tests to fail. Regrettably, I currently lack bandwith to provide them.
Related issues
#125
Thanks for the patch! Fixed the problem for me.
Any chance we can get this draft finished and merged? I'd be glad to help with this. /cc @dokterbob @boyan-soubachov
@palkan @boyan-soubachov @devosnw Thanks for the feedback and sorry it took quite a while.
I've rebased to master, let's see what the tests reveal.
So, this is the output I'm getting:
--- FAIL: Test_Arguments_Diff (0.00s)
mock_test.go:1631:
Error Trace: /Users/drbob/Development/testify/mock/mock_test.go:1631
Error: "\n\t0: PASS: (string=%!p(string=Hello World)) == (string=%!p(string=Hello World))\n\t1: FAIL: (int=%!p(int=456)) != (int=%!p(int=123))\n\t2: FAIL: (string=%!p(string=false)) != (bool=%!p(bool=true))\n" does not contain "(int=456) != (int=123)"
Test: Test_Arguments_Diff
mock_test.go:1632:
Error Trace: /Users/drbob/Development/testify/mock/mock_test.go:1632
Error: "\n\t0: PASS: (string=%!p(string=Hello World)) == (string=%!p(string=Hello World))\n\t1: FAIL: (int=%!p(int=456)) != (int=%!p(int=123))\n\t2: FAIL: (string=%!p(string=false)) != (bool=%!p(bool=true))\n" does not contain "(string=false) != (bool=true)"
Test: Test_Arguments_Diff
--- FAIL: Test_Arguments_Diff_DifferentNumberOfArgs (0.00s)
mock_test.go:1644:
Error Trace: /Users/drbob/Development/testify/mock/mock_test.go:1644
Error: "\n\t0: PASS: (string=%!p(string=string)) == (string=%!p(string=string))\n\t1: FAIL: (int=%!p(int=456)) != (int=%!p(int=123))\n\t2: FAIL: (string=%!p(string=false)) != (bool=%!p(bool=true))\n\t3: FAIL: (string=%!p(string=extra)) != (Missing)\n" does not contain "(string=extra) != (Missing)"
Test: Test_Arguments_Diff_DifferentNumberOfArgs
--- FAIL: Test_Arguments_Diff_WithAnythingOfTypeArgument_Failing (0.00s)
mock_test.go:1686:
Error Trace: /Users/drbob/Development/testify/mock/mock_test.go:1686
Error: "\n\t0: PASS: (string=%!p(string=string)) == (string=%!p(string=string))\n\t1: FAIL: type string != type int - (int=%!p(int=123))\n\t2: PASS: (bool=%!p(bool=true)) == (bool=%!p(bool=true))\n" does not contain "string != type int - (int=123)"
Test: Test_Arguments_Diff_WithAnythingOfTypeArgument_Failing
--- FAIL: Test_Arguments_Diff_WithIsTypeArgument_Failing (0.00s)
mock_test.go:1705:
Error Trace: /Users/drbob/Development/testify/mock/mock_test.go:1705
Error: "\n\t0: PASS: (string=%!p(string=string)) == (string=%!p(string=string))\n\t1: FAIL: type string != type int - (int=%!p(int=123))\n\t2: PASS: (bool=%!p(bool=true)) == (bool=%!p(bool=true))\n" does not contain "string != type int - (int=123)"
Test: Test_Arguments_Diff_WithIsTypeArgument_Failing
--- FAIL: Test_Arguments_Diff_WithArgMatcher (0.00s)
mock_test.go:1716:
Error Trace: /Users/drbob/Development/testify/mock/mock_test.go:1716
Error: "\n\t0: PASS: (string=%!p(string=string)) == (string=%!p(string=string))\n\t1: FAIL: (int=%!p(int=124)) not matched by func(int) bool\n\t2: PASS: (bool=%!p(bool=true)) == (bool=%!p(bool=true))\n" does not contain "(int=124) not matched by func(int) bool"
Test: Test_Arguments_Diff_WithArgMatcher
mock_test.go:1720:
Error Trace: /Users/drbob/Development/testify/mock/mock_test.go:1720
Error: "\n\t0: PASS: (string=%!p(string=string)) == (string=%!p(string=string))\n\t1: FAIL: (bool=%!p(bool=false)) not matched by func(int) bool\n\t2: PASS: (bool=%!p(bool=true)) == (bool=%!p(bool=true))\n" does not contain "(bool=false) not matched by func(int) bool"
Test: Test_Arguments_Diff_WithArgMatcher
mock_test.go:1724:
Error Trace: /Users/drbob/Development/testify/mock/mock_test.go:1724
Error: "\n\t0: PASS: (string=%!p(string=string)) == (string=%!p(string=string))\n\t1: PASS: (int=%!p(int=123)) matched by func(int) bool\n\t2: FAIL: (bool=%!p(bool=false)) != (bool=%!p(bool=true))\n" does not contain "(int=123) matched by func(int) bool"
Test: Test_Arguments_Diff_WithArgMatcher
--- FAIL: TestArgumentMatcherToPrintMismatch (0.00s)
mock_test.go:1920:
Error Trace: /Users/drbob/Development/testify/mock/mock_test.go:1920
/usr/local/Cellar/go/1.20.3/libexec/src/runtime/panic.go:884
/Users/drbob/Development/testify/mock/mock_test.go:1853
/Users/drbob/Development/testify/mock/mock_test.go:1927
Error: Expect "
mock: Unexpected Method Call
-----------------------------
GetTime(int)
0: 1
The closest call I have is:
GetTime(mock.argumentMatcher)
0: mock.argumentMatcher{fn:reflect.Value{typ:(*reflect.rtype)(0x11c3fe0), ptr:(unsafe.Pointer)(0x122a310), flag:0x13}}
Diff: 0: FAIL: (int=%!p(int=1)) not matched by func(int) bool" to match "\s+mock: Unexpected Method Call\s+-*\s+GetTime\(int\)\s+0: 1\s+The closest call I have is:\s+GetTime\(mock.argumentMatcher\)\s+0: mock.argumentMatcher\{.*?\}\s+Diff:.*\(int=1\) not matched by func\(int\) bool"
Test: TestArgumentMatcherToPrintMismatch
--- FAIL: TestArgumentMatcherToPrintMismatchWithReferenceType (0.00s)
mock_test.go:1937:
Error Trace: /Users/drbob/Development/testify/mock/mock_test.go:1937
/usr/local/Cellar/go/1.20.3/libexec/src/runtime/panic.go:884
/Users/drbob/Development/testify/mock/mock_test.go:1857
/Users/drbob/Development/testify/mock/mock_test.go:1944
Error: Expect "
mock: Unexpected Method Call
-----------------------------
GetTimes([]int)
0: []int{1}
The closest call I have is:
GetTimes(mock.argumentMatcher)
0: mock.argumentMatcher{fn:reflect.Value{typ:(*reflect.rtype)(0x11c36e0), ptr:(unsafe.Pointer)(0x122a318), flag:0x13}}
Diff: 0: FAIL: ([]int=0xc00001cbf8) not matched by func([]int) bool" to match "\s+mock: Unexpected Method Call\s+-*\s+GetTimes\(\[\]int\)\s+0: \[\]int\{1\}\s+The closest call I have is:\s+GetTimes\(mock.argumentMatcher\)\s+0: mock.argumentMatcher\{.*?\}\s+Diff:.*\(\[\]int=\[1\]\) not matched by func\(\[\]int\) bool"
Test: TestArgumentMatcherToPrintMismatchWithReferenceType
--- FAIL: TestClosestCallMismatchedArgumentInformationShowsTheClosest (0.00s)
mock_test.go:1953:
Error Trace: /Users/drbob/Development/testify/mock/mock_test.go:1953
/usr/local/Cellar/go/1.20.3/libexec/src/runtime/panic.go:884
/Users/drbob/Development/testify/mock/mock_test.go:31
/Users/drbob/Development/testify/mock/mock_test.go:1961
Error: Expect "
mock: Unexpected Method Call
-----------------------------
TheExampleMethod(int,int,int)
0: 1
1: 1
2: 2
The closest call I have is:
TheExampleMethod(int,int,int)
0: 1
1: 1
2: 1
Diff: 0: PASS: (int=%!p(int=1)) == (int=%!p(int=1))
1: PASS: (int=%!p(int=1)) == (int=%!p(int=1))
2: FAIL: (int=%!p(int=2)) != (int=%!p(int=1))" to match "\s+mock: Unexpected Method Call\s+-*\s+TheExampleMethod\(int,int,int\)\s+0: 1\s+1: 1\s+2: 2\s+The closest call I have is:\s+TheExampleMethod\(int,int,int\)\s+0: 1\s+1: 1\s+2: 1\s+Diff: 0: PASS: \(int=1\) == \(int=1\)\s+1: PASS: \(int=1\) == \(int=1\)\s+2: FAIL: \(int=2\) != \(int=1\)"
Test: TestClosestCallMismatchedArgumentInformationShowsTheClosest
--- FAIL: TestClosestCallMismatchedArgumentValueInformation (0.00s)
mock_test.go:2004:
Error Trace: /Users/drbob/Development/testify/mock/mock_test.go:2004
/usr/local/Cellar/go/1.20.3/libexec/src/runtime/panic.go:884
/Users/drbob/Development/testify/mock/mock_test.go:1853
/Users/drbob/Development/testify/mock/mock_test.go:2011
Error: Expect "
mock: Unexpected Method Call
-----------------------------
GetTime(int)
0: 1
The closest call I have is:
GetTime(int)
0: 999
Diff: 0: FAIL: (int=%!p(int=1)) != (int=%!p(int=999))" to match "\s+mock: Unexpected Method Call\s+-*\s+GetTime\(int\)\s+0: 1\s+The closest call I have is:\s+GetTime\(int\)\s+0: 999\s+Diff: 0: FAIL: \(int=1\) != \(int=999\)"
Test: TestClosestCallMismatchedArgumentValueInformation
The first errors seem more a matter of aesthetics, I guess it would be possible to use a conditional there - e.g%!p(int=123)) instead of (int=123).
The latter errors really do seem to relate something functional. But I'm not into the code enough to figure out what with the limited time I have available.
If somebody feels like continuing my work to get some variant of this merged that'd be 👍🏼 as I'm basically stuck for time.
Note that I also added a regression test with https://github.com/stretchr/testify/pull/1229/commits/82be843943178f31eb7b4d8134ee53c0fa180d20. I am not 100% sure it's correct, I discovered I had it lying around and never pushed it.