Data race using the default localized sampling strategy

[jonaslu]

Go xray version: v1.0.0-rc.14
Go version: go version go1.13.5 linux/amd64

Create a minimal http-server (copy paste the http-handler in the README.md)

func main() {
  http.Handle("/", xray.Handler(xray.NewFixedSegmentNamer("myApp"), http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
    w.Write([]byte("Hello!"))
  })))
  http.ListenAndServe(":8000", nil)
}

Start the server with go run -race main.go and no xray-daemon running locally (will revert to localized strategy according to the docs:
https://docs.aws.amazon.com/xray/latest/devguide/xray-sdk-go-configuration.html#xray-sdk-go-configuration-sampling)

Hit the server with some load (e g using hey):
hey -z 30s http://localhost:8000

This appears quite often in the logs:

==================
WARNING: DATA RACE
Write at 0x00c000026830 by goroutine 25:
  github.com/aws/aws-xray-sdk-go/strategy/sampling.(*Reservoir).Take()
      /home/jonasl/code/reference/aws-xray-sdk-go/strategy/sampling/reservoir.go:97 +0x261
  github.com/aws/aws-xray-sdk-go/strategy/sampling.(*Rule).Sample()
      /home/jonasl/code/reference/aws-xray-sdk-go/strategy/sampling/sampling_rule.go:207 +0x98
  github.com/aws/aws-xray-sdk-go/strategy/sampling.(*LocalizedStrategy).ShouldTrace()
      /home/jonasl/code/reference/aws-xray-sdk-go/strategy/sampling/localized.go:73 +0x5a8
  github.com/aws/aws-xray-sdk-go/strategy/sampling.(*CentralizedStrategy).ShouldTrace()
      /home/jonasl/code/reference/aws-xray-sdk-go/strategy/sampling/centralized.go:154 +0x574
  github.com/aws/aws-xray-sdk-go/xray.httpTrace()
      /home/jonasl/code/reference/aws-xray-sdk-go/xray/handler.go:148 +0x16bd
  github.com/aws/aws-xray-sdk-go/xray.Handler.func1()
      /home/jonasl/code/reference/aws-xray-sdk-go/xray/handler.go:118 +0x384
  net/http.HandlerFunc.ServeHTTP()
      /usr/lib/go/src/net/http/server.go:2007 +0x51
  net/http.(*ServeMux).ServeHTTP()
      /usr/lib/go/src/net/http/server.go:2387 +0x288
  net/http.serverHandler.ServeHTTP()
      /usr/lib/go/src/net/http/server.go:2802 +0xce
  net/http.(*conn).serve()
      /usr/lib/go/src/net/http/server.go:1890 +0x837

Previous read at 0x00c000026830 by goroutine 11:
  github.com/aws/aws-xray-sdk-go/strategy/sampling.(*Reservoir).Take()
      /home/jonasl/code/reference/aws-xray-sdk-go/strategy/sampling/reservoir.go:95 +0xde
  github.com/aws/aws-xray-sdk-go/strategy/sampling.(*Rule).Sample()
      /home/jonasl/code/reference/aws-xray-sdk-go/strategy/sampling/sampling_rule.go:207 +0x98
  github.com/aws/aws-xray-sdk-go/strategy/sampling.(*LocalizedStrategy).ShouldTrace()
      /home/jonasl/code/reference/aws-xray-sdk-go/strategy/sampling/localized.go:73 +0x5a8
  github.com/aws/aws-xray-sdk-go/strategy/sampling.(*CentralizedStrategy).ShouldTrace()
      /home/jonasl/code/reference/aws-xray-sdk-go/strategy/sampling/centralized.go:154 +0x574
  github.com/aws/aws-xray-sdk-go/xray.httpTrace()
      /home/jonasl/code/reference/aws-xray-sdk-go/xray/handler.go:148 +0x16bd
  github.com/aws/aws-xray-sdk-go/xray.Handler.func1()
      /home/jonasl/code/reference/aws-xray-sdk-go/xray/handler.go:118 +0x384
  net/http.HandlerFunc.ServeHTTP()
      /usr/lib/go/src/net/http/server.go:2007 +0x51
  net/http.(*ServeMux).ServeHTTP()
      /usr/lib/go/src/net/http/server.go:2387 +0x288
  net/http.serverHandler.ServeHTTP()
      /usr/lib/go/src/net/http/server.go:2802 +0xce
  net/http.(*conn).serve()
      /usr/lib/go/src/net/http/server.go:1890 +0x837

Goroutine 25 (running) created at:
  net/http.(*Server).Serve()
      /usr/lib/go/src/net/http/server.go:2928 +0x5b5
  net/http.(*Server).ListenAndServe()
      /usr/lib/go/src/net/http/server.go:2825 +0x102
  main.main()
      /usr/lib/go/src/net/http/server.go:3081 +0x303

Goroutine 11 (running) created at:
  net/http.(*Server).Serve()
      /usr/lib/go/src/net/http/server.go:2928 +0x5b5
  net/http.(*Server).ListenAndServe()
      /usr/lib/go/src/net/http/server.go:2825 +0x102
  main.main()
      /usr/lib/go/src/net/http/server.go:3081 +0x303
==================

[bhautikpip]

Hi @jonaslu,

Thanks for opening this issue. I tried to reproduce this but I did not see logs like this. Follow up questions from my side.

1. What do you mean by hitting the server with some load ? where are you running this command ? (hey -z 30s http://localhost:8000).

2. Why do I see multiple go routines in the logs and both running the same script server.go ?

[jonaslu]

Hi,

Hey (https://github.com/rakyll/hey) is a load-tester (you can use any load-tester - it's just to have some traffic om the server to invoke the race-condition). I'm running it in a terminal after starting the x-rayed server (go run -race main.go).

I know too little about the surroundings to fix it, but it happens here (when falling back to the localized sample strategy):
https://github.com/aws/aws-xray-sdk-go/blob/master/strategy/sampling/reservoir.go#L95

I'm guessing the access to the r *Reservoir is not synchronized so you'll have multiple go-routines reading and writing to the r.currentEpoch (or really any r. member) with sufficient requests on the server.

[bhautikpip]

Hi @jonaslu,

Thanks for pointing out this issue. I was able to reproduce those data race warnings. I will add this item in our backlog for reference and will address this issue.

[bhautikpip]

Pushed out a fix for this issue (#196)

[bhautikpip]

I am closing this issue since we have pushed out a fix for this issue in this release (https://github.com/aws/aws-xray-sdk-go/releases/tag/v1.0.0-rc.15). Feel free to open another issue.