Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Fix data races by removing unguarded goroutines; run mod tidy #16

Closed
wants to merge 2 commits into from
Closed

Fix data races by removing unguarded goroutines; run mod tidy #16

wants to merge 2 commits into from

Conversation

markphelps
Copy link

@markphelps markphelps commented Dec 7, 2019 •
edited

Fixes #15

  • Remove goroutines that are causing data races
  • Also ran go mod tidy to remove unneeded modules

Before

$ go test -v -race ./...

...
==================
WARNING: DATA RACE
Read at 0x00c00014a9c8 by goroutine 58:
  reflect.typedmemmove()
      /usr/local/Cellar/go/1.13.4/libexec/src/runtime/mbarrier.go:177 +0x0
  reflect.packEface()
      /usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:119 +0x103
  reflect.valueInterface()
      /usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:1033 +0x16f
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:1003 +0x38f7
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:880 +0x25da
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:716 +0x2ee
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:1126 +0x912
  fmt.Sprintf()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:219 +0x73
  github.com/stretchr/testify/mock.Arguments.Diff()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:687 +0xf1a
  github.com/stretchr/testify/mock.(*Mock).findExpectedCall()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:269 +0x16a
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:348 +0xb3
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:338 +0x1e4
  github.com/eko/gocache/test/mocks/metrics.(*MetricsInterface).RecordFromCodec()
      /Users/markphelps/workspace/gocache/test/mocks/metrics/metrics_interface.go:21 +0xaa

Previous write at 0x00c00014a9c8 by goroutine 57:
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:385 +0x7b6
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:338 +0x1e4
  github.com/eko/gocache/test/mocks/codec.(*CodecInterface).GetStore()
      /Users/markphelps/workspace/gocache/test/mocks/codec/codec_interface.go:83 +0x63
  github.com/eko/gocache/cache.(*ChainCache).setUntil()
      /Users/markphelps/workspace/gocache/cache/chain.go:90 +0x13b

Goroutine 58 (running) created at:
  github.com/eko/gocache/cache.(*MetricCache).updateMetrics()
      /Users/markphelps/workspace/gocache/cache/metric.go:65 +0x1bd
  github.com/eko/gocache/cache.(*MetricCache).updateMetrics()
      /Users/markphelps/workspace/gocache/cache/metric.go:61 +0xff
  github.com/eko/gocache/cache.(*MetricCache).Get()
      /Users/markphelps/workspace/gocache/cache/metric.go:31 +0xcb
  github.com/eko/gocache/cache.TestMetricGetWhenChainCache()
      /Users/markphelps/workspace/gocache/cache/metric_test.go:83 +0x714
  testing.tRunner()
      /usr/local/Cellar/go/1.13.4/libexec/src/testing/testing.go:909 +0x199

Goroutine 57 (finished) created at:
  github.com/eko/gocache/cache.(*ChainCache).Get()
      /Users/markphelps/workspace/gocache/cache/chain.go:37 +0x383
  github.com/eko/gocache/cache.(*MetricCache).Get()
      /Users/markphelps/workspace/gocache/cache/metric.go:29 +0x75
  github.com/eko/gocache/cache.TestMetricGetWhenChainCache()
      /Users/markphelps/workspace/gocache/cache/metric_test.go:83 +0x714
  testing.tRunner()
      /usr/local/Cellar/go/1.13.4/libexec/src/testing/testing.go:909 +0x199
==================
==================
WARNING: DATA RACE
Read at 0x00c00014a9f8 by goroutine 58:
  reflect.typedmemmove()
      /usr/local/Cellar/go/1.13.4/libexec/src/runtime/mbarrier.go:177 +0x0
--- FAIL: TestMetricSet (0.00s)
  reflect.packEface()
      /usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:119 +0x103
    testing.go:853: race detected during execution of test
  reflect.valueInterface()
      /usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:1033 +0x16f
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:1003 +0x38f7
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:880 +0x25da
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:716 +0x2ee
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:1126 +0x912
  fmt.Sprintf()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:219 +0x73
  github.com/stretchr/testify/mock.Arguments.Diff()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:687 +0xf1a
  github.com/stretchr/testify/mock.(*Mock).findExpectedCall()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:269 +0x16a
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:348 +0xb3
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:338 +0x1e4
  github.com/eko/gocache/test/mocks/metrics.(*MetricsInterface).RecordFromCodec()
      /Users/markphelps/workspace/gocache/test/mocks/metrics/metrics_interface.go:21 +0xaa

