Fix data race between Agent.Run() and Agent.Stop() #1625

tigrannajaryan · 2019-06-21T17:59:59Z

Which problem is this PR solving?

We had a data race with Agent.Stop() failing if called immediately
after Agent.Run() returns.

Short description of the changes

The root cause of the race was that Stop() called WaitGroup.Wait()
before Run() called WaitGroup.Add() for the first time which is
prohibited: https://golang.org/pkg/sync/#WaitGroup.Add

This change moves WaitGroup.Add() to earlier stage which guarantees
that WaitGroup.Wait() will be called after that.

Github issue: #1624

Testing done:

Added an automated test which was failing before the bug was fixed
and does not fail any more after the fix.

Also verified that make test passes.

Signed-off-by: Tigran Najaryan tigran@najaryan.net

tigrannajaryan · 2019-06-21T18:01:05Z

cmd/agent/app/processors/thrift_processor.go

@@ -22,7 +22,7 @@ import (
 	"github.com/uber/jaeger-lib/metrics"
 	"go.uber.org/zap"

-	"github.com/jaegertracing/jaeger/cmd/agent/app/customtransports"
+	customtransport "github.com/jaegertracing/jaeger/cmd/agent/app/customtransports"


This line is needed otherwise line 66 will not compile. I am not sure how it was compiling before. I may be missing something.

Suggestion: Rename the directory the the package is in or the package itself to match the directory name. Right now the package is named customtransport, which the directory is customertransports.

Yeah, that would be the right approach, otherwise it breaks a common naming practice with no apparent good reason.

However, I am reluctant to make this change. If any other external code (not in this repo) imports this package renaming it will break that external code. I'd rather let this repo's maintainers decide if that's what they want to do.

I am reverting this change since apparently it compiles fine the way it was, not sure why I thought it doesn't.

codecov · 2019-06-21T18:13:20Z

Codecov Report

❗ No coverage uploaded for pull request base (master@b18386f). Click here to learn what that means.
The diff coverage is 100%.

@@            Coverage Diff            @@
##             master    #1625   +/-   ##
=========================================
  Coverage          ?   98.74%           
=========================================
  Files             ?      191           
  Lines             ?     9182           
  Branches          ?        0           
=========================================
  Hits              ?     9067           
  Misses            ?       89           
  Partials          ?       26

Impacted Files	Coverage Δ
cmd/agent/app/processors/thrift_processor.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 b18386f...b1894be. Read the comment docs.

We had a data race with Agent.Stop() failing if called immediately after Agent.Run() returns. The root cause of the race was that Stop() called WaitGroup.Wait() before Run() called WaitGroup.Add() for the first time which is prohibited: https://golang.org/pkg/sync/#WaitGroup.Add This change moves WaitGroup.Add() to earlier stage which guarantees that WaitGroup.Wait() will be called after that. Github issue: #1624 Testing done: Added automated tests which was failing before the bug was fixed and does not fail any more after the fix. Also verified that `make test` passes. Signed-off-by: Tigran Najaryan <tigran@najaryan.net>

jan25 · 2019-06-21T22:03:10Z

cmd/agent/app/agent_test.go

@@ -147,6 +147,47 @@ func withRunningAgent(t *testing.T, testcase func(string, chan error)) {
 	t.Fatal("Expecting server exit log")
 }

+func TestStartStopRace(t *testing.T) {


I couldn't reproduce this on my mac open-telemetry/opentelemetry-collector#43

I think wg.Wait() doesn't block if count=0, not sure if i missed something

I couldn't reproduce this on my mac open-telemetry/opentelemetry-collector#43

Yes, unfortunately it is a non-deterministic race, no guarantee that it will be reproducible. The test may catch the problem and it does sometimes when running on my machine.

I think wg.Wait() doesn't block if count=0, not sure if i missed something

The documentation of WaitGroup.Add() says:

Note that calls with a positive delta that occur when the counter is zero must happen before a Wait.

This means it is not valid to call Wait with zero counter before Add is called. However this is precisely what happens in our code.

You are right that in production mode Wait() does not block when count=0 however it is considered a mistake and go test race detector catches this mistake, see this comment https://github.com/golang/go/blob/master/src/sync/waitgroup.go#L124-L127

jan25 · 2019-06-21T22:05:14Z

cmd/agent/app/processors/thrift_processor.go

@@ -76,12 +76,12 @@ func NewThriftProcessor(
 		numProcessors: numProcessors,
 	}
 	metrics.Init(&res.metrics, mFactory, nil)
+	res.processing.Add(res.numProcessors)


I have a hunch that deadlock might've been in func processBuffer due to not executing s.processing.Done(), maybe it should be defer s.processing.Done()?

Sorry, and thats not the case unless Serve() was called

I am not seeing a deadlock, I am observing a data race. Here is the output of go test -v -race github.com/jaegertracing/jaeger/cmd/agent/app without my fix applied (but with my new test included):

================== WARNING: DATA RACE Write at 0x00c000346118 by goroutine 19: sync.(*WaitGroup).Wait() /usr/local/go/src/internal/race/race.go:41 +0xef github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).Stop() /home/tigran/go/src/github.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:102 +0x11d Previous read at 0x00c000346118 by goroutine 18: sync.(*WaitGroup).Add() /usr/local/go/src/internal/race/race.go:37 +0x169 github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).Serve() /home/tigran/go/src/github.com/jaegertracing/jaeger/cmd/agent/app/processors/thrift_processor.go:84 +0x62 Goroutine 19 (running) created at: github.com/jaegertracing/jaeger/cmd/agent/app.(*Agent).Stop() /home/tigran/go/src/github.com/jaegertracing/jaeger/cmd/agent/app/agent.go:88 +0xa1 github.com/jaegertracing/jaeger/cmd/agent/app.TestStartStopRace() /home/tigran/go/src/github.com/jaegertracing/jaeger/cmd/agent/app/agent_test.go:180 +0x4ca testing.tRunner() /usr/local/go/src/testing/testing.go:865 +0x163 Goroutine 18 (running) created at: github.com/jaegertracing/jaeger/cmd/agent/app.(*Agent).Run() /home/tigran/go/src/github.com/jaegertracing/jaeger/cmd/agent/app/agent.go:75 +0x2bf github.com/jaegertracing/jaeger/cmd/agent/app.TestStartStopRace() /home/tigran/go/src/github.com/jaegertracing/jaeger/cmd/agent/app/agent_test.go:176 +0x442 testing.tRunner() /usr/local/go/src/testing/testing.go:865 +0x163 ================== --- FAIL: TestStartStopRace (0.01s) testing.go:809: race detected during execution of test

