Workaround race condition in printing of diff values. #1229

dokterbob · 2022-07-14T12:37:58Z

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/sync@v0.0.0-20210220032951-036812b2e83c/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/sync@v0.0.0-20210220032951-036812b2e83c/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/sync@v0.0.0-20210220032951-036812b2e83c/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/sync@v0.0.0-20210220032951-036812b2e83c/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 6241f9a.

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

Ref: stretchr/testify#1229

devosnw · 2022-08-12T18:48:14Z

+1 to this PR. I'm pretty sure I just ran into this today

palkan · 2023-03-28T16:39:06Z

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

dokterbob · 2023-04-25T15:46:18Z

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

dokterbob · 2023-04-25T15:54:21Z

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 82be843. I am not 100% sure it's correct, I discovered I had it lying around and never pushed it.

Caused by issue described in stretchr/testify#1229. The workaround here is to close out the session in the same goroutine as handleNewConnection. This actually simplifies the code by reducing the # of goroutines per connection by 1 and allowing the unit tests to synchronize without a waitgroup.

petergardfjall · 2024-05-14T07:24:47Z

I created an issue (#1597) related to this PR and opened a new PR (#1598) that is heavily inspired by this PR.

I decided to open a new PR since the progress on this PR appears to have stalled.

dolmen · 2024-05-16T11:50:34Z

Closing because replaced by #1598.

dokterbob added a commit to ipfs-search/ipfs-search that referenced this pull request Jul 14, 2022

Replace testify with workaround version.

b65cffd

Ref: stretchr/testify#1229

dokterbob added a commit to ipfs-search/ipfs-search that referenced this pull request Jul 14, 2022

Replace testify with workaround version.

e6b3207

Ref: stretchr/testify#1229

dokterbob mentioned this pull request Oct 6, 2022

Test with removal of testify replacement ipfs-search/ipfs-search#235

Open

dokterbob marked this pull request as ready for review April 25, 2023 15:42

dokterbob added 2 commits April 25, 2023 16:45

Fix race condition in printing of diff values.

1cfa497

Test to validate fix for racy concurrent value access in MethodCalled().

82be843

dokterbob force-pushed the fix_race_condition branch from 9ebebef to 82be843 Compare April 25, 2023 15:45

dolmen added bug pkg-assert Change related to package testify/assert help wanted labels Oct 31, 2023

This was referenced May 14, 2024

mock: Diff is prone to data races #1597

Open

mock: avoid data races in Arguments.Diff #1598

Open

dolmen added pkg-mock Any issues related to Mock and removed pkg-assert Change related to package testify/assert labels May 16, 2024

dolmen closed this May 16, 2024

dolmen removed the help wanted label May 16, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Workaround race condition in printing of diff values. #1229

Workaround race condition in printing of diff values. #1229

dokterbob commented Jul 14, 2022

devosnw commented Aug 12, 2022

palkan commented Mar 28, 2023

dokterbob commented Apr 25, 2023

dokterbob commented Apr 25, 2023

petergardfjall commented May 14, 2024 •

edited

dolmen commented May 16, 2024

Workaround race condition in printing of diff values. #1229

Workaround race condition in printing of diff values. #1229

Conversation

dokterbob commented Jul 14, 2022

Summary

Example output

Relevant code

Changes

Motivation

Related issues

devosnw commented Aug 12, 2022

palkan commented Mar 28, 2023

dokterbob commented Apr 25, 2023

dokterbob commented Apr 25, 2023

petergardfjall commented May 14, 2024 • edited

dolmen commented May 16, 2024

petergardfjall commented May 14, 2024 •

edited