Previous write at 0x00c00014a9f8 by goroutine 57:
  sync/atomic.AddInt32()
      /usr/local/Cellar/go/1.13.4/libexec/src/runtime/race_amd64.s:269 +0xb
  sync.(*Mutex).Unlock()
      /usr/local/Cellar/go/1.13.4/libexec/src/sync/mutex.go:186 +0x51
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:405 +0x921
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:338 +0x1e4
  github.com/eko/gocache/test/mocks/codec.(*CodecInterface).GetStore()
      /Users/markphelps/workspace/gocache/test/mocks/codec/codec_interface.go:83 +0x63
  github.com/eko/gocache/cache.(*ChainCache).setUntil()
      /Users/markphelps/workspace/gocache/cache/chain.go:90 +0x13b

Goroutine 58 (running) created at:
  github.com/eko/gocache/cache.(*MetricCache).updateMetrics()
      /Users/markphelps/workspace/gocache/cache/metric.go:65 +0x1bd
  github.com/eko/gocache/cache.(*MetricCache).updateMetrics()
      /Users/markphelps/workspace/gocache/cache/metric.go:61 +0xff
  github.com/eko/gocache/cache.(*MetricCache).Get()
      /Users/markphelps/workspace/gocache/cache/metric.go:31 +0xcb
  github.com/eko/gocache/cache.TestMetricGetWhenChainCache()
      /Users/markphelps/workspace/gocache/cache/metric_test.go:83 +0x714
  testing.tRunner()
      /usr/local/Cellar/go/1.13.4/libexec/src/testing/testing.go:909 +0x199
=== RUN   TestMetricDelete

Goroutine 57 (finished) created at:
  github.com/eko/gocache/cache.(*ChainCache).Get()
      /Users/markphelps/workspace/gocache/cache/chain.go:37 +0x383
  github.com/eko/gocache/cache.(*MetricCache).Get()
      /Users/markphelps/workspace/gocache/cache/metric.go:29 +0x75
  github.com/eko/gocache/cache.TestMetricGetWhenChainCache()
      /Users/markphelps/workspace/gocache/cache/metric_test.go:83 +0x714
  testing.tRunner()
      /usr/local/Cellar/go/1.13.4/libexec/src/testing/testing.go:909 +0x199
==================
==================
WARNING: DATA RACE
Read at 0x00c0001f6870 by goroutine 58:
  reflect.typedmemmove()
      /usr/local/Cellar/go/1.13.4/libexec/src/runtime/mbarrier.go:177 +0x0
  reflect.packEface()
      /usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:119 +0x103
  reflect.valueInterface()
      /usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:1033 +0x16f
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:1003 +0x38f7
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:869 +0xec7
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:810 +0x283f
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:810 +0x283f
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:880 +0x25da
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:716 +0x2ee
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:1126 +0x912
  fmt.Sprintf()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:219 +0x73
  github.com/stretchr/testify/mock.Arguments.Diff()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:687 +0xf1a
  github.com/stretchr/testify/mock.(*Mock).findExpectedCall()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:269 +0x16a
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:348 +0xb3
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:338 +0x1e4
  github.com/eko/gocache/test/mocks/metrics.(*MetricsInterface).RecordFromCodec()
      /Users/markphelps/workspace/gocache/test/mocks/metrics/metrics_interface.go:21 +0xaa

Previous write at 0x00c0001f6870 by goroutine 57:
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:385 +0x775
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:338 +0x1e4
  github.com/eko/gocache/test/mocks/codec.(*CodecInterface).GetStore()
      /Users/markphelps/workspace/gocache/test/mocks/codec/codec_interface.go:83 +0x63
  github.com/eko/gocache/cache.(*ChainCache).setUntil()
      /Users/markphelps/workspace/gocache/cache/chain.go:90 +0x13b