It shows a race between sync.(*WaitGroup).Wait() and sync.(*WaitGroup).Add() which is prohibited by WaitGroup documentation. The documentation says Add() must be called before Wait().

I have a hunch that deadlock might've been in func processBuffer due to not executing s.processing.Done(), maybe it should be defer s.processing.Done()?

I only see one exit path in processBuffer(), so s.processing.Done() is guaranteed be called when the function returns (I am ignoring the possible panic case, since that is not happening in this particular case).

I agree with you it would be more idiomatic to use defer s.processing.Done() which would make it more resilient if in the future additional exit path is added to processBuffer(), but I do not think in this particular case it cases any problems.

freeformz · 2019-06-21T23:51:35Z

cmd/agent/app/processors/thrift_processor.go

@@ -76,12 +76,12 @@ func NewThriftProcessor(
 		numProcessors: numProcessors,
 	}
 	metrics.Init(&res.metrics, mFactory, nil)
+	res.processing.Add(res.numProcessors)


suggestion....

res.processing.Add(res.numProcessors) go func() { s.processBuffer() s.processing.Done() }()

Why? It consolidates Add() and Done() close together.

the processBuffer goroutines will immediately block as there is nothing in the server's data channel.

This also nicely removes the ability to accidentally spin up multiple sets of processors for the same ThriftProcessor value that aren't tracked in the waitgroup.

I like the suggestion, it makes WaitGroup operation more visible. It needs to be slightly modified to account for numProcessors:

res.processing.Add(res.numProcessors) for i := 0; i < res.numProcessors; i++ { go func() { res.processBuffer() res.processing.Done() }() }

I'll push an update to this PR.

tigrannajaryan · 2019-06-24T22:23:05Z

Reviewers, please check again.

Signed-off-by: Tigran Najaryan <tigran@najaryan.net>

tigrannajaryan · 2019-06-26T01:20:53Z

@yurishkuro @pavolloffay can you review this, please?

pavolloffay · 2019-06-26T10:12:18Z

thanks @tigrannajaryan @freeformz !

