BUG: Data race in TestApplication_StartUnified

[pjanotti]

From this Travis run: https://travis-ci.org/open-telemetry/opentelemetry-service/builds/548531356?utm_source=github_status&utm_medium=notification

{"level":"info","ts":1561097714.798292,"caller":"collector/collector.go:174","msg":"Starting...","NumCPU":2}
{"level":"info","ts":1561097714.7983959,"caller":"collector/collector.go:93","msg":"Setting up profiler..."}
{"level":"info","ts":1561097714.7984593,"caller":"collector/collector.go:101","msg":"Setting up health checks..."}
{"level":"info","ts":1561097714.798795,"caller":"healthcheck/handler.go:99","msg":"Health Check server started","http-port":43771,"status":"unavailable"}
{"level":"info","ts":1561097714.7989807,"caller":"collector/collector.go:110","msg":"Setting up zPages..."}
{"level":"info","ts":1561097714.7992342,"caller":"collector/collector.go:118","msg":"Running zPages","port":42581}
{"level":"info","ts":1561097715.8005574,"caller":"opencensus/receiver.go:51","msg":"OpenCensus receiver is running.","port":45320}
{"level":"info","ts":1561097715.8007278,"caller":"collector/collector.go:127","msg":"Setting up own telemetry..."}
{"level":"info","ts":1561097715.8020036,"caller":"collector/telemetry.go:93","msg":"Serving Prometheus metrics","port":35317}
{"level":"info","ts":1561097715.8023326,"caller":"collector/collector.go:137","msg":"Everything is ready. Begin running and processing data."}
{"level":"info","ts":1561097715.8031561,"caller":"healthcheck/handler.go:133","msg":"Health Check state change","status":"ready"}
{"level":"info","ts":1561097715.8068607,"caller":"collector/collector.go:157","msg":"Received stop test request"}
{"level":"info","ts":1561097715.8069491,"caller":"healthcheck/handler.go:133","msg":"Health Check state change","status":"unavailable"}
{"level":"info","ts":1561097715.8070078,"caller":"collector/collector.go:194","msg":"Starting shutdown..."}
{"level":"info","ts":1561097715.807472,"caller":"collector/collector.go:205","msg":"Shutdown complete."}
{"level":"info","ts":1561097715.8124511,"caller":"collector/collector.go:285","msg":"Starting...","NumCPU":2}
{"level":"info","ts":1561097715.8126116,"caller":"collector/collector.go:93","msg":"Setting up profiler..."}
{"level":"info","ts":1561097715.8127234,"caller":"collector/collector.go:101","msg":"Setting up health checks..."}
{"level":"info","ts":1561097715.8131378,"caller":"healthcheck/handler.go:99","msg":"Health Check server started","http-port":37679,"status":"unavailable"}
{"level":"info","ts":1561097715.8132315,"caller":"collector/collector.go:110","msg":"Setting up zPages..."}
{"level":"info","ts":1561097715.8135908,"caller":"collector/collector.go:118","msg":"Running zPages","port":45743}
{"level":"info","ts":1561097715.8136768,"caller":"collector/collector.go:127","msg":"Setting up own telemetry..."}
{"level":"info","ts":1561097715.8148317,"caller":"collector/telemetry.go:93","msg":"Serving Prometheus metrics","port":46092}
{"level":"info","ts":1561097715.8150716,"caller":"collector/collector.go:232","msg":"Loading configuration..."}
{"level":"info","ts":1561097715.8159492,"caller":"collector/collector.go:240","msg":"Applying configuration..."}
{"level":"info","ts":1561097715.8763263,"caller":"builder/exporters_builder.go:199","msg":"Exporter is enabled.","exporter":"opencensus"}
{"level":"info","ts":1561097715.8764515,"caller":"builder/pipelines_builder.go:118","msg":"Pipeline is enabled.","pipelines":"traces"}
{"level":"info","ts":1561097715.8765345,"caller":"builder/receivers_builder.go:210","msg":"Receiver is enabled.","receiver":"jaeger","datatype":"traces"}
{"level":"info","ts":1561097715.876596,"caller":"collector/collector.go:264","msg":"Starting receivers..."}
{"level":"info","ts":1561097715.8766484,"caller":"builder/receivers_builder.go:91","msg":"Receiver is starting...","receiver":"jaeger"}
{"level":"info","ts":1561097715.878872,"caller":"builder/receivers_builder.go:96","msg":"Receiver is started.","receiver":"jaeger"}
{"level":"info","ts":1561097715.8789592,"caller":"collector/collector.go:137","msg":"Everything is ready. Begin running and processing data."}
{"level":"info","ts":1561097715.8790317,"caller":"healthcheck/handler.go:133","msg":"Health Check state change","status":"ready"}
{"level":"info","ts":1561097715.8865044,"caller":"collector/collector.go:157","msg":"Received stop test request"}
{"level":"info","ts":1561097715.8866715,"caller":"healthcheck/handler.go:133","msg":"Health Check state change","status":"unavailable"}
{"level":"info","ts":1561097715.8867686,"caller":"collector/collector.go:304","msg":"Starting shutdown..."}
{"level":"info","ts":1561097715.886851,"caller":"collector/collector.go:276","msg":"Stopping receivers..."}
==================
WARNING: DATA RACE
Write at 0x00c000139ae8 by goroutine 54:
  sync.(*WaitGroup).Wait()
      /home/travis/.gimme/versions/go1.12.6.linux.amd64/src/internal/race/race.go:41 +0xef
  github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).Stop()
      /home/travis/gopath/pkg/mod/github.com/jaegertracing/jaeger@v1.9.0/cmd/agent/app/processors/thrift_processor.go:102 +0x11d