Goroutine 58 (running) created at:
  github.com/eko/gocache/cache.(*MetricCache).updateMetrics()
      /Users/markphelps/workspace/gocache/cache/metric.go:65 +0x1bd
  github.com/eko/gocache/cache.(*MetricCache).updateMetrics()
      /Users/markphelps/workspace/gocache/cache/metric.go:61 +0xff
  github.com/eko/gocache/cache.(*MetricCache).Get()
      /Users/markphelps/workspace/gocache/cache/metric.go:31 +0xcb
  github.com/eko/gocache/cache.TestMetricGetWhenChainCache()
      /Users/markphelps/workspace/gocache/cache/metric_test.go:83 +0x714
  testing.tRunner()
      /usr/local/Cellar/go/1.13.4/libexec/src/testing/testing.go:909 +0x199

Goroutine 57 (finished) created at:
  github.com/eko/gocache/cache.(*ChainCache).Get()
      /Users/markphelps/workspace/gocache/cache/chain.go:37 +0x383
  github.com/eko/gocache/cache.(*MetricCache).Get()
      /Users/markphelps/workspace/gocache/cache/metric.go:29 +0x75
  github.com/eko/gocache/cache.TestMetricGetWhenChainCache()
      /Users/markphelps/workspace/gocache/cache/metric_test.go:83 +0x714
  testing.tRunner()
      /usr/local/Cellar/go/1.13.4/libexec/src/testing/testing.go:909 +0x199
==================
--- FAIL: TestMetricDelete (0.00s)
    testing.go:853: race detected during execution of test
=== RUN   TestMetricDeleteWhenError
--- PASS: TestMetricDeleteWhenError (0.00s)
=== RUN   TestMetricInvalidate
==================
WARNING: DATA RACE
Read at 0x00c0002dcba0 by goroutine 58:
  reflect.Value.String()
      /usr/local/Cellar/go/1.13.4/libexec/src/reflect/value.go:1845 +0x5d
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:761 +0x3156
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:869 +0xec7
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:810 +0x283f
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:869 +0xec7
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:810 +0x283f
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:810 +0x283f
  fmt.(*pp).printValue()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:880 +0x25da
  fmt.(*pp).printArg()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:716 +0x2ee
  fmt.(*pp).doPrintf()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:1126 +0x912
  fmt.Sprintf()
      /usr/local/Cellar/go/1.13.4/libexec/src/fmt/print.go:219 +0x73
  github.com/stretchr/testify/mock.Arguments.Diff()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:687 +0xf1a
  github.com/stretchr/testify/mock.(*Mock).findExpectedCall()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:269 +0x16a
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:348 +0xb3
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:338 +0x1e4
  github.com/eko/gocache/test/mocks/metrics.(*MetricsInterface).RecordFromCodec()
      /Users/markphelps/workspace/gocache/test/mocks/metrics/metrics_interface.go:21 +0xaa

Previous write at 0x00c0002dcba0 by goroutine 57:
  github.com/stretchr/testify/assert.CallerInfo()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/assert/assertions.go:146 +0x3c3
  github.com/stretchr/testify/mock.(*Mock).MethodCalled()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:385 +0x57e
  github.com/stretchr/testify/mock.(*Mock).Called()
      /Users/markphelps/go/pkg/mod/github.com/stretchr/testify@v1.4.0/mock/mock.go:338 +0x1e4
  github.com/eko/gocache/test/mocks/codec.(*CodecInterface).GetStore()
      /Users/markphelps/workspace/gocache/test/mocks/codec/codec_interface.go:83 +0x63
  github.com/eko/gocache/cache.(*ChainCache).setUntil()
      /Users/markphelps/workspace/gocache/cache/chain.go:90 +0x13b

Goroutine 58 (running) created at:
  github.com/eko/gocache/cache.(*MetricCache).updateMetrics()
      /Users/markphelps/workspace/gocache/cache/metric.go:65 +0x1bd
  github.com/eko/gocache/cache.(*MetricCache).updateMetrics()
      /Users/markphelps/workspace/gocache/cache/metric.go:61 +0xff
  github.com/eko/gocache/cache.(*MetricCache).Get()
      /Users/markphelps/workspace/gocache/cache/metric.go:31 +0xcb
  github.com/eko/gocache/cache.TestMetricGetWhenChainCache()
      /Users/markphelps/workspace/gocache/cache/metric_test.go:83 +0x714
  testing.tRunner()
      /usr/local/Cellar/go/1.13.4/libexec/src/testing/testing.go:909 +0x199