Added a Sleep to work around a data race bug in Jaeger (jaegertracing/jaeger#1625) caused by stopping immediately after starting. Without this Sleep we were observing this bug on our side: open-telemetry#43 The Sleep ensures that Jaeger Start() is fully completed before we call Jaeger Stop(). TODO: Jaeger bug is already fixed, remove this once we update Jaeger to latest version. Testing done: make test

Added a Sleep to work around a data race bug in Jaeger (jaegertracing/jaeger#1625) caused by stopping immediately after starting. Without this Sleep we were observing this bug on our side: #43 The Sleep ensures that Jaeger Start() is fully completed before we call Jaeger Stop(). TODO: Jaeger bug is already fixed, remove this once we update Jaeger to latest version. Testing done: make test

yurishkuro

Grouping Add() and Done() closer is nice, but doesn't have a functional impact.

How does moving the go-routines from Serve() to constructor solve the data race?

tigrannajaryan · 2019-07-08T05:09:08Z

@yurishkuro the race was happening when Stop() was called immediately after Run(). It was happening because when Run() was returning there was no guarantee that res.processing.Add() would be already called. So a subsequent Stop() call would try to call s.processing.Wait() while res.processing.Add() was still in progress. This is incorrect and is not allowed by WaitGroup implementation.

This change guarantees that res.processing.Add() is finished when Run() returns. Thus when Stop() is called after Run() it is guaranteed that s.processing.Wait() will never race with res.processing.Add(). This fixes the race between Add() and Wait() of WaitGroup.

tigrannajaryan requested review from black-adder, jpkrohling, objectiser, pavolloffay, tiffon, vprithvi and yurishkuro as code owners June 21, 2019 17:59

tigrannajaryan commented Jun 21, 2019

View reviewed changes

tigrannajaryan mentioned this pull request Jun 21, 2019

BUG: Data race in TestApplication_StartUnified open-telemetry/opentelemetry-collector#43

Closed

jan25 reviewed Jun 21, 2019

View reviewed changes

freeformz reviewed Jun 21, 2019

View reviewed changes

Fix based on PR comments

b1894be

Signed-off-by: Tigran Najaryan <tigran@najaryan.net>

pavolloffay approved these changes Jun 26, 2019

View reviewed changes

pavolloffay merged commit 2adc99c into jaegertracing:master Jun 26, 2019

pavolloffay mentioned this pull request Jun 26, 2019

Data race between Agent.Run() and Agent.Stop() #1624

Closed

This was referenced Jul 3, 2019

Add workaround for data race in TestApplication_StartUnified open-telemetry/opentelemetry-collector#96

Merged

Upgrade Jaeger to latest version open-telemetry/opentelemetry-collector#97

Closed

yurishkuro reviewed Jul 6, 2019

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix data race between Agent.Run() and Agent.Stop() #1625

Fix data race between Agent.Run() and Agent.Stop() #1625

tigrannajaryan commented Jun 21, 2019

tigrannajaryan Jun 21, 2019

freeformz Jun 25, 2019

tigrannajaryan Jun 25, 2019

codecov bot commented Jun 21, 2019 •

edited

Loading

jan25 Jun 21, 2019

jan25 Jun 21, 2019

tigrannajaryan Jun 21, 2019

jan25 Jun 21, 2019

jan25 Jun 21, 2019 •

edited

Loading

tigrannajaryan Jun 21, 2019 •

edited

Loading

tigrannajaryan Jun 21, 2019

freeformz Jun 21, 2019 •

edited

Loading

tigrannajaryan Jun 24, 2019

tigrannajaryan commented Jun 24, 2019

tigrannajaryan commented Jun 26, 2019

pavolloffay commented Jun 26, 2019

yurishkuro left a comment

tigrannajaryan commented Jul 8, 2019

Fix data race between Agent.Run() and Agent.Stop() #1625

Fix data race between Agent.Run() and Agent.Stop() #1625

Conversation

tigrannajaryan commented Jun 21, 2019

Which problem is this PR solving?

Short description of the changes

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov bot commented Jun 21, 2019 • edited Loading

Codecov Report

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jan25 Jun 21, 2019 • edited Loading

Choose a reason for hiding this comment

tigrannajaryan Jun 21, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

freeformz Jun 21, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tigrannajaryan commented Jun 24, 2019

tigrannajaryan commented Jun 26, 2019

pavolloffay commented Jun 26, 2019

yurishkuro left a comment

Choose a reason for hiding this comment

tigrannajaryan commented Jul 8, 2019

codecov bot commented Jun 21, 2019 •

edited

Loading

jan25 Jun 21, 2019 •

edited

Loading

tigrannajaryan Jun 21, 2019 •

edited

Loading

freeformz Jun 21, 2019 •

edited

Loading