testify
testify copied to clipboard
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
+1 to this PR. I'm pretty sure I just ran into this today
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.