Goroutine 57 (finished) created at:
  github.com/eko/gocache/cache.(*ChainCache).Get()
      /Users/markphelps/workspace/gocache/cache/chain.go:37 +0x383
  github.com/eko/gocache/cache.(*MetricCache).Get()
      /Users/markphelps/workspace/gocache/cache/metric.go:29 +0x75
  github.com/eko/gocache/cache.TestMetricGetWhenChainCache()
      /Users/markphelps/workspace/gocache/cache/metric_test.go:83 +0x714
  testing.tRunner()
      /usr/local/Cellar/go/1.13.4/libexec/src/testing/testing.go:909 +0x199
==================
--- FAIL: TestMetricInvalidate (0.00s)
    testing.go:853: race detected during execution of test
...
FAIL

After

$ go test -v -race ./...

...
=== RUN   TestRistrettoGetType
--- PASS: TestRistrettoGetType (0.00s)
PASS
ok      github.com/eko/gocache/store    (cached)
?       github.com/eko/gocache/test/mocks/cache [no test files]
?       github.com/eko/gocache/test/mocks/codec [no test files]
?       github.com/eko/gocache/test/mocks/metrics       [no test files]
?       github.com/eko/gocache/test/mocks/store [no test files]
?       github.com/eko/gocache/test/mocks/store/clients [no test files]

@codecov
Copy link

codecov bot commented Dec 7, 2019 •
edited

Codecov Report

Merging #16 into master will not change coverage.
The diff coverage is 100%.

Impacted file tree graph

@@           Coverage Diff           @@
##           master      #16   +/-   ##
=======================================
  Coverage   94.77%   94.77%           
=======================================
  Files          13       13           
  Lines         459      459           
=======================================
  Hits          435      435           
  Misses         13       13           
  Partials       11       11
Impacted Files Coverage Δ
cache/metric.go 100% <100%> (ø) ⬆️
cache/chain.go 100% <100%> (ø) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 1b6c810...75e0f75. Read the comment docs.

@eko
Copy link
Owner

eko commented Dec 7, 2019

Hi @markphelps,

Thank you for your work on this issue. It seems we were both working on fixing this today ;)

I was working on replacing mockery (which seems to be not maintained anymore) with gomock which looks more official library for mocking in Go.

Also, I think that when we send some metrics, it should be done asynchronously in order to avoid impacting process time. Have you seens some weird issues using these goroutines anywhere other than in the unit tests?

You can take a look at the following pull request: #17

I've used sync.WaitGroup to fix these goroutine issues in tests, see for example: https://github.com/eko/gocache/pull/17/files#diff-b9e09a12a71ec9a915f43aa0eb7cc7c0R78

Thank you for your help and your answers!

@markphelps
Copy link
Author

Hi @eko , that makes sense, however I wonder if there is still a race condition when running in the 'real world'. For example:

This goroutine is kicked off:

gocache/cache/metric.go

Line 65 in 1b6c810

go c.metrics.RecordFromCodec(current.GetCodec())

Which passes the result ofcurrent.GetCodec() to:

gocache/metrics/prometheus.go

Line 46 in 1b6c810

func (m *Prometheus) RecordFromCodec(codec codec.CodecInterface) {

I believe this could lead to a race since two goroutines could modify the same value if run concurrently.

I think if you wanted to maintain the async nature of updating metrics, then it would be better if RecordFromCodec accepted a channel like code.CodecInterface chan in a fan-in approach so that Codec's were processed sequentially and in a threadsafe manner.

I think setUntil has a similar problem:

gocache/cache/chain.go

Line 88 in 1b6c810

func (c *ChainCache) setUntil(key, object interface{}, until *string) {

@eko
Copy link
Owner

eko commented Dec 8, 2019

Hi @markphelps,

You're right, I just updated the PR to take use a channel for the different cases which avoid creating X goroutines depending on cache hits, there is now just a single goroutine in the ChainCache, LoadableCache and another in the metrics that listen for a channel and do things when a new message is pushed on the associated channel.

I will close this PR as I would also like to benefit from the move from mockery to gomock but thank you so much for your work and your help on this subject!

@eko eko closed this Dec 8, 2019
@markphelps markphelps deleted the fix-data-races branch December 8, 2019 18:32
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

Data Races when running tests with race detector
2 participants
@markphelps @eko