Previous read at 0x00c000139ae8 by goroutine 107:
  sync.(*WaitGroup).Add()
      /home/travis/.gimme/versions/go1.12.6.linux.amd64/src/internal/race/race.go:37 +0x169
  github.com/jaegertracing/jaeger/cmd/agent/app/processors.(*ThriftProcessor).Serve()
      /home/travis/gopath/pkg/mod/github.com/jaegertracing/jaeger@v1.9.0/cmd/agent/app/processors/thrift_processor.go:84 +0x62
Goroutine 54 (running) created at:
  github.com/jaegertracing/jaeger/cmd/agent/app.(*Agent).Stop()
      /home/travis/gopath/pkg/mod/github.com/jaegertracing/jaeger@v1.9.0/cmd/agent/app/agent.go:88 +0xa1
  github.com/open-telemetry/opentelemetry-service/receiver/jaegerreceiver.(*jReceiver).stopTraceReceptionLocked.func1()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/receiver/jaegerreceiver/trace_receiver.go:208 +0x5ad
  sync.(*Once).Do()
      /home/travis/.gimme/versions/go1.12.6.linux.amd64/src/sync/once.go:44 +0xde
  github.com/open-telemetry/opentelemetry-service/receiver/jaegerreceiver.(*jReceiver).stopTraceReceptionLocked()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/receiver/jaegerreceiver/trace_receiver.go:204 +0xa0
  github.com/open-telemetry/opentelemetry-service/receiver/jaegerreceiver.(*jReceiver).StopTraceReception()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/receiver/jaegerreceiver/trace_receiver.go:199 +0x8e
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/builder.(*builtReceiver).Stop()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/builder/receivers_builder.go:42 +0x2f8
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/builder.Receivers.StopAll()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/builder/receivers_builder.go:84 +0xc7
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector.(*Application).shutdownPipelines()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector/collector.go:277 +0xb6
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector.(*Application).executeUnified()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector/collector.go:306 +0x30a
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector.(*Application).StartUnified.func1()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector/collector.go:322 +0x71
  github.com/spf13/cobra.(*Command).execute()
      /home/travis/gopath/pkg/mod/github.com/spf13/cobra@v0.0.3/command.go:766 +0x8eb
  github.com/spf13/cobra.(*Command).ExecuteC()
      /home/travis/gopath/pkg/mod/github.com/spf13/cobra@v0.0.3/command.go:852 +0x418
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector.(*Application).StartUnified()
      /home/travis/gopath/pkg/mod/github.com/spf13/cobra@v0.0.3/command.go:800 +0x298
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector.TestApplication_StartUnified.func1()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector/collector_test.go:88 +0x78
Goroutine 107 (running) created at:
  github.com/jaegertracing/jaeger/cmd/agent/app.(*Agent).Run()
      /home/travis/gopath/pkg/mod/github.com/jaegertracing/jaeger@v1.9.0/cmd/agent/app/agent.go:75 +0x2bf
  github.com/open-telemetry/opentelemetry-service/receiver/jaegerreceiver.(*jReceiver).startAgent()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/receiver/jaegerreceiver/trace_receiver.go:335 +0x3cc
  github.com/open-telemetry/opentelemetry-service/receiver/jaegerreceiver.(*jReceiver).StartTraceReception.func1()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/receiver/jaegerreceiver/trace_receiver.go:180 +0x53
  sync.(*Once).Do()
      /home/travis/.gimme/versions/go1.12.6.linux.amd64/src/sync/once.go:44 +0xde
  github.com/open-telemetry/opentelemetry-service/receiver/jaegerreceiver.(*jReceiver).StartTraceReception()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/receiver/jaegerreceiver/trace_receiver.go:179 +0xe0
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/builder.(*builtReceiver).Start()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/builder/receivers_builder.go:62 +0x312
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/builder.Receivers.StartAll()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/builder/receivers_builder.go:93 +0x2c7
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector.(*Application).setupPipelines()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector/collector.go:265 +0x485
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector.(*Application).executeUnified()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector/collector.go:295 +0x26c
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector.(*Application).StartUnified.func1()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector/collector.go:322 +0x71
  github.com/spf13/cobra.(*Command).execute()
      /home/travis/gopath/pkg/mod/github.com/spf13/cobra@v0.0.3/command.go:766 +0x8eb
  github.com/spf13/cobra.(*Command).ExecuteC()
      /home/travis/gopath/pkg/mod/github.com/spf13/cobra@v0.0.3/command.go:852 +0x418
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector.(*Application).StartUnified()
      /home/travis/gopath/pkg/mod/github.com/spf13/cobra@v0.0.3/command.go:800 +0x298
  github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector.TestApplication_StartUnified.func1()
      /home/travis/gopath/src/github.com/open-telemetry/opentelemetry-service/cmd/occollector/app/collector/collector_test.go:88 +0x78
==================
{"level":"info","ts":1561097715.897572,"caller":"collector/collector.go:311","msg":"Shutdown complete."}
--- FAIL: TestApplication_StartUnified (0.10s)
    testing.go:809: race detected during execution of test
FAIL
coverage: 57.1% of statements

[tigrannajaryan]

Root cause is in Jaeger Agent implementation. I filed a bug with Jaeger: jaegertracing/jaeger#1624

I will see if there is a good workaround.

[tigrannajaryan]

I submitted a PR to fix the bug in Jaeger: jaegertracing/jaeger#1625

There is no good workaround except adding a pause in our tests. I will do it if PR does not get merged quickly.

[tigrannajaryan]

Jaeger PR is now fixed. However updating to use latest Jaeger is not straightforward. They have breaking changes.